github.com/twelsh-aw/go/src@v0.0.0-20230516233729-a56fe86a7c81/log/slog/handler.go (about)

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