src/log/slog/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(level, msg, slog.Int("a", 1), slog.Int("b", 2))
  80         //
  81         // should behave like
  82         //
  83         //     logger.LogAttrs(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 using app.
 465 // It handles replacement and checking for an empty key.
 466 // after replacement).
 467 // It reports whether something was appended.
 468 func (s *handleState) appendAttr(a Attr) bool {
 469         a.Value = a.Value.Resolve()
 470         if rep := s.h.opts.ReplaceAttr; rep != nil && a.Value.Kind() != KindGroup {
 471                 var gs []string
 472                 if s.groups != nil {
 473                         gs = *s.groups
 474                 }
 475                 // a.Value is resolved before calling ReplaceAttr, so the user doesn't have to.
 476                 a = rep(gs, a)
 477                 // The ReplaceAttr function may return an unresolved Attr.
 478                 a.Value = a.Value.Resolve()
 479         }
 480         // Elide empty Attrs.
 481         if a.isEmpty() {
 482                 return false
 483         }
 484         // Special case: Source.
 485         if v := a.Value; v.Kind() == KindAny {
 486                 if src, ok := v.Any().(*Source); ok {
 487                         if s.h.json {
 488                                 a.Value = src.group()
 489                         } else {
 490                                 a.Value = StringValue(fmt.Sprintf("%s:%d", src.File, src.Line))
 491                         }
 492                 }
 493         }
 494         if a.Value.Kind() == KindGroup {
 495                 attrs := a.Value.Group()
 496                 // Output only non-empty groups.
 497                 if len(attrs) > 0 {
 498                         // The group may turn out to be empty even though it has attrs (for
 499                         // example, ReplaceAttr may delete all the attrs).
 500                         // So remember where we are in the buffer, to restore the position
 501                         // later if necessary.
 502                         pos := s.buf.Len()
 503                         // Inline a group with an empty key.
 504                         if a.Key != "" {
 505                                 s.openGroup(a.Key)
 506                         }
 507                         if !s.appendAttrs(attrs) {
 508                                 s.buf.SetLen(pos)
 509                                 return false
 510                         }
 511                         if a.Key != "" {
 512                                 s.closeGroup(a.Key)
 513                         }
 514                 }
 515         } else {
 516                 s.appendKey(a.Key)
 517                 s.appendValue(a.Value)
 518         }
 519         return true
 520 }
 521
 522 func (s *handleState) appendError(err error) {
 523         s.appendString(fmt.Sprintf("!ERROR:%v", err))
 524 }
 525
 526 func (s *handleState) appendKey(key string) {
 527         s.buf.WriteString(s.sep)
 528         if s.prefix != nil && len(*s.prefix) > 0 {
 529                 // TODO: optimize by avoiding allocation.
 530                 s.appendString(string(*s.prefix) + key)
 531         } else {
 532                 s.appendString(key)
 533         }
 534         if s.h.json {
 535                 s.buf.WriteByte(':')
 536         } else {
 537                 s.buf.WriteByte('=')
 538         }
 539         s.sep = s.h.attrSep()
 540 }
 541
 542 func (s *handleState) appendString(str string) {
 543         if s.h.json {
 544                 s.buf.WriteByte('"')
 545                 *s.buf = appendEscapedJSONString(*s.buf, str)
 546                 s.buf.WriteByte('"')
 547         } else {
 548                 // text
 549                 if needsQuoting(str) {
 550                         *s.buf = strconv.AppendQuote(*s.buf, str)
 551                 } else {
 552                         s.buf.WriteString(str)
 553                 }
 554         }
 555 }
 556
 557 func (s *handleState) appendValue(v Value) {
 558         defer func() {
 559                 if r := recover(); r != nil {
 560                         // If it panics with a nil pointer, the most likely cases are
 561                         // an encoding.TextMarshaler or error fails to guard against nil,
 562                         // in which case "<nil>" seems to be the feasible choice.
 563                         //
 564                         // Adapted from the code in fmt/print.go.
 565                         if v := reflect.ValueOf(v.any); v.Kind() == reflect.Pointer && v.IsNil() {
 566                                 s.appendString("<nil>")
 567                                 return
 568                         }
 569
 570                         // Otherwise just print the original panic message.
 571                         s.appendString(fmt.Sprintf("!PANIC: %v", r))
 572                 }
 573         }()
 574
 575         var err error
 576         if s.h.json {
 577                 err = appendJSONValue(s, v)
 578         } else {
 579                 err = appendTextValue(s, v)
 580         }
 581         if err != nil {
 582                 s.appendError(err)
 583         }
 584 }
 585
 586 func (s *handleState) appendTime(t time.Time) {
 587         if s.h.json {
 588                 appendJSONTime(s, t)
 589         } else {
 590                 *s.buf = appendRFC3339Millis(*s.buf, t)
 591         }
 592 }
 593
 594 func appendRFC3339Millis(b []byte, t time.Time) []byte {
 595         // Format according to time.RFC3339Nano since it is highly optimized,
 596         // but truncate it to use millisecond resolution.
 597         // Unfortunately, that format trims trailing 0s, so add 1/10 millisecond
 598         // to guarantee that there are exactly 4 digits after the period.
 599         const prefixLen = len("2006-01-02T15:04:05.000")
 600         n := len(b)
 601         t = t.Truncate(time.Millisecond).Add(time.Millisecond / 10)
 602         b = t.AppendFormat(b, time.RFC3339Nano)
 603         b = append(b[:n+prefixLen], b[n+prefixLen+1:]...) // drop the 4th digit
 604         return b
 605 }