handler.go

Documentation: golang.org/x/exp/slog

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