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         "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 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         //   - If an Attr's key is the empty string and the value is not a group,
  54         //     ignore the Attr.
  55         //   - If a group's key is empty, inline the group's Attrs.
  56         //   - If a group has no Attrs (even if it has a non-empty key),
  57         //     ignore it.
  58         Handle(context.Context, Record) error
  59
  60         // WithAttrs returns a new Handler whose attributes consist of
  61         // both the receiver's attributes and the arguments.
  62         // The Handler owns the slice: it may retain, modify or discard it.
  63         // [Logger.With] will resolve the Attrs.
  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         // log.Output, except for testing
  91         output func(calldepth int, message string) error
  92 }
  93
  94 func newDefaultHandler(output func(int, string) 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, " ", nil)
 114         defer state.free()
 115         state.appendNonBuiltIns(r)
 116
 117         // skip [h.output, defaultHandler.Handle, handlerWriter.Write, log.Output]
 118         return h.output(4, buf.String())
 119 }
 120
 121 func (h *defaultHandler) WithAttrs(as []Attr) Handler {
 122         return &defaultHandler{h.ch.withAttrs(as), h.output}
 123 }
 124
 125 func (h *defaultHandler) WithGroup(name string) Handler {
 126         return &defaultHandler{h.ch.withGroup(name), h.output}
 127 }
 128
 129 // HandlerOptions are options for a TextHandler or JSONHandler.
 130 // A zero HandlerOptions consists entirely of default values.
 131 type HandlerOptions struct {
 132         // When AddSource is true, the handler adds a ("source", "file:line")
 133         // attribute to the output indicating the source code position of the log
 134         // statement. AddSource is false by default to skip the cost of computing
 135         // this information.
 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                 frame := r.frame()
 288                 if frame.File != "" {
 289                         key := SourceKey
 290                         if rep == nil {
 291                                 state.appendKey(key)
 292                                 state.appendSource(frame.File, frame.Line)
 293                         } else {
 294                                 buf := buffer.New()
 295                                 buf.WriteString(frame.File) // TODO: escape?
 296                                 buf.WriteByte(':')
 297                                 buf.WritePosInt(frame.Line)
 298                                 s := buf.String()
 299                                 buf.Free()
 300                                 state.appendAttr(String(key, s))
 301                         }
 302                 }
 303         }
 304         key = MessageKey
 305         msg := r.Message
 306         if rep == nil {
 307                 state.appendKey(key)
 308                 state.appendString(msg)
 309         } else {
 310                 state.appendAttr(String(key, msg))
 311         }
 312         state.groups = stateGroups // Restore groups passed to ReplaceAttrs.
 313         state.appendNonBuiltIns(r)
 314         state.buf.WriteByte('\n')
 315
 316         h.mu.Lock()
 317         defer h.mu.Unlock()
 318         _, err := h.w.Write(*state.buf)
 319         return err
 320 }
 321
 322 func (s *handleState) appendNonBuiltIns(r Record) {
 323         // preformatted Attrs
 324         if len(s.h.preformattedAttrs) > 0 {
 325                 s.buf.WriteString(s.sep)
 326                 s.buf.Write(s.h.preformattedAttrs)
 327                 s.sep = s.h.attrSep()
 328         }
 329         // Attrs in Record -- unlike the built-in ones, they are in groups started
 330         // from WithGroup.
 331         s.prefix = buffer.New()
 332         defer s.prefix.Free()
 333         s.prefix.WriteString(s.h.groupPrefix)
 334         s.openGroups()
 335         r.Attrs(func(a Attr) {
 336                 s.appendAttr(a)
 337         })
 338         if s.h.json {
 339                 // Close all open groups.
 340                 for range s.h.groups {
 341                         s.buf.WriteByte('}')
 342                 }
 343                 // Close the top-level object.
 344                 s.buf.WriteByte('}')
 345         }
 346 }
 347
 348 // attrSep returns the separator between attributes.
 349 func (h *commonHandler) attrSep() string {
 350         if h.json {
 351                 return ","
 352         }
 353         return " "
 354 }
 355
 356 // handleState holds state for a single call to commonHandler.handle.
 357 // The initial value of sep determines whether to emit a separator
 358 // before the next key, after which it stays true.
 359 type handleState struct {
 360         h       *commonHandler
 361         buf     *buffer.Buffer
 362         freeBuf bool           // should buf be freed?
 363         sep     string         // separator to write before next key
 364         prefix  *buffer.Buffer // for text: key prefix
 365         groups  *[]string      // pool-allocated slice of active groups, for ReplaceAttr
 366 }
 367
 368 var groupPool = sync.Pool{New: func() any {
 369         s := make([]string, 0, 10)
 370         return &s
 371 }}
 372
 373 func (h *commonHandler) newHandleState(buf *buffer.Buffer, freeBuf bool, sep string, prefix *buffer.Buffer) handleState {
 374         s := handleState{
 375                 h:       h,
 376                 buf:     buf,
 377                 freeBuf: freeBuf,
 378                 sep:     sep,
 379                 prefix:  prefix,
 380         }
 381         if h.opts.ReplaceAttr != nil {
 382                 s.groups = groupPool.Get().(*[]string)
 383                 *s.groups = append(*s.groups, h.groups[:h.nOpenGroups]...)
 384         }
 385         return s
 386 }
 387
 388 func (s *handleState) free() {
 389         if s.freeBuf {
 390                 s.buf.Free()
 391         }
 392         if gs := s.groups; gs != nil {
 393                 *gs = (*gs)[:0]
 394                 groupPool.Put(gs)
 395         }
 396 }
 397
 398 func (s *handleState) openGroups() {
 399         for _, n := range s.h.groups[s.h.nOpenGroups:] {
 400                 s.openGroup(n)
 401         }
 402 }
 403
 404 // Separator for group names and keys.
 405 const keyComponentSep = '.'
 406
 407 // openGroup starts a new group of attributes
 408 // with the given name.
 409 func (s *handleState) openGroup(name string) {
 410         if s.h.json {
 411                 s.appendKey(name)
 412                 s.buf.WriteByte('{')
 413                 s.sep = ""
 414         } else {
 415                 s.prefix.WriteString(name)
 416                 s.prefix.WriteByte(keyComponentSep)
 417         }
 418         // Collect group names for ReplaceAttr.
 419         if s.groups != nil {
 420                 *s.groups = append(*s.groups, name)
 421         }
 422
 423 }
 424
 425 // closeGroup ends the group with the given name.
 426 func (s *handleState) closeGroup(name string) {
 427         if s.h.json {
 428                 s.buf.WriteByte('}')
 429         } else {
 430                 (*s.prefix) = (*s.prefix)[:len(*s.prefix)-len(name)-1 /* for keyComponentSep */]
 431         }
 432         s.sep = s.h.attrSep()
 433         if s.groups != nil {
 434                 *s.groups = (*s.groups)[:len(*s.groups)-1]
 435         }
 436 }
 437
 438 // appendAttr appends the Attr's key and value using app.
 439 // It handles replacement and checking for an empty key.
 440 // after replacement).
 441 func (s *handleState) appendAttr(a Attr) {
 442         v := a.Value
 443         // Elide a non-group with an empty key.
 444         if a.Key == "" && v.Kind() != KindGroup {
 445                 return
 446         }
 447         if rep := s.h.opts.ReplaceAttr; rep != nil && v.Kind() != KindGroup {
 448                 var gs []string
 449                 if s.groups != nil {
 450                         gs = *s.groups
 451                 }
 452                 a = rep(gs, Attr{a.Key, v})
 453                 if a.Key == "" {
 454                         return
 455                 }
 456                 // Although all attributes in the Record are already resolved,
 457                 // This one came from the user, so it may not have been.
 458                 v = a.Value.Resolve()
 459         }
 460         if v.Kind() == KindGroup {
 461                 attrs := v.Group()
 462                 // Output only non-empty groups.
 463                 if len(attrs) > 0 {
 464                         // Inline a group with an empty key.
 465                         if a.Key != "" {
 466                                 s.openGroup(a.Key)
 467                         }
 468                         for _, aa := range attrs {
 469                                 s.appendAttr(aa)
 470                         }
 471                         if a.Key != "" {
 472                                 s.closeGroup(a.Key)
 473                         }
 474                 }
 475         } else {
 476                 s.appendKey(a.Key)
 477                 s.appendValue(v)
 478         }
 479 }
 480
 481 func (s *handleState) appendError(err error) {
 482         s.appendString(fmt.Sprintf("!ERROR:%v", err))
 483 }
 484
 485 func (s *handleState) appendKey(key string) {
 486         s.buf.WriteString(s.sep)
 487         if s.prefix != nil {
 488                 // TODO: optimize by avoiding allocation.
 489                 s.appendString(string(*s.prefix) + key)
 490         } else {
 491                 s.appendString(key)
 492         }
 493         if s.h.json {
 494                 s.buf.WriteByte(':')
 495         } else {
 496                 s.buf.WriteByte('=')
 497         }
 498         s.sep = s.h.attrSep()
 499 }
 500
 501 func (s *handleState) appendSource(file string, line int) {
 502         if s.h.json {
 503                 s.buf.WriteByte('"')
 504                 *s.buf = appendEscapedJSONString(*s.buf, file)
 505                 s.buf.WriteByte(':')
 506                 s.buf.WritePosInt(line)
 507                 s.buf.WriteByte('"')
 508         } else {
 509                 // text
 510                 if needsQuoting(file) {
 511                         s.appendString(file + ":" + strconv.Itoa(line))
 512                 } else {
 513                         // common case: no quoting needed.
 514                         s.appendString(file)
 515                         s.buf.WriteByte(':')
 516                         s.buf.WritePosInt(line)
 517                 }
 518         }
 519 }
 520
 521 func (s *handleState) appendString(str string) {
 522         if s.h.json {
 523                 s.buf.WriteByte('"')
 524                 *s.buf = appendEscapedJSONString(*s.buf, str)
 525                 s.buf.WriteByte('"')
 526         } else {
 527                 // text
 528                 if needsQuoting(str) {
 529                         *s.buf = strconv.AppendQuote(*s.buf, str)
 530                 } else {
 531                         s.buf.WriteString(str)
 532                 }
 533         }
 534 }
 535
 536 func (s *handleState) appendValue(v Value) {
 537         var err error
 538         if s.h.json {
 539                 err = appendJSONValue(s, v)
 540         } else {
 541                 err = appendTextValue(s, v)
 542         }
 543         if err != nil {
 544                 s.appendError(err)
 545         }
 546 }
 547
 548 func (s *handleState) appendTime(t time.Time) {
 549         if s.h.json {
 550                 appendJSONTime(s, t)
 551         } else {
 552                 writeTimeRFC3339Millis(s.buf, t)
 553         }
 554 }
 555
 556 // This takes half the time of Time.AppendFormat.
 557 func writeTimeRFC3339Millis(buf *buffer.Buffer, t time.Time) {
 558         year, month, day := t.Date()
 559         buf.WritePosIntWidth(year, 4)
 560         buf.WriteByte('-')
 561         buf.WritePosIntWidth(int(month), 2)
 562         buf.WriteByte('-')
 563         buf.WritePosIntWidth(day, 2)
 564         buf.WriteByte('T')
 565         hour, min, sec := t.Clock()
 566         buf.WritePosIntWidth(hour, 2)
 567         buf.WriteByte(':')
 568         buf.WritePosIntWidth(min, 2)
 569         buf.WriteByte(':')
 570         buf.WritePosIntWidth(sec, 2)
 571         ns := t.Nanosecond()
 572         buf.WriteByte('.')
 573         buf.WritePosIntWidth(ns/1e6, 3)
 574         _, offsetSeconds := t.Zone()
 575         if offsetSeconds == 0 {
 576                 buf.WriteByte('Z')
 577         } else {
 578                 offsetMinutes := offsetSeconds / 60
 579                 if offsetMinutes < 0 {
 580                         buf.WriteByte('-')
 581                         offsetMinutes = -offsetMinutes
 582                 } else {
 583                         buf.WriteByte('+')
 584                 }
 585                 buf.WritePosIntWidth(offsetMinutes/60, 2)
 586                 buf.WriteByte(':')
 587                 buf.WritePosIntWidth(offsetMinutes%60, 2)
 588         }
 589 }