handler.go

     1  // Copyright 2022 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  package slog
     6  
     7  import (
     8  	"context"
     9  	"fmt"
    10  	"io"
    11  	"log/slog/internal/buffer"
    12  	"reflect"
    13  	"slices"
    14  	"strconv"
    15  	"sync"
    16  	"time"
    17  )
    18  
    19  // A Handler handles log records produced by a Logger.
    20  //
    21  // A typical handler may print log records to standard error,
    22  // or write them to a file or database, or perhaps augment them
    23  // with additional attributes and pass them on to another handler.
    24  //
    25  // Any of the Handler's methods may be called concurrently with itself
    26  // or with other methods. It is the responsibility of the Handler to
    27  // manage this concurrency.
    28  //
    29  // Users of the slog package should not invoke Handler methods directly.
    30  // They should use the methods of [Logger] instead.
    31  type Handler interface {
    32  	// Enabled reports whether the handler handles records at the given level.
    33  	// The handler ignores records whose level is lower.
    34  	// It is called early, before any arguments are processed,
    35  	// to save effort if the log event should be discarded.
    36  	// If called from a Logger method, the first argument is the context
    37  	// passed to that method, or context.Background() if nil was passed
    38  	// or the method does not take a context.
    39  	// The context is passed so Enabled can use its values
    40  	// to make a decision.
    41  	Enabled(context.Context, Level) bool
    42  
    43  	// Handle handles the Record.
    44  	// It will only be called when Enabled returns true.
    45  	// The Context argument is as for Enabled.
    46  	// It is present solely to provide Handlers access to the context's values.
    47  	// Canceling the context should not affect record processing.
    48  	// (Among other things, log messages may be necessary to debug a
    49  	// cancellation-related problem.)
    50  	//
    51  	// Handle methods that produce output should observe the following rules:
    52  	//   - If r.Time is the zero time, ignore the time.
    53  	//   - If r.PC is zero, ignore it.
    54  	//   - Attr's values should be resolved.
    55  	//   - If an Attr's key and value are both the zero value, ignore the Attr.
    56  	//     This can be tested with attr.Equal(Attr{}).
    57  	//   - If a group's key is empty, inline the group's Attrs.
    58  	//   - If a group has no Attrs (even if it has a non-empty key),
    59  	//     ignore it.
    60  	Handle(context.Context, Record) error
    61  
    62  	// WithAttrs returns a new Handler whose attributes consist of
    63  	// both the receiver's attributes and the arguments.
    64  	// The Handler owns the slice: it may retain, modify or discard it.
    65  	WithAttrs(attrs []Attr) Handler
    66  
    67  	// WithGroup returns a new Handler with the given group appended to
    68  	// the receiver's existing groups.
    69  	// The keys of all subsequent attributes, whether added by With or in a
    70  	// Record, should be qualified by the sequence of group names.
    71  	//
    72  	// How this qualification happens is up to the Handler, so long as
    73  	// this Handler's attribute keys differ from those of another Handler
    74  	// with a different sequence of group names.
    75  	//
    76  	// A Handler should treat WithGroup as starting a Group of Attrs that ends
    77  	// at the end of the log event. That is,
    78  	//
    79  	//     logger.WithGroup("s").LogAttrs(ctx, level, msg, slog.Int("a", 1), slog.Int("b", 2))
    80  	//
    81  	// should behave like
    82  	//
    83  	//     logger.LogAttrs(ctx, level, msg, slog.Group("s", slog.Int("a", 1), slog.Int("b", 2)))
    84  	//
    85  	// If the name is empty, WithGroup returns the receiver.
    86  	WithGroup(name string) Handler
    87  }
    88  
    89  type defaultHandler struct {
    90  	ch *commonHandler
    91  	// internal.DefaultOutput, except for testing
    92  	output func(pc uintptr, data []byte) error
    93  }
    94  
    95  func newDefaultHandler(output func(uintptr, []byte) error) *defaultHandler {
    96  	return &defaultHandler{
    97  		ch:     &commonHandler{json: false},
    98  		output: output,
    99  	}
   100  }
   101  
   102  func (*defaultHandler) Enabled(_ context.Context, l Level) bool {
   103  	return l >= logLoggerLevel.Level()
   104  }
   105  
   106  // Collect the level, attributes and message in a string and
   107  // write it with the default log.Logger.
   108  // Let the log.Logger handle time and file/line.
   109  func (h *defaultHandler) Handle(ctx context.Context, r Record) error {
   110  	buf := buffer.New()
   111  	buf.WriteString(r.Level.String())
   112  	buf.WriteByte(' ')
   113  	buf.WriteString(r.Message)
   114  	state := h.ch.newHandleState(buf, true, " ")
   115  	defer state.free()
   116  	state.appendNonBuiltIns(r)
   117  	return h.output(r.PC, *buf)
   118  }
   119  
   120  func (h *defaultHandler) WithAttrs(as []Attr) Handler {
   121  	return &defaultHandler{h.ch.withAttrs(as), h.output}
   122  }
   123  
   124  func (h *defaultHandler) WithGroup(name string) Handler {
   125  	return &defaultHandler{h.ch.withGroup(name), h.output}
   126  }
   127  
   128  // HandlerOptions are options for a [TextHandler] or [JSONHandler].
   129  // A zero HandlerOptions consists entirely of default values.
   130  type HandlerOptions struct {
   131  	// AddSource causes the handler to compute the source code position
   132  	// of the log statement and add a SourceKey attribute to the output.
   133  	AddSource bool
   134  
   135  	// Level reports the minimum record level that will be logged.
   136  	// The handler discards records with lower levels.
   137  	// If Level is nil, the handler assumes LevelInfo.
   138  	// The handler calls Level.Level for each record processed;
   139  	// to adjust the minimum level dynamically, use a LevelVar.
   140  	Level Leveler
   141  
   142  	// ReplaceAttr is called to rewrite each non-group attribute before it is logged.
   143  	// The attribute's value has been resolved (see [Value.Resolve]).
   144  	// If ReplaceAttr returns a zero Attr, the attribute is discarded.
   145  	//
   146  	// The built-in attributes with keys "time", "level", "source", and "msg"
   147  	// are passed to this function, except that time is omitted
   148  	// if zero, and source is omitted if AddSource is false.
   149  	//
   150  	// The first argument is a list of currently open groups that contain the
   151  	// Attr. It must not be retained or modified. ReplaceAttr is never called
   152  	// for Group attributes, only their contents. For example, the attribute
   153  	// list
   154  	//
   155  	//     Int("a", 1), Group("g", Int("b", 2)), Int("c", 3)
   156  	//
   157  	// results in consecutive calls to ReplaceAttr with the following arguments:
   158  	//
   159  	//     nil, Int("a", 1)
   160  	//     []string{"g"}, Int("b", 2)
   161  	//     nil, Int("c", 3)
   162  	//
   163  	// ReplaceAttr can be used to change the default keys of the built-in
   164  	// attributes, convert types (for example, to replace a `time.Time` with the
   165  	// integer seconds since the Unix epoch), sanitize personal information, or
   166  	// remove attributes from the output.
   167  	ReplaceAttr func(groups []string, a Attr) Attr
   168  }
   169  
   170  // Keys for "built-in" attributes.
   171  const (
   172  	// TimeKey is the key used by the built-in handlers for the time
   173  	// when the log method is called. The associated Value is a [time.Time].
   174  	TimeKey = "time"
   175  	// LevelKey is the key used by the built-in handlers for the level
   176  	// of the log call. The associated value is a [Level].
   177  	LevelKey = "level"
   178  	// MessageKey is the key used by the built-in handlers for the
   179  	// message of the log call. The associated value is a string.
   180  	MessageKey = "msg"
   181  	// SourceKey is the key used by the built-in handlers for the source file
   182  	// and line of the log call. The associated value is a *[Source].
   183  	SourceKey = "source"
   184  )
   185  
   186  type commonHandler struct {
   187  	json              bool // true => output JSON; false => output text
   188  	opts              HandlerOptions
   189  	preformattedAttrs []byte
   190  	// groupPrefix is for the text handler only.
   191  	// It holds the prefix for groups that were already pre-formatted.
   192  	// A group will appear here when a call to WithGroup is followed by
   193  	// a call to WithAttrs.
   194  	groupPrefix string
   195  	groups      []string // all groups started from WithGroup
   196  	nOpenGroups int      // the number of groups opened in preformattedAttrs
   197  	mu          *sync.Mutex
   198  	w           io.Writer
   199  }
   200  
   201  func (h *commonHandler) clone() *commonHandler {
   202  	// We can't use assignment because we can't copy the mutex.
   203  	return &commonHandler{
   204  		json:              h.json,
   205  		opts:              h.opts,
   206  		preformattedAttrs: slices.Clip(h.preformattedAttrs),
   207  		groupPrefix:       h.groupPrefix,
   208  		groups:            slices.Clip(h.groups),
   209  		nOpenGroups:       h.nOpenGroups,
   210  		w:                 h.w,
   211  		mu:                h.mu, // mutex shared among all clones of this handler
   212  	}
   213  }
   214  
   215  // enabled reports whether l is greater than or equal to the
   216  // minimum level.
   217  func (h *commonHandler) enabled(l Level) bool {
   218  	minLevel := LevelInfo
   219  	if h.opts.Level != nil {
   220  		minLevel = h.opts.Level.Level()
   221  	}
   222  	return l >= minLevel
   223  }
   224  
   225  func (h *commonHandler) withAttrs(as []Attr) *commonHandler {
   226  	// We are going to ignore empty groups, so if the entire slice consists of
   227  	// them, there is nothing to do.
   228  	if countEmptyGroups(as) == len(as) {
   229  		return h
   230  	}
   231  	h2 := h.clone()
   232  	// Pre-format the attributes as an optimization.
   233  	state := h2.newHandleState((*buffer.Buffer)(&h2.preformattedAttrs), false, "")
   234  	defer state.free()
   235  	state.prefix.WriteString(h.groupPrefix)
   236  	if pfa := h2.preformattedAttrs; len(pfa) > 0 {
   237  		state.sep = h.attrSep()
   238  		if h2.json && pfa[len(pfa)-1] == '{' {
   239  			state.sep = ""
   240  		}
   241  	}
   242  	// Remember the position in the buffer, in case all attrs are empty.
   243  	pos := state.buf.Len()
   244  	state.openGroups()
   245  	if !state.appendAttrs(as) {
   246  		state.buf.SetLen(pos)
   247  	} else {
   248  		// Remember the new prefix for later keys.
   249  		h2.groupPrefix = state.prefix.String()
   250  		// Remember how many opened groups are in preformattedAttrs,
   251  		// so we don't open them again when we handle a Record.
   252  		h2.nOpenGroups = len(h2.groups)
   253  	}
   254  	return h2
   255  }
   256  
   257  func (h *commonHandler) withGroup(name string) *commonHandler {
   258  	h2 := h.clone()
   259  	h2.groups = append(h2.groups, name)
   260  	return h2
   261  }
   262  
   263  // handle is the internal implementation of Handler.Handle
   264  // used by TextHandler and JSONHandler.
   265  func (h *commonHandler) handle(r Record) error {
   266  	state := h.newHandleState(buffer.New(), true, "")
   267  	defer state.free()
   268  	if h.json {
   269  		state.buf.WriteByte('{')
   270  	}
   271  	// Built-in attributes. They are not in a group.
   272  	stateGroups := state.groups
   273  	state.groups = nil // So ReplaceAttrs sees no groups instead of the pre groups.
   274  	rep := h.opts.ReplaceAttr
   275  	// time
   276  	if !r.Time.IsZero() {
   277  		key := TimeKey
   278  		val := r.Time.Round(0) // strip monotonic to match Attr behavior
   279  		if rep == nil {
   280  			state.appendKey(key)
   281  			state.appendTime(val)
   282  		} else {
   283  			state.appendAttr(Time(key, val))
   284  		}
   285  	}
   286  	// level
   287  	key := LevelKey
   288  	val := r.Level
   289  	if rep == nil {
   290  		state.appendKey(key)
   291  		state.appendString(val.String())
   292  	} else {
   293  		state.appendAttr(Any(key, val))
   294  	}
   295  	// source
   296  	if h.opts.AddSource {
   297  		state.appendAttr(Any(SourceKey, r.source()))
   298  	}
   299  	key = MessageKey
   300  	msg := r.Message
   301  	if rep == nil {
   302  		state.appendKey(key)
   303  		state.appendString(msg)
   304  	} else {
   305  		state.appendAttr(String(key, msg))
   306  	}
   307  	state.groups = stateGroups // Restore groups passed to ReplaceAttrs.
   308  	state.appendNonBuiltIns(r)
   309  	state.buf.WriteByte('\n')
   310  
   311  	h.mu.Lock()
   312  	defer h.mu.Unlock()
   313  	_, err := h.w.Write(*state.buf)
   314  	return err
   315  }
   316  
   317  func (s *handleState) appendNonBuiltIns(r Record) {
   318  	// preformatted Attrs
   319  	if pfa := s.h.preformattedAttrs; len(pfa) > 0 {
   320  		s.buf.WriteString(s.sep)
   321  		s.buf.Write(pfa)
   322  		s.sep = s.h.attrSep()
   323  		if s.h.json && pfa[len(pfa)-1] == '{' {
   324  			s.sep = ""
   325  		}
   326  	}
   327  	// Attrs in Record -- unlike the built-in ones, they are in groups started
   328  	// from WithGroup.
   329  	// If the record has no Attrs, don't output any groups.
   330  	nOpenGroups := s.h.nOpenGroups
   331  	if r.NumAttrs() > 0 {
   332  		s.prefix.WriteString(s.h.groupPrefix)
   333  		// The group may turn out to be empty even though it has attrs (for
   334  		// example, ReplaceAttr may delete all the attrs).
   335  		// So remember where we are in the buffer, to restore the position
   336  		// later if necessary.
   337  		pos := s.buf.Len()
   338  		s.openGroups()
   339  		nOpenGroups = len(s.h.groups)
   340  		empty := true
   341  		r.Attrs(func(a Attr) bool {
   342  			if s.appendAttr(a) {
   343  				empty = false
   344  			}
   345  			return true
   346  		})
   347  		if empty {
   348  			s.buf.SetLen(pos)
   349  			nOpenGroups = s.h.nOpenGroups
   350  		}
   351  	}
   352  	if s.h.json {
   353  		// Close all open groups.
   354  		for range s.h.groups[:nOpenGroups] {
   355  			s.buf.WriteByte('}')
   356  		}
   357  		// Close the top-level object.
   358  		s.buf.WriteByte('}')
   359  	}
   360  }
   361  
   362  // attrSep returns the separator between attributes.
   363  func (h *commonHandler) attrSep() string {
   364  	if h.json {
   365  		return ","
   366  	}
   367  	return " "
   368  }
   369  
   370  // handleState holds state for a single call to commonHandler.handle.
   371  // The initial value of sep determines whether to emit a separator
   372  // before the next key, after which it stays true.
   373  type handleState struct {
   374  	h       *commonHandler
   375  	buf     *buffer.Buffer
   376  	freeBuf bool           // should buf be freed?
   377  	sep     string         // separator to write before next key
   378  	prefix  *buffer.Buffer // for text: key prefix
   379  	groups  *[]string      // pool-allocated slice of active groups, for ReplaceAttr
   380  }
   381  
   382  var groupPool = sync.Pool{New: func() any {
   383  	s := make([]string, 0, 10)
   384  	return &s
   385  }}
   386  
   387  func (h *commonHandler) newHandleState(buf *buffer.Buffer, freeBuf bool, sep string) handleState {
   388  	s := handleState{
   389  		h:       h,
   390  		buf:     buf,
   391  		freeBuf: freeBuf,
   392  		sep:     sep,
   393  		prefix:  buffer.New(),
   394  	}
   395  	if h.opts.ReplaceAttr != nil {
   396  		s.groups = groupPool.Get().(*[]string)
   397  		*s.groups = append(*s.groups, h.groups[:h.nOpenGroups]...)
   398  	}
   399  	return s
   400  }
   401  
   402  func (s *handleState) free() {
   403  	if s.freeBuf {
   404  		s.buf.Free()
   405  	}
   406  	if gs := s.groups; gs != nil {
   407  		*gs = (*gs)[:0]
   408  		groupPool.Put(gs)
   409  	}
   410  	s.prefix.Free()
   411  }
   412  
   413  func (s *handleState) openGroups() {
   414  	for _, n := range s.h.groups[s.h.nOpenGroups:] {
   415  		s.openGroup(n)
   416  	}
   417  }
   418  
   419  // Separator for group names and keys.
   420  const keyComponentSep = '.'
   421  
   422  // openGroup starts a new group of attributes
   423  // with the given name.
   424  func (s *handleState) openGroup(name string) {
   425  	if s.h.json {
   426  		s.appendKey(name)
   427  		s.buf.WriteByte('{')
   428  		s.sep = ""
   429  	} else {
   430  		s.prefix.WriteString(name)
   431  		s.prefix.WriteByte(keyComponentSep)
   432  	}
   433  	// Collect group names for ReplaceAttr.
   434  	if s.groups != nil {
   435  		*s.groups = append(*s.groups, name)
   436  	}
   437  }
   438  
   439  // closeGroup ends the group with the given name.
   440  func (s *handleState) closeGroup(name string) {
   441  	if s.h.json {
   442  		s.buf.WriteByte('}')
   443  	} else {
   444  		(*s.prefix) = (*s.prefix)[:len(*s.prefix)-len(name)-1 /* for keyComponentSep */]
   445  	}
   446  	s.sep = s.h.attrSep()
   447  	if s.groups != nil {
   448  		*s.groups = (*s.groups)[:len(*s.groups)-1]
   449  	}
   450  }
   451  
   452  // appendAttrs appends the slice of Attrs.
   453  // It reports whether something was appended.
   454  func (s *handleState) appendAttrs(as []Attr) bool {
   455  	nonEmpty := false
   456  	for _, a := range as {
   457  		if s.appendAttr(a) {
   458  			nonEmpty = true
   459  		}
   460  	}
   461  	return nonEmpty
   462  }
   463  
   464  // appendAttr appends the Attr's key and value.
   465  // It handles replacement and checking for an empty key.
   466  // It reports whether something was appended.
   467  func (s *handleState) appendAttr(a Attr) bool {
   468  	a.Value = a.Value.Resolve()
   469  	if rep := s.h.opts.ReplaceAttr; rep != nil && a.Value.Kind() != KindGroup {
   470  		var gs []string
   471  		if s.groups != nil {
   472  			gs = *s.groups
   473  		}
   474  		// a.Value is resolved before calling ReplaceAttr, so the user doesn't have to.
   475  		a = rep(gs, a)
   476  		// The ReplaceAttr function may return an unresolved Attr.
   477  		a.Value = a.Value.Resolve()
   478  	}
   479  	// Elide empty Attrs.
   480  	if a.isEmpty() {
   481  		return false
   482  	}
   483  	// Special case: Source.
   484  	if v := a.Value; v.Kind() == KindAny {
   485  		if src, ok := v.Any().(*Source); ok {
   486  			if s.h.json {
   487  				a.Value = src.group()
   488  			} else {
   489  				a.Value = StringValue(fmt.Sprintf("%s:%d", src.File, src.Line))
   490  			}
   491  		}
   492  	}
   493  	if a.Value.Kind() == KindGroup {
   494  		attrs := a.Value.Group()
   495  		// Output only non-empty groups.
   496  		if len(attrs) > 0 {
   497  			// The group may turn out to be empty even though it has attrs (for
   498  			// example, ReplaceAttr may delete all the attrs).
   499  			// So remember where we are in the buffer, to restore the position
   500  			// later if necessary.
   501  			pos := s.buf.Len()
   502  			// Inline a group with an empty key.
   503  			if a.Key != "" {
   504  				s.openGroup(a.Key)
   505  			}
   506  			if !s.appendAttrs(attrs) {
   507  				s.buf.SetLen(pos)
   508  				return false
   509  			}
   510  			if a.Key != "" {
   511  				s.closeGroup(a.Key)
   512  			}
   513  		}
   514  	} else {
   515  		s.appendKey(a.Key)
   516  		s.appendValue(a.Value)
   517  	}
   518  	return true
   519  }
   520  
   521  func (s *handleState) appendError(err error) {
   522  	s.appendString(fmt.Sprintf("!ERROR:%v", err))
   523  }
   524  
   525  func (s *handleState) appendKey(key string) {
   526  	s.buf.WriteString(s.sep)
   527  	if s.prefix != nil && len(*s.prefix) > 0 {
   528  		// TODO: optimize by avoiding allocation.
   529  		s.appendString(string(*s.prefix) + key)
   530  	} else {
   531  		s.appendString(key)
   532  	}
   533  	if s.h.json {
   534  		s.buf.WriteByte(':')
   535  	} else {
   536  		s.buf.WriteByte('=')
   537  	}
   538  	s.sep = s.h.attrSep()
   539  }
   540  
   541  func (s *handleState) appendString(str string) {
   542  	if s.h.json {
   543  		s.buf.WriteByte('"')
   544  		*s.buf = appendEscapedJSONString(*s.buf, str)
   545  		s.buf.WriteByte('"')
   546  	} else {
   547  		// text
   548  		if needsQuoting(str) {
   549  			*s.buf = strconv.AppendQuote(*s.buf, str)
   550  		} else {
   551  			s.buf.WriteString(str)
   552  		}
   553  	}
   554  }
   555  
   556  func (s *handleState) appendValue(v Value) {
   557  	defer func() {
   558  		if r := recover(); r != nil {
   559  			// If it panics with a nil pointer, the most likely cases are
   560  			// an encoding.TextMarshaler or error fails to guard against nil,
   561  			// in which case "<nil>" seems to be the feasible choice.
   562  			//
   563  			// Adapted from the code in fmt/print.go.
   564  			if v := reflect.ValueOf(v.any); v.Kind() == reflect.Pointer && v.IsNil() {
   565  				s.appendString("<nil>")
   566  				return
   567  			}
   568  
   569  			// Otherwise just print the original panic message.
   570  			s.appendString(fmt.Sprintf("!PANIC: %v", r))
   571  		}
   572  	}()
   573  
   574  	var err error
   575  	if s.h.json {
   576  		err = appendJSONValue(s, v)
   577  	} else {
   578  		err = appendTextValue(s, v)
   579  	}
   580  	if err != nil {
   581  		s.appendError(err)
   582  	}
   583  }
   584  
   585  func (s *handleState) appendTime(t time.Time) {
   586  	if s.h.json {
   587  		appendJSONTime(s, t)
   588  	} else {
   589  		*s.buf = appendRFC3339Millis(*s.buf, t)
   590  	}
   591  }
   592  
   593  func appendRFC3339Millis(b []byte, t time.Time) []byte {
   594  	// Format according to time.RFC3339Nano since it is highly optimized,
   595  	// but truncate it to use millisecond resolution.
   596  	// Unfortunately, that format trims trailing 0s, so add 1/10 millisecond
   597  	// to guarantee that there are exactly 4 digits after the period.
   598  	const prefixLen = len("2006-01-02T15:04:05.000")
   599  	n := len(b)
   600  	t = t.Truncate(time.Millisecond).Add(time.Millisecond / 10)
   601  	b = t.AppendFormat(b, time.RFC3339Nano)
   602  	b = append(b[:n+prefixLen], b[n+prefixLen+1:]...) // drop the 4th digit
   603  	return b
   604  }
   605
View as plain text