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