diff options
Diffstat (limited to 'src/log')
42 files changed, 7829 insertions, 0 deletions
diff --git a/src/log/example_test.go b/src/log/example_test.go new file mode 100644 index 0000000..769d076 --- /dev/null +++ b/src/log/example_test.go @@ -0,0 +1,41 @@ +// Copyright 2013 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package log_test + +import ( + "bytes" + "fmt" + "log" +) + +func ExampleLogger() { + var ( + buf bytes.Buffer + logger = log.New(&buf, "logger: ", log.Lshortfile) + ) + + logger.Print("Hello, log file!") + + fmt.Print(&buf) + // Output: + // logger: example_test.go:19: Hello, log file! +} + +func ExampleLogger_Output() { + var ( + buf bytes.Buffer + logger = log.New(&buf, "INFO: ", log.Lshortfile) + + infof = func(info string) { + logger.Output(2, info) + } + ) + + infof("Hello world") + + fmt.Print(&buf) + // Output: + // INFO: example_test.go:36: Hello world +} diff --git a/src/log/internal/internal.go b/src/log/internal/internal.go new file mode 100644 index 0000000..d5af2c5 --- /dev/null +++ b/src/log/internal/internal.go @@ -0,0 +1,12 @@ +// Copyright 2023 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package internal contains definitions used by both log and log/slog. +package internal + +// DefaultOutput holds a function which calls the default log.Logger's +// output function. +// It allows slog.defaultHandler to call into an unexported function of +// the log package. +var DefaultOutput func(pc uintptr, data []byte) error diff --git a/src/log/log.go b/src/log/log.go new file mode 100644 index 0000000..9d5440e --- /dev/null +++ b/src/log/log.go @@ -0,0 +1,458 @@ +// Copyright 2009 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package log implements a simple logging package. It defines a type, Logger, +// with methods for formatting output. It also has a predefined 'standard' +// Logger accessible through helper functions Print[f|ln], Fatal[f|ln], and +// Panic[f|ln], which are easier to use than creating a Logger manually. +// That logger writes to standard error and prints the date and time +// of each logged message. +// Every log message is output on a separate line: if the message being +// printed does not end in a newline, the logger will add one. +// The Fatal functions call os.Exit(1) after writing the log message. +// The Panic functions call panic after writing the log message. +package log + +import ( + "fmt" + "io" + "log/internal" + "os" + "runtime" + "sync" + "sync/atomic" + "time" +) + +// These flags define which text to prefix to each log entry generated by the Logger. +// Bits are or'ed together to control what's printed. +// With the exception of the Lmsgprefix flag, there is no +// control over the order they appear (the order listed here) +// or the format they present (as described in the comments). +// The prefix is followed by a colon only when Llongfile or Lshortfile +// is specified. +// For example, flags Ldate | Ltime (or LstdFlags) produce, +// +// 2009/01/23 01:23:23 message +// +// while flags Ldate | Ltime | Lmicroseconds | Llongfile produce, +// +// 2009/01/23 01:23:23.123123 /a/b/c/d.go:23: message +const ( + Ldate = 1 << iota // the date in the local time zone: 2009/01/23 + Ltime // the time in the local time zone: 01:23:23 + Lmicroseconds // microsecond resolution: 01:23:23.123123. assumes Ltime. + Llongfile // full file name and line number: /a/b/c/d.go:23 + Lshortfile // final file name element and line number: d.go:23. overrides Llongfile + LUTC // if Ldate or Ltime is set, use UTC rather than the local time zone + Lmsgprefix // move the "prefix" from the beginning of the line to before the message + LstdFlags = Ldate | Ltime // initial values for the standard logger +) + +// A Logger represents an active logging object that generates lines of +// output to an io.Writer. Each logging operation makes a single call to +// the Writer's Write method. A Logger can be used simultaneously from +// multiple goroutines; it guarantees to serialize access to the Writer. +type Logger struct { + outMu sync.Mutex + out io.Writer // destination for output + + prefix atomic.Pointer[string] // prefix on each line to identify the logger (but see Lmsgprefix) + flag atomic.Int32 // properties + isDiscard atomic.Bool +} + +// New creates a new Logger. The out variable sets the +// destination to which log data will be written. +// The prefix appears at the beginning of each generated log line, or +// after the log header if the Lmsgprefix flag is provided. +// The flag argument defines the logging properties. +func New(out io.Writer, prefix string, flag int) *Logger { + l := new(Logger) + l.SetOutput(out) + l.SetPrefix(prefix) + l.SetFlags(flag) + return l +} + +// SetOutput sets the output destination for the logger. +func (l *Logger) SetOutput(w io.Writer) { + l.outMu.Lock() + defer l.outMu.Unlock() + l.out = w + l.isDiscard.Store(w == io.Discard) +} + +var std = New(os.Stderr, "", LstdFlags) + +// Default returns the standard logger used by the package-level output functions. +func Default() *Logger { return std } + +// Cheap integer to fixed-width decimal ASCII. Give a negative width to avoid zero-padding. +func itoa(buf *[]byte, i int, wid int) { + // Assemble decimal in reverse order. + var b [20]byte + bp := len(b) - 1 + for i >= 10 || wid > 1 { + wid-- + q := i / 10 + b[bp] = byte('0' + i - q*10) + bp-- + i = q + } + // i < 10 + b[bp] = byte('0' + i) + *buf = append(*buf, b[bp:]...) +} + +// formatHeader writes log header to buf in following order: +// - l.prefix (if it's not blank and Lmsgprefix is unset), +// - date and/or time (if corresponding flags are provided), +// - file and line number (if corresponding flags are provided), +// - l.prefix (if it's not blank and Lmsgprefix is set). +func formatHeader(buf *[]byte, t time.Time, prefix string, flag int, file string, line int) { + if flag&Lmsgprefix == 0 { + *buf = append(*buf, prefix...) + } + if flag&(Ldate|Ltime|Lmicroseconds) != 0 { + if flag&LUTC != 0 { + t = t.UTC() + } + if flag&Ldate != 0 { + year, month, day := t.Date() + itoa(buf, year, 4) + *buf = append(*buf, '/') + itoa(buf, int(month), 2) + *buf = append(*buf, '/') + itoa(buf, day, 2) + *buf = append(*buf, ' ') + } + if flag&(Ltime|Lmicroseconds) != 0 { + hour, min, sec := t.Clock() + itoa(buf, hour, 2) + *buf = append(*buf, ':') + itoa(buf, min, 2) + *buf = append(*buf, ':') + itoa(buf, sec, 2) + if flag&Lmicroseconds != 0 { + *buf = append(*buf, '.') + itoa(buf, t.Nanosecond()/1e3, 6) + } + *buf = append(*buf, ' ') + } + } + if flag&(Lshortfile|Llongfile) != 0 { + if flag&Lshortfile != 0 { + short := file + for i := len(file) - 1; i > 0; i-- { + if file[i] == '/' { + short = file[i+1:] + break + } + } + file = short + } + *buf = append(*buf, file...) + *buf = append(*buf, ':') + itoa(buf, line, -1) + *buf = append(*buf, ": "...) + } + if flag&Lmsgprefix != 0 { + *buf = append(*buf, prefix...) + } +} + +var bufferPool = sync.Pool{New: func() any { return new([]byte) }} + +func getBuffer() *[]byte { + p := bufferPool.Get().(*[]byte) + *p = (*p)[:0] + return p +} + +func putBuffer(p *[]byte) { + // Proper usage of a sync.Pool requires each entry to have approximately + // the same memory cost. To obtain this property when the stored type + // contains a variably-sized buffer, we add a hard limit on the maximum buffer + // to place back in the pool. + // + // See https://go.dev/issue/23199 + if cap(*p) > 64<<10 { + *p = nil + } + bufferPool.Put(p) +} + +// Output writes the output for a logging event. The string s contains +// the text to print after the prefix specified by the flags of the +// Logger. A newline is appended if the last character of s is not +// already a newline. Calldepth is used to recover the PC and is +// provided for generality, although at the moment on all pre-defined +// paths it will be 2. +func (l *Logger) Output(calldepth int, s string) error { + calldepth++ // +1 for this frame. + return l.output(0, calldepth, func(b []byte) []byte { + return append(b, s...) + }) +} + +// output can take either a calldepth or a pc to get source line information. +// It uses the pc if it is non-zero. +func (l *Logger) output(pc uintptr, calldepth int, appendOutput func([]byte) []byte) error { + if l.isDiscard.Load() { + return nil + } + + now := time.Now() // get this early. + + // Load prefix and flag once so that their value is consistent within + // this call regardless of any concurrent changes to their value. + prefix := l.Prefix() + flag := l.Flags() + + var file string + var line int + if flag&(Lshortfile|Llongfile) != 0 { + if pc == 0 { + var ok bool + _, file, line, ok = runtime.Caller(calldepth) + if !ok { + file = "???" + line = 0 + } + } else { + fs := runtime.CallersFrames([]uintptr{pc}) + f, _ := fs.Next() + file = f.File + if file == "" { + file = "???" + } + line = f.Line + } + } + + buf := getBuffer() + defer putBuffer(buf) + formatHeader(buf, now, prefix, flag, file, line) + *buf = appendOutput(*buf) + if len(*buf) == 0 || (*buf)[len(*buf)-1] != '\n' { + *buf = append(*buf, '\n') + } + + l.outMu.Lock() + defer l.outMu.Unlock() + _, err := l.out.Write(*buf) + return err +} + +func init() { + internal.DefaultOutput = func(pc uintptr, data []byte) error { + return std.output(pc, 0, func(buf []byte) []byte { + return append(buf, data...) + }) + } +} + +// Print calls l.Output to print to the logger. +// Arguments are handled in the manner of fmt.Print. +func (l *Logger) Print(v ...any) { + l.output(0, 2, func(b []byte) []byte { + return fmt.Append(b, v...) + }) +} + +// Printf calls l.Output to print to the logger. +// Arguments are handled in the manner of fmt.Printf. +func (l *Logger) Printf(format string, v ...any) { + l.output(0, 2, func(b []byte) []byte { + return fmt.Appendf(b, format, v...) + }) +} + +// Println calls l.Output to print to the logger. +// Arguments are handled in the manner of fmt.Println. +func (l *Logger) Println(v ...any) { + l.output(0, 2, func(b []byte) []byte { + return fmt.Appendln(b, v...) + }) +} + +// Fatal is equivalent to l.Print() followed by a call to os.Exit(1). +func (l *Logger) Fatal(v ...any) { + l.Output(2, fmt.Sprint(v...)) + os.Exit(1) +} + +// Fatalf is equivalent to l.Printf() followed by a call to os.Exit(1). +func (l *Logger) Fatalf(format string, v ...any) { + l.Output(2, fmt.Sprintf(format, v...)) + os.Exit(1) +} + +// Fatalln is equivalent to l.Println() followed by a call to os.Exit(1). +func (l *Logger) Fatalln(v ...any) { + l.Output(2, fmt.Sprintln(v...)) + os.Exit(1) +} + +// Panic is equivalent to l.Print() followed by a call to panic(). +func (l *Logger) Panic(v ...any) { + s := fmt.Sprint(v...) + l.Output(2, s) + panic(s) +} + +// Panicf is equivalent to l.Printf() followed by a call to panic(). +func (l *Logger) Panicf(format string, v ...any) { + s := fmt.Sprintf(format, v...) + l.Output(2, s) + panic(s) +} + +// Panicln is equivalent to l.Println() followed by a call to panic(). +func (l *Logger) Panicln(v ...any) { + s := fmt.Sprintln(v...) + l.Output(2, s) + panic(s) +} + +// Flags returns the output flags for the logger. +// The flag bits are Ldate, Ltime, and so on. +func (l *Logger) Flags() int { + return int(l.flag.Load()) +} + +// SetFlags sets the output flags for the logger. +// The flag bits are Ldate, Ltime, and so on. +func (l *Logger) SetFlags(flag int) { + l.flag.Store(int32(flag)) +} + +// Prefix returns the output prefix for the logger. +func (l *Logger) Prefix() string { + if p := l.prefix.Load(); p != nil { + return *p + } + return "" +} + +// SetPrefix sets the output prefix for the logger. +func (l *Logger) SetPrefix(prefix string) { + l.prefix.Store(&prefix) +} + +// Writer returns the output destination for the logger. +func (l *Logger) Writer() io.Writer { + l.outMu.Lock() + defer l.outMu.Unlock() + return l.out +} + +// SetOutput sets the output destination for the standard logger. +func SetOutput(w io.Writer) { + std.SetOutput(w) +} + +// Flags returns the output flags for the standard logger. +// The flag bits are Ldate, Ltime, and so on. +func Flags() int { + return std.Flags() +} + +// SetFlags sets the output flags for the standard logger. +// The flag bits are Ldate, Ltime, and so on. +func SetFlags(flag int) { + std.SetFlags(flag) +} + +// Prefix returns the output prefix for the standard logger. +func Prefix() string { + return std.Prefix() +} + +// SetPrefix sets the output prefix for the standard logger. +func SetPrefix(prefix string) { + std.SetPrefix(prefix) +} + +// Writer returns the output destination for the standard logger. +func Writer() io.Writer { + return std.Writer() +} + +// These functions write to the standard logger. + +// Print calls Output to print to the standard logger. +// Arguments are handled in the manner of fmt.Print. +func Print(v ...any) { + std.output(0, 2, func(b []byte) []byte { + return fmt.Append(b, v...) + }) +} + +// Printf calls Output to print to the standard logger. +// Arguments are handled in the manner of fmt.Printf. +func Printf(format string, v ...any) { + std.output(0, 2, func(b []byte) []byte { + return fmt.Appendf(b, format, v...) + }) +} + +// Println calls Output to print to the standard logger. +// Arguments are handled in the manner of fmt.Println. +func Println(v ...any) { + std.output(0, 2, func(b []byte) []byte { + return fmt.Appendln(b, v...) + }) +} + +// Fatal is equivalent to Print() followed by a call to os.Exit(1). +func Fatal(v ...any) { + std.Output(2, fmt.Sprint(v...)) + os.Exit(1) +} + +// Fatalf is equivalent to Printf() followed by a call to os.Exit(1). +func Fatalf(format string, v ...any) { + std.Output(2, fmt.Sprintf(format, v...)) + os.Exit(1) +} + +// Fatalln is equivalent to Println() followed by a call to os.Exit(1). +func Fatalln(v ...any) { + std.Output(2, fmt.Sprintln(v...)) + os.Exit(1) +} + +// Panic is equivalent to Print() followed by a call to panic(). +func Panic(v ...any) { + s := fmt.Sprint(v...) + std.Output(2, s) + panic(s) +} + +// Panicf is equivalent to Printf() followed by a call to panic(). +func Panicf(format string, v ...any) { + s := fmt.Sprintf(format, v...) + std.Output(2, s) + panic(s) +} + +// Panicln is equivalent to Println() followed by a call to panic(). +func Panicln(v ...any) { + s := fmt.Sprintln(v...) + std.Output(2, s) + panic(s) +} + +// Output writes the output for a logging event. The string s contains +// the text to print after the prefix specified by the flags of the +// Logger. A newline is appended if the last character of s is not +// already a newline. Calldepth is the count of the number of +// frames to skip when computing the file name and line number +// if Llongfile or Lshortfile is set; a value of 1 will print the details +// for the caller of Output. +func Output(calldepth int, s string) error { + return std.Output(calldepth+1, s) // +1 for this frame. +} diff --git a/src/log/log_test.go b/src/log/log_test.go new file mode 100644 index 0000000..c7fa78f --- /dev/null +++ b/src/log/log_test.go @@ -0,0 +1,280 @@ +// Copyright 2009 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package log + +// These tests are too simple. + +import ( + "bytes" + "fmt" + "io" + "os" + "regexp" + "runtime" + "strings" + "sync" + "testing" + "time" +) + +const ( + Rdate = `[0-9][0-9][0-9][0-9]/[0-9][0-9]/[0-9][0-9]` + Rtime = `[0-9][0-9]:[0-9][0-9]:[0-9][0-9]` + Rmicroseconds = `\.[0-9][0-9][0-9][0-9][0-9][0-9]` + Rline = `(63|65):` // must update if the calls to l.Printf / l.Print below move + Rlongfile = `.*/[A-Za-z0-9_\-]+\.go:` + Rline + Rshortfile = `[A-Za-z0-9_\-]+\.go:` + Rline +) + +type tester struct { + flag int + prefix string + pattern string // regexp that log output must match; we add ^ and expected_text$ always +} + +var tests = []tester{ + // individual pieces: + {0, "", ""}, + {0, "XXX", "XXX"}, + {Ldate, "", Rdate + " "}, + {Ltime, "", Rtime + " "}, + {Ltime | Lmsgprefix, "XXX", Rtime + " XXX"}, + {Ltime | Lmicroseconds, "", Rtime + Rmicroseconds + " "}, + {Lmicroseconds, "", Rtime + Rmicroseconds + " "}, // microsec implies time + {Llongfile, "", Rlongfile + " "}, + {Lshortfile, "", Rshortfile + " "}, + {Llongfile | Lshortfile, "", Rshortfile + " "}, // shortfile overrides longfile + // everything at once: + {Ldate | Ltime | Lmicroseconds | Llongfile, "XXX", "XXX" + Rdate + " " + Rtime + Rmicroseconds + " " + Rlongfile + " "}, + {Ldate | Ltime | Lmicroseconds | Lshortfile, "XXX", "XXX" + Rdate + " " + Rtime + Rmicroseconds + " " + Rshortfile + " "}, + {Ldate | Ltime | Lmicroseconds | Llongfile | Lmsgprefix, "XXX", Rdate + " " + Rtime + Rmicroseconds + " " + Rlongfile + " XXX"}, + {Ldate | Ltime | Lmicroseconds | Lshortfile | Lmsgprefix, "XXX", Rdate + " " + Rtime + Rmicroseconds + " " + Rshortfile + " XXX"}, +} + +// Test using Println("hello", 23, "world") or using Printf("hello %d world", 23) +func testPrint(t *testing.T, flag int, prefix string, pattern string, useFormat bool) { + buf := new(strings.Builder) + SetOutput(buf) + SetFlags(flag) + SetPrefix(prefix) + if useFormat { + Printf("hello %d world", 23) + } else { + Println("hello", 23, "world") + } + line := buf.String() + line = line[0 : len(line)-1] + pattern = "^" + pattern + "hello 23 world$" + matched, err := regexp.MatchString(pattern, line) + if err != nil { + t.Fatal("pattern did not compile:", err) + } + if !matched { + t.Errorf("log output should match %q is %q", pattern, line) + } + SetOutput(os.Stderr) +} + +func TestDefault(t *testing.T) { + if got := Default(); got != std { + t.Errorf("Default [%p] should be std [%p]", got, std) + } +} + +func TestAll(t *testing.T) { + for _, testcase := range tests { + testPrint(t, testcase.flag, testcase.prefix, testcase.pattern, false) + testPrint(t, testcase.flag, testcase.prefix, testcase.pattern, true) + } +} + +func TestOutput(t *testing.T) { + const testString = "test" + var b strings.Builder + l := New(&b, "", 0) + l.Println(testString) + if expect := testString + "\n"; b.String() != expect { + t.Errorf("log output should match %q is %q", expect, b.String()) + } +} + +func TestNonNewLogger(t *testing.T) { + var l Logger + l.SetOutput(new(bytes.Buffer)) // minimal work to initialize a Logger + l.Print("hello") +} + +func TestOutputRace(t *testing.T) { + var b bytes.Buffer + l := New(&b, "", 0) + var wg sync.WaitGroup + wg.Add(100) + for i := 0; i < 100; i++ { + go func() { + defer wg.Done() + l.SetFlags(0) + l.Output(0, "") + }() + } + wg.Wait() +} + +func TestFlagAndPrefixSetting(t *testing.T) { + var b bytes.Buffer + l := New(&b, "Test:", LstdFlags) + f := l.Flags() + if f != LstdFlags { + t.Errorf("Flags 1: expected %x got %x", LstdFlags, f) + } + l.SetFlags(f | Lmicroseconds) + f = l.Flags() + if f != LstdFlags|Lmicroseconds { + t.Errorf("Flags 2: expected %x got %x", LstdFlags|Lmicroseconds, f) + } + p := l.Prefix() + if p != "Test:" { + t.Errorf(`Prefix: expected "Test:" got %q`, p) + } + l.SetPrefix("Reality:") + p = l.Prefix() + if p != "Reality:" { + t.Errorf(`Prefix: expected "Reality:" got %q`, p) + } + // Verify a log message looks right, with our prefix and microseconds present. + l.Print("hello") + pattern := "^Reality:" + Rdate + " " + Rtime + Rmicroseconds + " hello\n" + matched, err := regexp.Match(pattern, b.Bytes()) + if err != nil { + t.Fatalf("pattern %q did not compile: %s", pattern, err) + } + if !matched { + t.Error("message did not match pattern") + } + + // Ensure that a newline is added only if the buffer lacks a newline suffix. + b.Reset() + l.SetFlags(0) + l.SetPrefix("\n") + l.Output(0, "") + if got := b.String(); got != "\n" { + t.Errorf("message mismatch:\ngot %q\nwant %q", got, "\n") + } +} + +func TestUTCFlag(t *testing.T) { + var b strings.Builder + l := New(&b, "Test:", LstdFlags) + l.SetFlags(Ldate | Ltime | LUTC) + // Verify a log message looks right in the right time zone. Quantize to the second only. + now := time.Now().UTC() + l.Print("hello") + want := fmt.Sprintf("Test:%d/%.2d/%.2d %.2d:%.2d:%.2d hello\n", + now.Year(), now.Month(), now.Day(), now.Hour(), now.Minute(), now.Second()) + got := b.String() + if got == want { + return + } + // It's possible we crossed a second boundary between getting now and logging, + // so add a second and try again. This should very nearly always work. + now = now.Add(time.Second) + want = fmt.Sprintf("Test:%d/%.2d/%.2d %.2d:%.2d:%.2d hello\n", + now.Year(), now.Month(), now.Day(), now.Hour(), now.Minute(), now.Second()) + if got == want { + return + } + t.Errorf("got %q; want %q", got, want) +} + +func TestEmptyPrintCreatesLine(t *testing.T) { + var b strings.Builder + l := New(&b, "Header:", LstdFlags) + l.Print() + l.Println("non-empty") + output := b.String() + if n := strings.Count(output, "Header"); n != 2 { + t.Errorf("expected 2 headers, got %d", n) + } + if n := strings.Count(output, "\n"); n != 2 { + t.Errorf("expected 2 lines, got %d", n) + } +} + +func TestDiscard(t *testing.T) { + l := New(io.Discard, "", 0) + s := strings.Repeat("a", 102400) + c := testing.AllocsPerRun(100, func() { l.Printf("%s", s) }) + // One allocation for slice passed to Printf, + // but none for formatting of long string. + if c > 1 { + t.Errorf("got %v allocs, want at most 1", c) + } +} + +func BenchmarkItoa(b *testing.B) { + dst := make([]byte, 0, 64) + for i := 0; i < b.N; i++ { + dst = dst[0:0] + itoa(&dst, 2015, 4) // year + itoa(&dst, 1, 2) // month + itoa(&dst, 30, 2) // day + itoa(&dst, 12, 2) // hour + itoa(&dst, 56, 2) // minute + itoa(&dst, 0, 2) // second + itoa(&dst, 987654, 6) // microsecond + } +} + +func BenchmarkPrintln(b *testing.B) { + const testString = "test" + var buf bytes.Buffer + l := New(&buf, "", LstdFlags) + b.ReportAllocs() + for i := 0; i < b.N; i++ { + buf.Reset() + l.Println(testString) + } +} + +func BenchmarkPrintlnNoFlags(b *testing.B) { + const testString = "test" + var buf bytes.Buffer + l := New(&buf, "", 0) + b.ReportAllocs() + for i := 0; i < b.N; i++ { + buf.Reset() + l.Println(testString) + } +} + +// discard is identical to io.Discard, +// but copied here to avoid the io.Discard optimization in Logger. +type discard struct{} + +func (discard) Write(p []byte) (int, error) { + return len(p), nil +} + +func BenchmarkConcurrent(b *testing.B) { + l := New(discard{}, "prefix: ", Ldate|Ltime|Lmicroseconds|Llongfile|Lmsgprefix) + var group sync.WaitGroup + for i := runtime.NumCPU(); i > 0; i-- { + group.Add(1) + go func() { + for i := 0; i < b.N; i++ { + l.Output(0, "hello, world!") + } + defer group.Done() + }() + } + group.Wait() +} + +func BenchmarkDiscard(b *testing.B) { + l := New(io.Discard, "", LstdFlags|Lshortfile) + b.ReportAllocs() + for i := 0; i < b.N; i++ { + l.Printf("processing %d objects from bucket %q", 1234, "fizzbuzz") + } +} diff --git a/src/log/slog/attr.go b/src/log/slog/attr.go new file mode 100644 index 0000000..90e343b --- /dev/null +++ b/src/log/slog/attr.go @@ -0,0 +1,102 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "fmt" + "time" +) + +// An Attr is a key-value pair. +type Attr struct { + Key string + Value Value +} + +// String returns an Attr for a string value. +func String(key, value string) Attr { + return Attr{key, StringValue(value)} +} + +// Int64 returns an Attr for an int64. +func Int64(key string, value int64) Attr { + return Attr{key, Int64Value(value)} +} + +// Int converts an int to an int64 and returns +// an Attr with that value. +func Int(key string, value int) Attr { + return Int64(key, int64(value)) +} + +// Uint64 returns an Attr for a uint64. +func Uint64(key string, v uint64) Attr { + return Attr{key, Uint64Value(v)} +} + +// Float64 returns an Attr for a floating-point number. +func Float64(key string, v float64) Attr { + return Attr{key, Float64Value(v)} +} + +// Bool returns an Attr for a bool. +func Bool(key string, v bool) Attr { + return Attr{key, BoolValue(v)} +} + +// Time returns an Attr for a time.Time. +// It discards the monotonic portion. +func Time(key string, v time.Time) Attr { + return Attr{key, TimeValue(v)} +} + +// Duration returns an Attr for a time.Duration. +func Duration(key string, v time.Duration) Attr { + return Attr{key, DurationValue(v)} +} + +// Group returns an Attr for a Group Value. +// The first argument is the key; the remaining arguments +// are converted to Attrs as in [Logger.Log]. +// +// Use Group to collect several key-value pairs under a single +// key on a log line, or as the result of LogValue +// in order to log a single value as multiple Attrs. +func Group(key string, args ...any) Attr { + return Attr{key, GroupValue(argsToAttrSlice(args)...)} +} + +func argsToAttrSlice(args []any) []Attr { + var ( + attr Attr + attrs []Attr + ) + for len(args) > 0 { + attr, args = argsToAttr(args) + attrs = append(attrs, attr) + } + return attrs +} + +// Any returns an Attr for the supplied value. +// See [AnyValue] for how values are treated. +func Any(key string, value any) Attr { + return Attr{key, AnyValue(value)} +} + +// Equal reports whether a and b have equal keys and values. +func (a Attr) Equal(b Attr) bool { + return a.Key == b.Key && a.Value.Equal(b.Value) +} + +func (a Attr) String() string { + return fmt.Sprintf("%s=%s", a.Key, a.Value) +} + +// isEmpty reports whether a has an empty key and a nil value. +// That can be written as Attr{} or Any("", nil). +func (a Attr) isEmpty() bool { + return a.Key == "" && a.Value.num == 0 && a.Value.any == nil +} diff --git a/src/log/slog/attr_test.go b/src/log/slog/attr_test.go new file mode 100644 index 0000000..1187a85 --- /dev/null +++ b/src/log/slog/attr_test.go @@ -0,0 +1,43 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "internal/testenv" + "testing" + "time" +) + +func TestAttrNoAlloc(t *testing.T) { + testenv.SkipIfOptimizationOff(t) + // Assign values just to make sure the compiler doesn't optimize away the statements. + var ( + i int64 + u uint64 + f float64 + b bool + s string + x any + p = &i + d time.Duration + ) + a := int(testing.AllocsPerRun(5, func() { + i = Int64("key", 1).Value.Int64() + u = Uint64("key", 1).Value.Uint64() + f = Float64("key", 1).Value.Float64() + b = Bool("key", true).Value.Bool() + s = String("key", "foo").Value.String() + d = Duration("key", d).Value.Duration() + x = Any("key", p).Value.Any() + })) + if a != 0 { + t.Errorf("got %d allocs, want zero", a) + } + _ = u + _ = f + _ = b + _ = s + _ = x +} diff --git a/src/log/slog/doc.go b/src/log/slog/doc.go new file mode 100644 index 0000000..088df61 --- /dev/null +++ b/src/log/slog/doc.go @@ -0,0 +1,320 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +/* +Package slog provides structured logging, +in which log records include a message, +a severity level, and various other attributes +expressed as key-value pairs. + +It defines a type, [Logger], +which provides several methods (such as [Logger.Info] and [Logger.Error]) +for reporting events of interest. + +Each Logger is associated with a [Handler]. +A Logger output method creates a [Record] from the method arguments +and passes it to the Handler, which decides how to handle it. +There is a default Logger accessible through top-level functions +(such as [Info] and [Error]) that call the corresponding Logger methods. + +A log record consists of a time, a level, a message, and a set of key-value +pairs, where the keys are strings and the values may be of any type. +As an example, + + slog.Info("hello", "count", 3) + +creates a record containing the time of the call, +a level of Info, the message "hello", and a single +pair with key "count" and value 3. + +The [Info] top-level function calls the [Logger.Info] method on the default Logger. +In addition to [Logger.Info], there are methods for Debug, Warn and Error levels. +Besides these convenience methods for common levels, +there is also a [Logger.Log] method which takes the level as an argument. +Each of these methods has a corresponding top-level function that uses the +default logger. + +The default handler formats the log record's message, time, level, and attributes +as a string and passes it to the [log] package. + + 2022/11/08 15:28:26 INFO hello count=3 + +For more control over the output format, create a logger with a different handler. +This statement uses [New] to create a new logger with a TextHandler +that writes structured records in text form to standard error: + + logger := slog.New(slog.NewTextHandler(os.Stderr, nil)) + +[TextHandler] output is a sequence of key=value pairs, easily and unambiguously +parsed by machine. This statement: + + logger.Info("hello", "count", 3) + +produces this output: + + time=2022-11-08T15:28:26.000-05:00 level=INFO msg=hello count=3 + +The package also provides [JSONHandler], whose output is line-delimited JSON: + + logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)) + logger.Info("hello", "count", 3) + +produces this output: + + {"time":"2022-11-08T15:28:26.000000000-05:00","level":"INFO","msg":"hello","count":3} + +Both [TextHandler] and [JSONHandler] can be configured with [HandlerOptions]. +There are options for setting the minimum level (see Levels, below), +displaying the source file and line of the log call, and +modifying attributes before they are logged. + +Setting a logger as the default with + + slog.SetDefault(logger) + +will cause the top-level functions like [Info] to use it. +[SetDefault] also updates the default logger used by the [log] package, +so that existing applications that use [log.Printf] and related functions +will send log records to the logger's handler without needing to be rewritten. + +Some attributes are common to many log calls. +For example, you may wish to include the URL or trace identifier of a server request +with all log events arising from the request. +Rather than repeat the attribute with every log call, you can use [Logger.With] +to construct a new Logger containing the attributes: + + logger2 := logger.With("url", r.URL) + +The arguments to With are the same key-value pairs used in [Logger.Info]. +The result is a new Logger with the same handler as the original, but additional +attributes that will appear in the output of every call. + +# Levels + +A [Level] is an integer representing the importance or severity of a log event. +The higher the level, the more severe the event. +This package defines constants for the most common levels, +but any int can be used as a level. + +In an application, you may wish to log messages only at a certain level or greater. +One common configuration is to log messages at Info or higher levels, +suppressing debug logging until it is needed. +The built-in handlers can be configured with the minimum level to output by +setting [HandlerOptions.Level]. +The program's `main` function typically does this. +The default value is LevelInfo. + +Setting the [HandlerOptions.Level] field to a [Level] value +fixes the handler's minimum level throughout its lifetime. +Setting it to a [LevelVar] allows the level to be varied dynamically. +A LevelVar holds a Level and is safe to read or write from multiple +goroutines. +To vary the level dynamically for an entire program, first initialize +a global LevelVar: + + var programLevel = new(slog.LevelVar) // Info by default + +Then use the LevelVar to construct a handler, and make it the default: + + h := slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: programLevel}) + slog.SetDefault(slog.New(h)) + +Now the program can change its logging level with a single statement: + + programLevel.Set(slog.LevelDebug) + +# Groups + +Attributes can be collected into groups. +A group has a name that is used to qualify the names of its attributes. +How this qualification is displayed depends on the handler. +[TextHandler] separates the group and attribute names with a dot. +[JSONHandler] treats each group as a separate JSON object, with the group name as the key. + +Use [Group] to create a Group attribute from a name and a list of key-value pairs: + + slog.Group("request", + "method", r.Method, + "url", r.URL) + +TextHandler would display this group as + + request.method=GET request.url=http://example.com + +JSONHandler would display it as + + "request":{"method":"GET","url":"http://example.com"} + +Use [Logger.WithGroup] to qualify all of a Logger's output +with a group name. Calling WithGroup on a Logger results in a +new Logger with the same Handler as the original, but with all +its attributes qualified by the group name. + +This can help prevent duplicate attribute keys in large systems, +where subsystems might use the same keys. +Pass each subsystem a different Logger with its own group name so that +potential duplicates are qualified: + + logger := slog.Default().With("id", systemID) + parserLogger := logger.WithGroup("parser") + parseInput(input, parserLogger) + +When parseInput logs with parserLogger, its keys will be qualified with "parser", +so even if it uses the common key "id", the log line will have distinct keys. + +# Contexts + +Some handlers may wish to include information from the [context.Context] that is +available at the call site. One example of such information +is the identifier for the current span when tracing is enabled. + +The [Logger.Log] and [Logger.LogAttrs] methods take a context as a first +argument, as do their corresponding top-level functions. + +Although the convenience methods on Logger (Info and so on) and the +corresponding top-level functions do not take a context, the alternatives ending +in "Context" do. For example, + + slog.InfoContext(ctx, "message") + +It is recommended to pass a context to an output method if one is available. + +# Attrs and Values + +An [Attr] is a key-value pair. The Logger output methods accept Attrs as well as +alternating keys and values. The statement + + slog.Info("hello", slog.Int("count", 3)) + +behaves the same as + + slog.Info("hello", "count", 3) + +There are convenience constructors for [Attr] such as [Int], [String], and [Bool] +for common types, as well as the function [Any] for constructing Attrs of any +type. + +The value part of an Attr is a type called [Value]. +Like an [any], a Value can hold any Go value, +but it can represent typical values, including all numbers and strings, +without an allocation. + +For the most efficient log output, use [Logger.LogAttrs]. +It is similar to [Logger.Log] but accepts only Attrs, not alternating +keys and values; this allows it, too, to avoid allocation. + +The call + + logger.LogAttrs(ctx, slog.LevelInfo, "hello", slog.Int("count", 3)) + +is the most efficient way to achieve the same output as + + slog.Info("hello", "count", 3) + +# Customizing a type's logging behavior + +If a type implements the [LogValuer] interface, the [Value] returned from its LogValue +method is used for logging. You can use this to control how values of the type +appear in logs. For example, you can redact secret information like passwords, +or gather a struct's fields in a Group. See the examples under [LogValuer] for +details. + +A LogValue method may return a Value that itself implements [LogValuer]. The [Value.Resolve] +method handles these cases carefully, avoiding infinite loops and unbounded recursion. +Handler authors and others may wish to use Value.Resolve instead of calling LogValue directly. + +# Wrapping output methods + +The logger functions use reflection over the call stack to find the file name +and line number of the logging call within the application. This can produce +incorrect source information for functions that wrap slog. For instance, if you +define this function in file mylog.go: + + func Infof(format string, args ...any) { + slog.Default().Info(fmt.Sprintf(format, args...)) + } + +and you call it like this in main.go: + + Infof(slog.Default(), "hello, %s", "world") + +then slog will report the source file as mylog.go, not main.go. + +A correct implementation of Infof will obtain the source location +(pc) and pass it to NewRecord. +The Infof function in the package-level example called "wrapping" +demonstrates how to do this. + +# Working with Records + +Sometimes a Handler will need to modify a Record +before passing it on to another Handler or backend. +A Record contains a mixture of simple public fields (e.g. Time, Level, Message) +and hidden fields that refer to state (such as attributes) indirectly. This +means that modifying a simple copy of a Record (e.g. by calling +[Record.Add] or [Record.AddAttrs] to add attributes) +may have unexpected effects on the original. +Before modifying a Record, use [Record.Clone] to +create a copy that shares no state with the original, +or create a new Record with [NewRecord] +and build up its Attrs by traversing the old ones with [Record.Attrs]. + +# Performance considerations + +If profiling your application demonstrates that logging is taking significant time, +the following suggestions may help. + +If many log lines have a common attribute, use [Logger.With] to create a Logger with +that attribute. The built-in handlers will format that attribute only once, at the +call to [Logger.With]. The [Handler] interface is designed to allow that optimization, +and a well-written Handler should take advantage of it. + +The arguments to a log call are always evaluated, even if the log event is discarded. +If possible, defer computation so that it happens only if the value is actually logged. +For example, consider the call + + slog.Info("starting request", "url", r.URL.String()) // may compute String unnecessarily + +The URL.String method will be called even if the logger discards Info-level events. +Instead, pass the URL directly: + + slog.Info("starting request", "url", &r.URL) // calls URL.String only if needed + +The built-in [TextHandler] will call its String method, but only +if the log event is enabled. +Avoiding the call to String also preserves the structure of the underlying value. +For example [JSONHandler] emits the components of the parsed URL as a JSON object. +If you want to avoid eagerly paying the cost of the String call +without causing the handler to potentially inspect the structure of the value, +wrap the value in a fmt.Stringer implementation that hides its Marshal methods. + +You can also use the [LogValuer] interface to avoid unnecessary work in disabled log +calls. Say you need to log some expensive value: + + slog.Debug("frobbing", "value", computeExpensiveValue(arg)) + +Even if this line is disabled, computeExpensiveValue will be called. +To avoid that, define a type implementing LogValuer: + + type expensive struct { arg int } + + func (e expensive) LogValue() slog.Value { + return slog.AnyValue(computeExpensiveValue(e.arg)) + } + +Then use a value of that type in log calls: + + slog.Debug("frobbing", "value", expensive{arg}) + +Now computeExpensiveValue will only be called when the line is enabled. + +The built-in handlers acquire a lock before calling [io.Writer.Write] +to ensure that each record is written in one piece. User-defined +handlers are responsible for their own locking. + +# Writing a handler + +For a guide to writing a custom handler, see https://golang.org/s/slog-handler-guide. +*/ +package slog diff --git a/src/log/slog/example_custom_levels_test.go b/src/log/slog/example_custom_levels_test.go new file mode 100644 index 0000000..7351ca4 --- /dev/null +++ b/src/log/slog/example_custom_levels_test.go @@ -0,0 +1,93 @@ +// Copyright 2023 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog_test + +import ( + "context" + "log/slog" + "os" +) + +// This example demonstrates using custom log levels and custom log level names. +// In addition to the default log levels, it introduces Trace, Notice, and +// Emergency levels. The ReplaceAttr changes the way levels are printed for both +// the standard log levels and the custom log levels. +func ExampleHandlerOptions_customLevels() { + // Exported constants from a custom logging package. + const ( + LevelTrace = slog.Level(-8) + LevelDebug = slog.LevelDebug + LevelInfo = slog.LevelInfo + LevelNotice = slog.Level(2) + LevelWarning = slog.LevelWarn + LevelError = slog.LevelError + LevelEmergency = slog.Level(12) + ) + + th := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ + // Set a custom level to show all log output. The default value is + // LevelInfo, which would drop Debug and Trace logs. + Level: LevelTrace, + + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + // Remove time from the output for predictable test output. + if a.Key == slog.TimeKey { + return slog.Attr{} + } + + // Customize the name of the level key and the output string, including + // custom level values. + if a.Key == slog.LevelKey { + // Rename the level key from "level" to "sev". + a.Key = "sev" + + // Handle custom level values. + level := a.Value.Any().(slog.Level) + + // This could also look up the name from a map or other structure, but + // this demonstrates using a switch statement to rename levels. For + // maximum performance, the string values should be constants, but this + // example uses the raw strings for readability. + switch { + case level < LevelDebug: + a.Value = slog.StringValue("TRACE") + case level < LevelInfo: + a.Value = slog.StringValue("DEBUG") + case level < LevelNotice: + a.Value = slog.StringValue("INFO") + case level < LevelWarning: + a.Value = slog.StringValue("NOTICE") + case level < LevelError: + a.Value = slog.StringValue("WARNING") + case level < LevelEmergency: + a.Value = slog.StringValue("ERROR") + default: + a.Value = slog.StringValue("EMERGENCY") + } + } + + return a + }, + }) + + logger := slog.New(th) + ctx := context.Background() + logger.Log(ctx, LevelEmergency, "missing pilots") + logger.Error("failed to start engines", "err", "missing fuel") + logger.Warn("falling back to default value") + logger.Log(ctx, LevelNotice, "all systems are running") + logger.Info("initiating launch") + logger.Debug("starting background job") + logger.Log(ctx, LevelTrace, "button clicked") + + // Output: + // sev=EMERGENCY msg="missing pilots" + // sev=ERROR msg="failed to start engines" err="missing fuel" + // sev=WARNING msg="falling back to default value" + // sev=NOTICE msg="all systems are running" + // sev=INFO msg="initiating launch" + // sev=DEBUG msg="starting background job" + // sev=TRACE msg="button clicked" +} diff --git a/src/log/slog/example_level_handler_test.go b/src/log/slog/example_level_handler_test.go new file mode 100644 index 0000000..1ff91d4 --- /dev/null +++ b/src/log/slog/example_level_handler_test.go @@ -0,0 +1,73 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog_test + +import ( + "context" + "log/slog" + "log/slog/internal/slogtest" + "os" +) + +// A LevelHandler wraps a Handler with an Enabled method +// that returns false for levels below a minimum. +type LevelHandler struct { + level slog.Leveler + handler slog.Handler +} + +// NewLevelHandler returns a LevelHandler with the given level. +// All methods except Enabled delegate to h. +func NewLevelHandler(level slog.Leveler, h slog.Handler) *LevelHandler { + // Optimization: avoid chains of LevelHandlers. + if lh, ok := h.(*LevelHandler); ok { + h = lh.Handler() + } + return &LevelHandler{level, h} +} + +// Enabled implements Handler.Enabled by reporting whether +// level is at least as large as h's level. +func (h *LevelHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.level.Level() +} + +// Handle implements Handler.Handle. +func (h *LevelHandler) Handle(ctx context.Context, r slog.Record) error { + return h.handler.Handle(ctx, r) +} + +// WithAttrs implements Handler.WithAttrs. +func (h *LevelHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return NewLevelHandler(h.level, h.handler.WithAttrs(attrs)) +} + +// WithGroup implements Handler.WithGroup. +func (h *LevelHandler) WithGroup(name string) slog.Handler { + return NewLevelHandler(h.level, h.handler.WithGroup(name)) +} + +// Handler returns the Handler wrapped by h. +func (h *LevelHandler) Handler() slog.Handler { + return h.handler +} + +// This example shows how to Use a LevelHandler to change the level of an +// existing Handler while preserving its other behavior. +// +// This example demonstrates increasing the log level to reduce a logger's +// output. +// +// Another typical use would be to decrease the log level (to LevelDebug, say) +// during a part of the program that was suspected of containing a bug. +func ExampleHandler_levelHandler() { + th := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ReplaceAttr: slogtest.RemoveTime}) + logger := slog.New(NewLevelHandler(slog.LevelWarn, th)) + logger.Info("not printed") + logger.Warn("printed") + + // Output: + // level=WARN msg=printed +} diff --git a/src/log/slog/example_logvaluer_group_test.go b/src/log/slog/example_logvaluer_group_test.go new file mode 100644 index 0000000..4cc478f --- /dev/null +++ b/src/log/slog/example_logvaluer_group_test.go @@ -0,0 +1,35 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog_test + +import "log/slog" + +type Name struct { + First, Last string +} + +// LogValue implements slog.LogValuer. +// It returns a group containing the fields of +// the Name, so that they appear together in the log output. +func (n Name) LogValue() slog.Value { + return slog.GroupValue( + slog.String("first", n.First), + slog.String("last", n.Last)) +} + +func ExampleLogValuer_group() { + n := Name{"Perry", "Platypus"} + slog.Info("mission accomplished", "agent", n) + + // JSON Output would look in part like: + // { + // ... + // "msg": "mission accomplished", + // "agent": { + // "first": "Perry", + // "last": "Platypus" + // } + // } +} diff --git a/src/log/slog/example_logvaluer_secret_test.go b/src/log/slog/example_logvaluer_secret_test.go new file mode 100644 index 0000000..51d0020 --- /dev/null +++ b/src/log/slog/example_logvaluer_secret_test.go @@ -0,0 +1,31 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog_test + +import ( + "log/slog" + "log/slog/internal/slogtest" + "os" +) + +// A token is a secret value that grants permissions. +type Token string + +// LogValue implements slog.LogValuer. +// It avoids revealing the token. +func (Token) LogValue() slog.Value { + return slog.StringValue("REDACTED_TOKEN") +} + +// This example demonstrates a Value that replaces itself +// with an alternative representation to avoid revealing secrets. +func ExampleLogValuer_secret() { + t := Token("shhhh!") + logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ReplaceAttr: slogtest.RemoveTime})) + logger.Info("permission granted", "user", "Perry", "token", t) + + // Output: + // level=INFO msg="permission granted" user=Perry token=REDACTED_TOKEN +} diff --git a/src/log/slog/example_test.go b/src/log/slog/example_test.go new file mode 100644 index 0000000..a677456 --- /dev/null +++ b/src/log/slog/example_test.go @@ -0,0 +1,29 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog_test + +import ( + "log/slog" + "log/slog/internal/slogtest" + "net/http" + "os" + "time" +) + +func ExampleGroup() { + r, _ := http.NewRequest("GET", "localhost", nil) + // ... + + logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ReplaceAttr: slogtest.RemoveTime})) + logger.Info("finished", + slog.Group("req", + slog.String("method", r.Method), + slog.String("url", r.URL.String())), + slog.Int("status", http.StatusOK), + slog.Duration("duration", time.Second)) + + // Output: + // level=INFO msg=finished req.method=GET req.url=localhost status=200 duration=1s +} diff --git a/src/log/slog/example_wrap_test.go b/src/log/slog/example_wrap_test.go new file mode 100644 index 0000000..dcc87b8 --- /dev/null +++ b/src/log/slog/example_wrap_test.go @@ -0,0 +1,47 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog_test + +import ( + "context" + "fmt" + "log/slog" + "os" + "path/filepath" + "runtime" + "time" +) + +// Infof is an example of a user-defined logging function that wraps slog. +// The log record contains the source position of the caller of Infof. +func Infof(logger *slog.Logger, format string, args ...any) { + if !logger.Enabled(context.Background(), slog.LevelInfo) { + return + } + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(time.Now(), slog.LevelInfo, fmt.Sprintf(format, args...), pcs[0]) + _ = logger.Handler().Handle(context.Background(), r) +} + +func Example_wrapping() { + replace := func(groups []string, a slog.Attr) slog.Attr { + // Remove time. + if a.Key == slog.TimeKey && len(groups) == 0 { + return slog.Attr{} + } + // Remove the directory from the source's filename. + if a.Key == slog.SourceKey { + source := a.Value.Any().(*slog.Source) + source.File = filepath.Base(source.File) + } + return a + } + logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{AddSource: true, ReplaceAttr: replace})) + Infof(logger, "message, %s", "formatted") + + // Output: + // level=INFO source=example_wrap_test.go:43 msg="message, formatted" +} diff --git a/src/log/slog/handler.go b/src/log/slog/handler.go new file mode 100644 index 0000000..a73983c --- /dev/null +++ b/src/log/slog/handler.go @@ -0,0 +1,567 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "context" + "fmt" + "io" + "log/slog/internal/buffer" + "slices" + "strconv" + "sync" + "time" +) + +// A Handler handles log records produced by a Logger.. +// +// A typical handler may print log records to standard error, +// or write them to a file or database, or perhaps augment them +// with additional attributes and pass them on to another handler. +// +// Any of the Handler's methods may be called concurrently with itself +// or with other methods. It is the responsibility of the Handler to +// manage this concurrency. +// +// Users of the slog package should not invoke Handler methods directly. +// They should use the methods of [Logger] instead. +type Handler interface { + // Enabled reports whether the handler handles records at the given level. + // The handler ignores records whose level is lower. + // It is called early, before any arguments are processed, + // to save effort if the log event should be discarded. + // If called from a Logger method, the first argument is the context + // passed to that method, or context.Background() if nil was passed + // or the method does not take a context. + // The context is passed so Enabled can use its values + // to make a decision. + Enabled(context.Context, Level) bool + + // Handle handles the Record. + // It will only be called when Enabled returns true. + // The Context argument is as for Enabled. + // It is present solely to provide Handlers access to the context's values. + // Canceling the context should not affect record processing. + // (Among other things, log messages may be necessary to debug a + // cancellation-related problem.) + // + // Handle methods that produce output should observe the following rules: + // - If r.Time is the zero time, ignore the time. + // - If r.PC is zero, ignore it. + // - Attr's values should be resolved. + // - If an Attr's key and value are both the zero value, ignore the Attr. + // This can be tested with attr.Equal(Attr{}). + // - If a group's key is empty, inline the group's Attrs. + // - If a group has no Attrs (even if it has a non-empty key), + // ignore it. + Handle(context.Context, Record) error + + // WithAttrs returns a new Handler whose attributes consist of + // both the receiver's attributes and the arguments. + // The Handler owns the slice: it may retain, modify or discard it. + WithAttrs(attrs []Attr) Handler + + // WithGroup returns a new Handler with the given group appended to + // the receiver's existing groups. + // The keys of all subsequent attributes, whether added by With or in a + // Record, should be qualified by the sequence of group names. + // + // How this qualification happens is up to the Handler, so long as + // this Handler's attribute keys differ from those of another Handler + // with a different sequence of group names. + // + // A Handler should treat WithGroup as starting a Group of Attrs that ends + // at the end of the log event. That is, + // + // logger.WithGroup("s").LogAttrs(level, msg, slog.Int("a", 1), slog.Int("b", 2)) + // + // should behave like + // + // logger.LogAttrs(level, msg, slog.Group("s", slog.Int("a", 1), slog.Int("b", 2))) + // + // If the name is empty, WithGroup returns the receiver. + WithGroup(name string) Handler +} + +type defaultHandler struct { + ch *commonHandler + // internal.DefaultOutput, except for testing + output func(pc uintptr, data []byte) error +} + +func newDefaultHandler(output func(uintptr, []byte) error) *defaultHandler { + return &defaultHandler{ + ch: &commonHandler{json: false}, + output: output, + } +} + +func (*defaultHandler) Enabled(_ context.Context, l Level) bool { + return l >= LevelInfo +} + +// Collect the level, attributes and message in a string and +// write it with the default log.Logger. +// Let the log.Logger handle time and file/line. +func (h *defaultHandler) Handle(ctx context.Context, r Record) error { + buf := buffer.New() + buf.WriteString(r.Level.String()) + buf.WriteByte(' ') + buf.WriteString(r.Message) + state := h.ch.newHandleState(buf, true, " ") + defer state.free() + state.appendNonBuiltIns(r) + return h.output(r.PC, *buf) +} + +func (h *defaultHandler) WithAttrs(as []Attr) Handler { + return &defaultHandler{h.ch.withAttrs(as), h.output} +} + +func (h *defaultHandler) WithGroup(name string) Handler { + return &defaultHandler{h.ch.withGroup(name), h.output} +} + +// HandlerOptions are options for a TextHandler or JSONHandler. +// A zero HandlerOptions consists entirely of default values. +type HandlerOptions struct { + // AddSource causes the handler to compute the source code position + // of the log statement and add a SourceKey attribute to the output. + AddSource bool + + // Level reports the minimum record level that will be logged. + // The handler discards records with lower levels. + // If Level is nil, the handler assumes LevelInfo. + // The handler calls Level.Level for each record processed; + // to adjust the minimum level dynamically, use a LevelVar. + Level Leveler + + // ReplaceAttr is called to rewrite each non-group attribute before it is logged. + // The attribute's value has been resolved (see [Value.Resolve]). + // If ReplaceAttr returns a zero Attr, the attribute is discarded. + // + // The built-in attributes with keys "time", "level", "source", and "msg" + // are passed to this function, except that time is omitted + // if zero, and source is omitted if AddSource is false. + // + // The first argument is a list of currently open groups that contain the + // Attr. It must not be retained or modified. ReplaceAttr is never called + // for Group attributes, only their contents. For example, the attribute + // list + // + // Int("a", 1), Group("g", Int("b", 2)), Int("c", 3) + // + // results in consecutive calls to ReplaceAttr with the following arguments: + // + // nil, Int("a", 1) + // []string{"g"}, Int("b", 2) + // nil, Int("c", 3) + // + // ReplaceAttr can be used to change the default keys of the built-in + // attributes, convert types (for example, to replace a `time.Time` with the + // integer seconds since the Unix epoch), sanitize personal information, or + // remove attributes from the output. + ReplaceAttr func(groups []string, a Attr) Attr +} + +// Keys for "built-in" attributes. +const ( + // TimeKey is the key used by the built-in handlers for the time + // when the log method is called. The associated Value is a [time.Time]. + TimeKey = "time" + // LevelKey is the key used by the built-in handlers for the level + // of the log call. The associated value is a [Level]. + LevelKey = "level" + // MessageKey is the key used by the built-in handlers for the + // message of the log call. The associated value is a string. + MessageKey = "msg" + // SourceKey is the key used by the built-in handlers for the source file + // and line of the log call. The associated value is a string. + SourceKey = "source" +) + +type commonHandler struct { + json bool // true => output JSON; false => output text + opts HandlerOptions + preformattedAttrs []byte + // groupPrefix is for the text handler only. + // It holds the prefix for groups that were already pre-formatted. + // A group will appear here when a call to WithGroup is followed by + // a call to WithAttrs. + groupPrefix string + groups []string // all groups started from WithGroup + nOpenGroups int // the number of groups opened in preformattedAttrs + mu *sync.Mutex + w io.Writer +} + +func (h *commonHandler) clone() *commonHandler { + // We can't use assignment because we can't copy the mutex. + return &commonHandler{ + json: h.json, + opts: h.opts, + preformattedAttrs: slices.Clip(h.preformattedAttrs), + groupPrefix: h.groupPrefix, + groups: slices.Clip(h.groups), + nOpenGroups: h.nOpenGroups, + w: h.w, + mu: h.mu, // mutex shared among all clones of this handler + } +} + +// enabled reports whether l is greater than or equal to the +// minimum level. +func (h *commonHandler) enabled(l Level) bool { + minLevel := LevelInfo + if h.opts.Level != nil { + minLevel = h.opts.Level.Level() + } + return l >= minLevel +} + +func (h *commonHandler) withAttrs(as []Attr) *commonHandler { + // We are going to ignore empty groups, so if the entire slice consists of + // them, there is nothing to do. + if countEmptyGroups(as) == len(as) { + return h + } + h2 := h.clone() + // Pre-format the attributes as an optimization. + state := h2.newHandleState((*buffer.Buffer)(&h2.preformattedAttrs), false, "") + defer state.free() + state.prefix.WriteString(h.groupPrefix) + if len(h2.preformattedAttrs) > 0 { + state.sep = h.attrSep() + } + state.openGroups() + for _, a := range as { + state.appendAttr(a) + } + // Remember the new prefix for later keys. + h2.groupPrefix = state.prefix.String() + // Remember how many opened groups are in preformattedAttrs, + // so we don't open them again when we handle a Record. + h2.nOpenGroups = len(h2.groups) + return h2 +} + +func (h *commonHandler) withGroup(name string) *commonHandler { + h2 := h.clone() + h2.groups = append(h2.groups, name) + return h2 +} + +// handle is the internal implementation of Handler.Handle +// used by TextHandler and JSONHandler. +func (h *commonHandler) handle(r Record) error { + state := h.newHandleState(buffer.New(), true, "") + defer state.free() + if h.json { + state.buf.WriteByte('{') + } + // Built-in attributes. They are not in a group. + stateGroups := state.groups + state.groups = nil // So ReplaceAttrs sees no groups instead of the pre groups. + rep := h.opts.ReplaceAttr + // time + if !r.Time.IsZero() { + key := TimeKey + val := r.Time.Round(0) // strip monotonic to match Attr behavior + if rep == nil { + state.appendKey(key) + state.appendTime(val) + } else { + state.appendAttr(Time(key, val)) + } + } + // level + key := LevelKey + val := r.Level + if rep == nil { + state.appendKey(key) + state.appendString(val.String()) + } else { + state.appendAttr(Any(key, val)) + } + // source + if h.opts.AddSource { + state.appendAttr(Any(SourceKey, r.source())) + } + key = MessageKey + msg := r.Message + if rep == nil { + state.appendKey(key) + state.appendString(msg) + } else { + state.appendAttr(String(key, msg)) + } + state.groups = stateGroups // Restore groups passed to ReplaceAttrs. + state.appendNonBuiltIns(r) + state.buf.WriteByte('\n') + + h.mu.Lock() + defer h.mu.Unlock() + _, err := h.w.Write(*state.buf) + return err +} + +func (s *handleState) appendNonBuiltIns(r Record) { + // preformatted Attrs + if len(s.h.preformattedAttrs) > 0 { + s.buf.WriteString(s.sep) + s.buf.Write(s.h.preformattedAttrs) + s.sep = s.h.attrSep() + } + // Attrs in Record -- unlike the built-in ones, they are in groups started + // from WithGroup. + // If the record has no Attrs, don't output any groups. + nOpenGroups := s.h.nOpenGroups + if r.NumAttrs() > 0 { + s.prefix.WriteString(s.h.groupPrefix) + s.openGroups() + nOpenGroups = len(s.h.groups) + r.Attrs(func(a Attr) bool { + s.appendAttr(a) + return true + }) + } + if s.h.json { + // Close all open groups. + for range s.h.groups[:nOpenGroups] { + s.buf.WriteByte('}') + } + // Close the top-level object. + s.buf.WriteByte('}') + } +} + +// attrSep returns the separator between attributes. +func (h *commonHandler) attrSep() string { + if h.json { + return "," + } + return " " +} + +// handleState holds state for a single call to commonHandler.handle. +// The initial value of sep determines whether to emit a separator +// before the next key, after which it stays true. +type handleState struct { + h *commonHandler + buf *buffer.Buffer + freeBuf bool // should buf be freed? + sep string // separator to write before next key + prefix *buffer.Buffer // for text: key prefix + groups *[]string // pool-allocated slice of active groups, for ReplaceAttr +} + +var groupPool = sync.Pool{New: func() any { + s := make([]string, 0, 10) + return &s +}} + +func (h *commonHandler) newHandleState(buf *buffer.Buffer, freeBuf bool, sep string) handleState { + s := handleState{ + h: h, + buf: buf, + freeBuf: freeBuf, + sep: sep, + prefix: buffer.New(), + } + if h.opts.ReplaceAttr != nil { + s.groups = groupPool.Get().(*[]string) + *s.groups = append(*s.groups, h.groups[:h.nOpenGroups]...) + } + return s +} + +func (s *handleState) free() { + if s.freeBuf { + s.buf.Free() + } + if gs := s.groups; gs != nil { + *gs = (*gs)[:0] + groupPool.Put(gs) + } + s.prefix.Free() +} + +func (s *handleState) openGroups() { + for _, n := range s.h.groups[s.h.nOpenGroups:] { + s.openGroup(n) + } +} + +// Separator for group names and keys. +const keyComponentSep = '.' + +// openGroup starts a new group of attributes +// with the given name. +func (s *handleState) openGroup(name string) { + if s.h.json { + s.appendKey(name) + s.buf.WriteByte('{') + s.sep = "" + } else { + s.prefix.WriteString(name) + s.prefix.WriteByte(keyComponentSep) + } + // Collect group names for ReplaceAttr. + if s.groups != nil { + *s.groups = append(*s.groups, name) + } +} + +// closeGroup ends the group with the given name. +func (s *handleState) closeGroup(name string) { + if s.h.json { + s.buf.WriteByte('}') + } else { + (*s.prefix) = (*s.prefix)[:len(*s.prefix)-len(name)-1 /* for keyComponentSep */] + } + s.sep = s.h.attrSep() + if s.groups != nil { + *s.groups = (*s.groups)[:len(*s.groups)-1] + } +} + +// appendAttr appends the Attr's key and value using app. +// It handles replacement and checking for an empty key. +// after replacement). +func (s *handleState) appendAttr(a Attr) { + if rep := s.h.opts.ReplaceAttr; rep != nil && a.Value.Kind() != KindGroup { + var gs []string + if s.groups != nil { + gs = *s.groups + } + // Resolve before calling ReplaceAttr, so the user doesn't have to. + a.Value = a.Value.Resolve() + a = rep(gs, a) + } + a.Value = a.Value.Resolve() + // Elide empty Attrs. + if a.isEmpty() { + return + } + // Special case: Source. + if v := a.Value; v.Kind() == KindAny { + if src, ok := v.Any().(*Source); ok { + if s.h.json { + a.Value = src.group() + } else { + a.Value = StringValue(fmt.Sprintf("%s:%d", src.File, src.Line)) + } + } + } + if a.Value.Kind() == KindGroup { + attrs := a.Value.Group() + // Output only non-empty groups. + if len(attrs) > 0 { + // Inline a group with an empty key. + if a.Key != "" { + s.openGroup(a.Key) + } + for _, aa := range attrs { + s.appendAttr(aa) + } + if a.Key != "" { + s.closeGroup(a.Key) + } + } + } else { + s.appendKey(a.Key) + s.appendValue(a.Value) + } +} + +func (s *handleState) appendError(err error) { + s.appendString(fmt.Sprintf("!ERROR:%v", err)) +} + +func (s *handleState) appendKey(key string) { + s.buf.WriteString(s.sep) + if s.prefix != nil && len(*s.prefix) > 0 { + // TODO: optimize by avoiding allocation. + s.appendString(string(*s.prefix) + key) + } else { + s.appendString(key) + } + if s.h.json { + s.buf.WriteByte(':') + } else { + s.buf.WriteByte('=') + } + s.sep = s.h.attrSep() +} + +func (s *handleState) appendString(str string) { + if s.h.json { + s.buf.WriteByte('"') + *s.buf = appendEscapedJSONString(*s.buf, str) + s.buf.WriteByte('"') + } else { + // text + if needsQuoting(str) { + *s.buf = strconv.AppendQuote(*s.buf, str) + } else { + s.buf.WriteString(str) + } + } +} + +func (s *handleState) appendValue(v Value) { + var err error + if s.h.json { + err = appendJSONValue(s, v) + } else { + err = appendTextValue(s, v) + } + if err != nil { + s.appendError(err) + } +} + +func (s *handleState) appendTime(t time.Time) { + if s.h.json { + appendJSONTime(s, t) + } else { + writeTimeRFC3339Millis(s.buf, t) + } +} + +// This takes half the time of Time.AppendFormat. +func writeTimeRFC3339Millis(buf *buffer.Buffer, t time.Time) { + year, month, day := t.Date() + buf.WritePosIntWidth(year, 4) + buf.WriteByte('-') + buf.WritePosIntWidth(int(month), 2) + buf.WriteByte('-') + buf.WritePosIntWidth(day, 2) + buf.WriteByte('T') + hour, min, sec := t.Clock() + buf.WritePosIntWidth(hour, 2) + buf.WriteByte(':') + buf.WritePosIntWidth(min, 2) + buf.WriteByte(':') + buf.WritePosIntWidth(sec, 2) + ns := t.Nanosecond() + buf.WriteByte('.') + buf.WritePosIntWidth(ns/1e6, 3) + _, offsetSeconds := t.Zone() + if offsetSeconds == 0 { + buf.WriteByte('Z') + } else { + offsetMinutes := offsetSeconds / 60 + if offsetMinutes < 0 { + buf.WriteByte('-') + offsetMinutes = -offsetMinutes + } else { + buf.WriteByte('+') + } + buf.WritePosIntWidth(offsetMinutes/60, 2) + buf.WriteByte(':') + buf.WritePosIntWidth(offsetMinutes%60, 2) + } +} diff --git a/src/log/slog/handler_test.go b/src/log/slog/handler_test.go new file mode 100644 index 0000000..4f10ee5 --- /dev/null +++ b/src/log/slog/handler_test.go @@ -0,0 +1,626 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// TODO: verify that the output of Marshal{Text,JSON} is suitably escaped. + +package slog + +import ( + "bytes" + "context" + "encoding/json" + "io" + "log/slog/internal/buffer" + "path/filepath" + "slices" + "strconv" + "strings" + "sync" + "testing" + "time" +) + +func TestDefaultHandle(t *testing.T) { + ctx := context.Background() + preAttrs := []Attr{Int("pre", 0)} + attrs := []Attr{Int("a", 1), String("b", "two")} + for _, test := range []struct { + name string + with func(Handler) Handler + attrs []Attr + want string + }{ + { + name: "no attrs", + want: "INFO message", + }, + { + name: "attrs", + attrs: attrs, + want: "INFO message a=1 b=two", + }, + { + name: "preformatted", + with: func(h Handler) Handler { return h.WithAttrs(preAttrs) }, + attrs: attrs, + want: "INFO message pre=0 a=1 b=two", + }, + { + name: "groups", + attrs: []Attr{ + Int("a", 1), + Group("g", + Int("b", 2), + Group("h", Int("c", 3)), + Int("d", 4)), + Int("e", 5), + }, + want: "INFO message a=1 g.b=2 g.h.c=3 g.d=4 e=5", + }, + { + name: "group", + with: func(h Handler) Handler { return h.WithAttrs(preAttrs).WithGroup("s") }, + attrs: attrs, + want: "INFO message pre=0 s.a=1 s.b=two", + }, + { + name: "preformatted groups", + with: func(h Handler) Handler { + return h.WithAttrs([]Attr{Int("p1", 1)}). + WithGroup("s1"). + WithAttrs([]Attr{Int("p2", 2)}). + WithGroup("s2") + }, + attrs: attrs, + want: "INFO message p1=1 s1.p2=2 s1.s2.a=1 s1.s2.b=two", + }, + { + name: "two with-groups", + with: func(h Handler) Handler { + return h.WithAttrs([]Attr{Int("p1", 1)}). + WithGroup("s1"). + WithGroup("s2") + }, + attrs: attrs, + want: "INFO message p1=1 s1.s2.a=1 s1.s2.b=two", + }, + } { + t.Run(test.name, func(t *testing.T) { + var got string + var h Handler = newDefaultHandler(func(_ uintptr, b []byte) error { + got = string(b) + return nil + }) + if test.with != nil { + h = test.with(h) + } + r := NewRecord(time.Time{}, LevelInfo, "message", 0) + r.AddAttrs(test.attrs...) + if err := h.Handle(ctx, r); err != nil { + t.Fatal(err) + } + if got != test.want { + t.Errorf("\ngot %s\nwant %s", got, test.want) + } + }) + } +} + +func TestConcurrentWrites(t *testing.T) { + ctx := context.Background() + count := 1000 + for _, handlerType := range []string{"text", "json"} { + t.Run(handlerType, func(t *testing.T) { + var buf bytes.Buffer + var h Handler + switch handlerType { + case "text": + h = NewTextHandler(&buf, nil) + case "json": + h = NewJSONHandler(&buf, nil) + default: + t.Fatalf("unexpected handlerType %q", handlerType) + } + sub1 := h.WithAttrs([]Attr{Bool("sub1", true)}) + sub2 := h.WithAttrs([]Attr{Bool("sub2", true)}) + var wg sync.WaitGroup + for i := 0; i < count; i++ { + sub1Record := NewRecord(time.Time{}, LevelInfo, "hello from sub1", 0) + sub1Record.AddAttrs(Int("i", i)) + sub2Record := NewRecord(time.Time{}, LevelInfo, "hello from sub2", 0) + sub2Record.AddAttrs(Int("i", i)) + wg.Add(1) + go func() { + defer wg.Done() + if err := sub1.Handle(ctx, sub1Record); err != nil { + t.Error(err) + } + if err := sub2.Handle(ctx, sub2Record); err != nil { + t.Error(err) + } + }() + } + wg.Wait() + for i := 1; i <= 2; i++ { + want := "hello from sub" + strconv.Itoa(i) + n := strings.Count(buf.String(), want) + if n != count { + t.Fatalf("want %d occurrences of %q, got %d", count, want, n) + } + } + }) + } +} + +// Verify the common parts of TextHandler and JSONHandler. +func TestJSONAndTextHandlers(t *testing.T) { + // remove all Attrs + removeAll := func(_ []string, a Attr) Attr { return Attr{} } + + attrs := []Attr{String("a", "one"), Int("b", 2), Any("", nil)} + preAttrs := []Attr{Int("pre", 3), String("x", "y")} + + for _, test := range []struct { + name string + replace func([]string, Attr) Attr + addSource bool + with func(Handler) Handler + preAttrs []Attr + attrs []Attr + wantText string + wantJSON string + }{ + { + name: "basic", + attrs: attrs, + wantText: "time=2000-01-02T03:04:05.000Z level=INFO msg=message a=one b=2", + wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","a":"one","b":2}`, + }, + { + name: "empty key", + attrs: append(slices.Clip(attrs), Any("", "v")), + wantText: `time=2000-01-02T03:04:05.000Z level=INFO msg=message a=one b=2 ""=v`, + wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","a":"one","b":2,"":"v"}`, + }, + { + name: "cap keys", + replace: upperCaseKey, + attrs: attrs, + wantText: "TIME=2000-01-02T03:04:05.000Z LEVEL=INFO MSG=message A=one B=2", + wantJSON: `{"TIME":"2000-01-02T03:04:05Z","LEVEL":"INFO","MSG":"message","A":"one","B":2}`, + }, + { + name: "remove all", + replace: removeAll, + attrs: attrs, + wantText: "", + wantJSON: `{}`, + }, + { + name: "preformatted", + with: func(h Handler) Handler { return h.WithAttrs(preAttrs) }, + preAttrs: preAttrs, + attrs: attrs, + wantText: "time=2000-01-02T03:04:05.000Z level=INFO msg=message pre=3 x=y a=one b=2", + wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","pre":3,"x":"y","a":"one","b":2}`, + }, + { + name: "preformatted cap keys", + replace: upperCaseKey, + with: func(h Handler) Handler { return h.WithAttrs(preAttrs) }, + preAttrs: preAttrs, + attrs: attrs, + wantText: "TIME=2000-01-02T03:04:05.000Z LEVEL=INFO MSG=message PRE=3 X=y A=one B=2", + wantJSON: `{"TIME":"2000-01-02T03:04:05Z","LEVEL":"INFO","MSG":"message","PRE":3,"X":"y","A":"one","B":2}`, + }, + { + name: "preformatted remove all", + replace: removeAll, + with: func(h Handler) Handler { return h.WithAttrs(preAttrs) }, + preAttrs: preAttrs, + attrs: attrs, + wantText: "", + wantJSON: "{}", + }, + { + name: "remove built-in", + replace: removeKeys(TimeKey, LevelKey, MessageKey), + attrs: attrs, + wantText: "a=one b=2", + wantJSON: `{"a":"one","b":2}`, + }, + { + name: "preformatted remove built-in", + replace: removeKeys(TimeKey, LevelKey, MessageKey), + with: func(h Handler) Handler { return h.WithAttrs(preAttrs) }, + attrs: attrs, + wantText: "pre=3 x=y a=one b=2", + wantJSON: `{"pre":3,"x":"y","a":"one","b":2}`, + }, + { + name: "groups", + replace: removeKeys(TimeKey, LevelKey), // to simplify the result + attrs: []Attr{ + Int("a", 1), + Group("g", + Int("b", 2), + Group("h", Int("c", 3)), + Int("d", 4)), + Int("e", 5), + }, + wantText: "msg=message a=1 g.b=2 g.h.c=3 g.d=4 e=5", + wantJSON: `{"msg":"message","a":1,"g":{"b":2,"h":{"c":3},"d":4},"e":5}`, + }, + { + name: "empty group", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{Group("g"), Group("h", Int("a", 1))}, + wantText: "msg=message h.a=1", + wantJSON: `{"msg":"message","h":{"a":1}}`, + }, + { + name: "nested empty group", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{ + Group("g", + Group("h", + Group("i"), Group("j"))), + }, + wantText: `msg=message`, + wantJSON: `{"msg":"message"}`, + }, + { + name: "nested non-empty group", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{ + Group("g", + Group("h", + Group("i"), Group("j", Int("a", 1)))), + }, + wantText: `msg=message g.h.j.a=1`, + wantJSON: `{"msg":"message","g":{"h":{"j":{"a":1}}}}`, + }, + { + name: "escapes", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{ + String("a b", "x\t\n\000y"), + Group(" b.c=\"\\x2E\t", + String("d=e", "f.g\""), + Int("m.d", 1)), // dot is not escaped + }, + wantText: `msg=message "a b"="x\t\n\x00y" " b.c=\"\\x2E\t.d=e"="f.g\"" " b.c=\"\\x2E\t.m.d"=1`, + wantJSON: `{"msg":"message","a b":"x\t\n\u0000y"," b.c=\"\\x2E\t":{"d=e":"f.g\"","m.d":1}}`, + }, + { + name: "LogValuer", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{ + Int("a", 1), + Any("name", logValueName{"Ren", "Hoek"}), + Int("b", 2), + }, + wantText: "msg=message a=1 name.first=Ren name.last=Hoek b=2", + wantJSON: `{"msg":"message","a":1,"name":{"first":"Ren","last":"Hoek"},"b":2}`, + }, + { + // Test resolution when there is no ReplaceAttr function. + name: "resolve", + attrs: []Attr{ + Any("", &replace{Value{}}), // should be elided + Any("name", logValueName{"Ren", "Hoek"}), + }, + wantText: "time=2000-01-02T03:04:05.000Z level=INFO msg=message name.first=Ren name.last=Hoek", + wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","name":{"first":"Ren","last":"Hoek"}}`, + }, + { + name: "with-group", + replace: removeKeys(TimeKey, LevelKey), + with: func(h Handler) Handler { return h.WithAttrs(preAttrs).WithGroup("s") }, + attrs: attrs, + wantText: "msg=message pre=3 x=y s.a=one s.b=2", + wantJSON: `{"msg":"message","pre":3,"x":"y","s":{"a":"one","b":2}}`, + }, + { + name: "preformatted with-groups", + replace: removeKeys(TimeKey, LevelKey), + with: func(h Handler) Handler { + return h.WithAttrs([]Attr{Int("p1", 1)}). + WithGroup("s1"). + WithAttrs([]Attr{Int("p2", 2)}). + WithGroup("s2"). + WithAttrs([]Attr{Int("p3", 3)}) + }, + attrs: attrs, + wantText: "msg=message p1=1 s1.p2=2 s1.s2.p3=3 s1.s2.a=one s1.s2.b=2", + wantJSON: `{"msg":"message","p1":1,"s1":{"p2":2,"s2":{"p3":3,"a":"one","b":2}}}`, + }, + { + name: "two with-groups", + replace: removeKeys(TimeKey, LevelKey), + with: func(h Handler) Handler { + return h.WithAttrs([]Attr{Int("p1", 1)}). + WithGroup("s1"). + WithGroup("s2") + }, + attrs: attrs, + wantText: "msg=message p1=1 s1.s2.a=one s1.s2.b=2", + wantJSON: `{"msg":"message","p1":1,"s1":{"s2":{"a":"one","b":2}}}`, + }, + { + name: "empty with-groups", + replace: removeKeys(TimeKey, LevelKey), + with: func(h Handler) Handler { + return h.WithGroup("x").WithGroup("y") + }, + wantText: "msg=message", + wantJSON: `{"msg":"message"}`, + }, + { + name: "empty with-groups, no non-empty attrs", + replace: removeKeys(TimeKey, LevelKey), + with: func(h Handler) Handler { + return h.WithGroup("x").WithAttrs([]Attr{Group("g")}).WithGroup("y") + }, + wantText: "msg=message", + wantJSON: `{"msg":"message"}`, + }, + { + name: "one empty with-group", + replace: removeKeys(TimeKey, LevelKey), + with: func(h Handler) Handler { + return h.WithGroup("x").WithAttrs([]Attr{Int("a", 1)}).WithGroup("y") + }, + attrs: []Attr{Group("g", Group("h"))}, + wantText: "msg=message x.a=1", + wantJSON: `{"msg":"message","x":{"a":1}}`, + }, + { + name: "GroupValue as Attr value", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{{"v", AnyValue(IntValue(3))}}, + wantText: "msg=message v=3", + wantJSON: `{"msg":"message","v":3}`, + }, + { + name: "byte slice", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{Any("bs", []byte{1, 2, 3, 4})}, + wantText: `msg=message bs="\x01\x02\x03\x04"`, + wantJSON: `{"msg":"message","bs":"AQIDBA=="}`, + }, + { + name: "json.RawMessage", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{Any("bs", json.RawMessage([]byte("1234")))}, + wantText: `msg=message bs="1234"`, + wantJSON: `{"msg":"message","bs":1234}`, + }, + { + name: "inline group", + replace: removeKeys(TimeKey, LevelKey), + attrs: []Attr{ + Int("a", 1), + Group("", Int("b", 2), Int("c", 3)), + Int("d", 4), + }, + wantText: `msg=message a=1 b=2 c=3 d=4`, + wantJSON: `{"msg":"message","a":1,"b":2,"c":3,"d":4}`, + }, + { + name: "Source", + replace: func(gs []string, a Attr) Attr { + if a.Key == SourceKey { + s := a.Value.Any().(*Source) + s.File = filepath.Base(s.File) + return Any(a.Key, s) + } + return removeKeys(TimeKey, LevelKey)(gs, a) + }, + addSource: true, + wantText: `source=handler_test.go:$LINE msg=message`, + wantJSON: `{"source":{"function":"log/slog.TestJSONAndTextHandlers","file":"handler_test.go","line":$LINE},"msg":"message"}`, + }, + { + name: "replace built-in with group", + replace: func(_ []string, a Attr) Attr { + if a.Key == TimeKey { + return Group(TimeKey, "mins", 3, "secs", 2) + } + if a.Key == LevelKey { + return Attr{} + } + return a + }, + wantText: `time.mins=3 time.secs=2 msg=message`, + wantJSON: `{"time":{"mins":3,"secs":2},"msg":"message"}`, + }, + } { + r := NewRecord(testTime, LevelInfo, "message", callerPC(2)) + line := strconv.Itoa(r.source().Line) + r.AddAttrs(test.attrs...) + var buf bytes.Buffer + opts := HandlerOptions{ReplaceAttr: test.replace, AddSource: test.addSource} + t.Run(test.name, func(t *testing.T) { + for _, handler := range []struct { + name string + h Handler + want string + }{ + {"text", NewTextHandler(&buf, &opts), test.wantText}, + {"json", NewJSONHandler(&buf, &opts), test.wantJSON}, + } { + t.Run(handler.name, func(t *testing.T) { + h := handler.h + if test.with != nil { + h = test.with(h) + } + buf.Reset() + if err := h.Handle(nil, r); err != nil { + t.Fatal(err) + } + want := strings.ReplaceAll(handler.want, "$LINE", line) + got := strings.TrimSuffix(buf.String(), "\n") + if got != want { + t.Errorf("\ngot %s\nwant %s\n", got, want) + } + }) + } + }) + } +} + +// removeKeys returns a function suitable for HandlerOptions.ReplaceAttr +// that removes all Attrs with the given keys. +func removeKeys(keys ...string) func([]string, Attr) Attr { + return func(_ []string, a Attr) Attr { + for _, k := range keys { + if a.Key == k { + return Attr{} + } + } + return a + } +} + +func upperCaseKey(_ []string, a Attr) Attr { + a.Key = strings.ToUpper(a.Key) + return a +} + +type logValueName struct { + first, last string +} + +func (n logValueName) LogValue() Value { + return GroupValue( + String("first", n.first), + String("last", n.last)) +} + +func TestHandlerEnabled(t *testing.T) { + levelVar := func(l Level) *LevelVar { + var al LevelVar + al.Set(l) + return &al + } + + for _, test := range []struct { + leveler Leveler + want bool + }{ + {nil, true}, + {LevelWarn, false}, + {&LevelVar{}, true}, // defaults to Info + {levelVar(LevelWarn), false}, + {LevelDebug, true}, + {levelVar(LevelDebug), true}, + } { + h := &commonHandler{opts: HandlerOptions{Level: test.leveler}} + got := h.enabled(LevelInfo) + if got != test.want { + t.Errorf("%v: got %t, want %t", test.leveler, got, test.want) + } + } +} + +func TestSecondWith(t *testing.T) { + // Verify that a second call to Logger.With does not corrupt + // the original. + var buf bytes.Buffer + h := NewTextHandler(&buf, &HandlerOptions{ReplaceAttr: removeKeys(TimeKey)}) + logger := New(h).With( + String("app", "playground"), + String("role", "tester"), + Int("data_version", 2), + ) + appLogger := logger.With("type", "log") // this becomes type=met + _ = logger.With("type", "metric") + appLogger.Info("foo") + got := strings.TrimSpace(buf.String()) + want := `level=INFO msg=foo app=playground role=tester data_version=2 type=log` + if got != want { + t.Errorf("\ngot %s\nwant %s", got, want) + } +} + +func TestReplaceAttrGroups(t *testing.T) { + // Verify that ReplaceAttr is called with the correct groups. + type ga struct { + groups string + key string + val string + } + + var got []ga + + h := NewTextHandler(io.Discard, &HandlerOptions{ReplaceAttr: func(gs []string, a Attr) Attr { + v := a.Value.String() + if a.Key == TimeKey { + v = "<now>" + } + got = append(got, ga{strings.Join(gs, ","), a.Key, v}) + return a + }}) + New(h). + With(Int("a", 1)). + WithGroup("g1"). + With(Int("b", 2)). + WithGroup("g2"). + With( + Int("c", 3), + Group("g3", Int("d", 4)), + Int("e", 5)). + Info("m", + Int("f", 6), + Group("g4", Int("h", 7)), + Int("i", 8)) + + want := []ga{ + {"", "a", "1"}, + {"g1", "b", "2"}, + {"g1,g2", "c", "3"}, + {"g1,g2,g3", "d", "4"}, + {"g1,g2", "e", "5"}, + {"", "time", "<now>"}, + {"", "level", "INFO"}, + {"", "msg", "m"}, + {"g1,g2", "f", "6"}, + {"g1,g2,g4", "h", "7"}, + {"g1,g2", "i", "8"}, + } + if !slices.Equal(got, want) { + t.Errorf("\ngot %v\nwant %v", got, want) + } +} + +const rfc3339Millis = "2006-01-02T15:04:05.000Z07:00" + +func TestWriteTimeRFC3339(t *testing.T) { + for _, tm := range []time.Time{ + time.Date(2000, 1, 2, 3, 4, 5, 0, time.UTC), + time.Date(2000, 1, 2, 3, 4, 5, 400, time.Local), + time.Date(2000, 11, 12, 3, 4, 500, 5e7, time.UTC), + } { + want := tm.Format(rfc3339Millis) + buf := buffer.New() + defer buf.Free() + writeTimeRFC3339Millis(buf, tm) + got := buf.String() + if got != want { + t.Errorf("got %s, want %s", got, want) + } + } +} + +func BenchmarkWriteTime(b *testing.B) { + buf := buffer.New() + defer buf.Free() + tm := time.Date(2022, 3, 4, 5, 6, 7, 823456789, time.Local) + b.ResetTimer() + for i := 0; i < b.N; i++ { + writeTimeRFC3339Millis(buf, tm) + buf.Reset() + } +} diff --git a/src/log/slog/internal/benchmarks/benchmarks.go b/src/log/slog/internal/benchmarks/benchmarks.go new file mode 100644 index 0000000..3a28523 --- /dev/null +++ b/src/log/slog/internal/benchmarks/benchmarks.go @@ -0,0 +1,50 @@ +// Copyright 2023 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package benchmarks contains benchmarks for slog. +// +// These benchmarks are loosely based on github.com/uber-go/zap/benchmarks. +// They have the following desirable properties: +// +// - They test a complete log event, from the user's call to its return. +// +// - The benchmarked code is run concurrently in multiple goroutines, to +// better simulate a real server (the most common environment for structured +// logs). +// +// - Some handlers are optimistic versions of real handlers, doing real-world +// tasks as fast as possible (and sometimes faster, in that an +// implementation may not be concurrency-safe). This gives us an upper bound +// on handler performance, so we can evaluate the (handler-independent) core +// activity of the package in an end-to-end context without concern that a +// slow handler implementation is skewing the results. +// +// - We also test the built-in handlers, for comparison. +package benchmarks + +import ( + "errors" + "log/slog" + "time" +) + +const testMessage = "Test logging, but use a somewhat realistic message length." + +var ( + testTime = time.Date(2022, time.May, 1, 0, 0, 0, 0, time.UTC) + testString = "7e3b3b2aaeff56a7108fe11e154200dd/7819479873059528190" + testInt = 32768 + testDuration = 23 * time.Second + testError = errors.New("fail") +) + +var testAttrs = []slog.Attr{ + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), +} + +const wantText = "time=1651363200 level=0 msg=Test logging, but use a somewhat realistic message length. string=7e3b3b2aaeff56a7108fe11e154200dd/7819479873059528190 status=32768 duration=23000000000 time=1651363200 error=fail\n" diff --git a/src/log/slog/internal/benchmarks/benchmarks_test.go b/src/log/slog/internal/benchmarks/benchmarks_test.go new file mode 100644 index 0000000..18643b7 --- /dev/null +++ b/src/log/slog/internal/benchmarks/benchmarks_test.go @@ -0,0 +1,152 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package benchmarks + +import ( + "context" + "flag" + "internal/race" + "io" + "log/slog" + "log/slog/internal" + "testing" +) + +func init() { + flag.BoolVar(&internal.IgnorePC, "nopc", false, "do not invoke runtime.Callers") +} + +// We pass Attrs inline because it affects allocations: building +// up a list outside of the benchmarked code and passing it in with "..." +// reduces measured allocations. + +func BenchmarkAttrs(b *testing.B) { + ctx := context.Background() + for _, handler := range []struct { + name string + h slog.Handler + skipRace bool + }{ + {"disabled", disabledHandler{}, false}, + {"async discard", newAsyncHandler(), true}, + {"fastText discard", newFastTextHandler(io.Discard), false}, + {"Text discard", slog.NewTextHandler(io.Discard, nil), false}, + {"JSON discard", slog.NewJSONHandler(io.Discard, nil), false}, + } { + logger := slog.New(handler.h) + b.Run(handler.name, func(b *testing.B) { + if handler.skipRace && race.Enabled { + b.Skip("skipping benchmark in race mode") + } + for _, call := range []struct { + name string + f func() + }{ + { + // The number should match nAttrsInline in slog/record.go. + // This should exercise the code path where no allocations + // happen in Record or Attr. If there are allocations, they + // should only be from Duration.String and Time.String. + "5 args", + func() { + logger.LogAttrs(nil, slog.LevelInfo, testMessage, + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + ) + }, + }, + { + "5 args ctx", + func() { + logger.LogAttrs(ctx, slog.LevelInfo, testMessage, + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + ) + }, + }, + { + "10 args", + func() { + logger.LogAttrs(nil, slog.LevelInfo, testMessage, + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + ) + }, + }, + { + // Try an extreme value to see if the results are reasonable. + "40 args", + func() { + logger.LogAttrs(nil, slog.LevelInfo, testMessage, + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", testError), + ) + }, + }, + } { + b.Run(call.name, func(b *testing.B) { + b.ReportAllocs() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + call.f() + } + }) + }) + } + }) + } +} diff --git a/src/log/slog/internal/benchmarks/handlers.go b/src/log/slog/internal/benchmarks/handlers.go new file mode 100644 index 0000000..091e2dd --- /dev/null +++ b/src/log/slog/internal/benchmarks/handlers.go @@ -0,0 +1,148 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package benchmarks + +// Handlers for benchmarking. + +import ( + "context" + "fmt" + "io" + "log/slog" + "log/slog/internal/buffer" + "strconv" + "time" +) + +// A fastTextHandler writes a Record to an io.Writer in a format similar to +// slog.TextHandler, but without quoting or locking. It has a few other +// performance-motivated shortcuts, like writing times as seconds since the +// epoch instead of strings. +// +// It is intended to represent a high-performance Handler that synchronously +// writes text (as opposed to binary). +type fastTextHandler struct { + w io.Writer +} + +func newFastTextHandler(w io.Writer) slog.Handler { + return &fastTextHandler{w: w} +} + +func (h *fastTextHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (h *fastTextHandler) Handle(_ context.Context, r slog.Record) error { + buf := buffer.New() + defer buf.Free() + + if !r.Time.IsZero() { + buf.WriteString("time=") + h.appendTime(buf, r.Time) + buf.WriteByte(' ') + } + buf.WriteString("level=") + *buf = strconv.AppendInt(*buf, int64(r.Level), 10) + buf.WriteByte(' ') + buf.WriteString("msg=") + buf.WriteString(r.Message) + r.Attrs(func(a slog.Attr) bool { + buf.WriteByte(' ') + buf.WriteString(a.Key) + buf.WriteByte('=') + h.appendValue(buf, a.Value) + return true + }) + buf.WriteByte('\n') + _, err := h.w.Write(*buf) + return err +} + +func (h *fastTextHandler) appendValue(buf *buffer.Buffer, v slog.Value) { + switch v.Kind() { + case slog.KindString: + buf.WriteString(v.String()) + case slog.KindInt64: + *buf = strconv.AppendInt(*buf, v.Int64(), 10) + case slog.KindUint64: + *buf = strconv.AppendUint(*buf, v.Uint64(), 10) + case slog.KindFloat64: + *buf = strconv.AppendFloat(*buf, v.Float64(), 'g', -1, 64) + case slog.KindBool: + *buf = strconv.AppendBool(*buf, v.Bool()) + case slog.KindDuration: + *buf = strconv.AppendInt(*buf, v.Duration().Nanoseconds(), 10) + case slog.KindTime: + h.appendTime(buf, v.Time()) + case slog.KindAny: + a := v.Any() + switch a := a.(type) { + case error: + buf.WriteString(a.Error()) + default: + fmt.Fprint(buf, a) + } + default: + panic(fmt.Sprintf("bad kind: %s", v.Kind())) + } +} + +func (h *fastTextHandler) appendTime(buf *buffer.Buffer, t time.Time) { + *buf = strconv.AppendInt(*buf, t.Unix(), 10) +} + +func (h *fastTextHandler) WithAttrs([]slog.Attr) slog.Handler { + panic("fastTextHandler: With unimplemented") +} + +func (*fastTextHandler) WithGroup(string) slog.Handler { + panic("fastTextHandler: WithGroup unimplemented") +} + +// An asyncHandler simulates a Handler that passes Records to a +// background goroutine for processing. +// Because sending to a channel can be expensive due to locking, +// we simulate a lock-free queue by adding the Record to a ring buffer. +// Omitting the locking makes this little more than a copy of the Record, +// but that is a worthwhile thing to measure because Records are on the large +// side. Since nothing actually reads from the ring buffer, it can handle an +// arbitrary number of Records without either blocking or allocation. +type asyncHandler struct { + ringBuffer [100]slog.Record + next int +} + +func newAsyncHandler() *asyncHandler { + return &asyncHandler{} +} + +func (*asyncHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (h *asyncHandler) Handle(_ context.Context, r slog.Record) error { + h.ringBuffer[h.next] = r.Clone() + h.next = (h.next + 1) % len(h.ringBuffer) + return nil +} + +func (*asyncHandler) WithAttrs([]slog.Attr) slog.Handler { + panic("asyncHandler: With unimplemented") +} + +func (*asyncHandler) WithGroup(string) slog.Handler { + panic("asyncHandler: WithGroup unimplemented") +} + +// A disabledHandler's Enabled method always returns false. +type disabledHandler struct{} + +func (disabledHandler) Enabled(context.Context, slog.Level) bool { return false } +func (disabledHandler) Handle(context.Context, slog.Record) error { panic("should not be called") } + +func (disabledHandler) WithAttrs([]slog.Attr) slog.Handler { + panic("disabledHandler: With unimplemented") +} + +func (disabledHandler) WithGroup(string) slog.Handler { + panic("disabledHandler: WithGroup unimplemented") +} diff --git a/src/log/slog/internal/benchmarks/handlers_test.go b/src/log/slog/internal/benchmarks/handlers_test.go new file mode 100644 index 0000000..6c00c80 --- /dev/null +++ b/src/log/slog/internal/benchmarks/handlers_test.go @@ -0,0 +1,42 @@ +package benchmarks + +import ( + "bytes" + "context" + "log/slog" + "slices" + "testing" +) + +func TestHandlers(t *testing.T) { + ctx := context.Background() + r := slog.NewRecord(testTime, slog.LevelInfo, testMessage, 0) + r.AddAttrs(testAttrs...) + t.Run("text", func(t *testing.T) { + var b bytes.Buffer + h := newFastTextHandler(&b) + if err := h.Handle(ctx, r); err != nil { + t.Fatal(err) + } + got := b.String() + if got != wantText { + t.Errorf("\ngot %q\nwant %q", got, wantText) + } + }) + t.Run("async", func(t *testing.T) { + h := newAsyncHandler() + if err := h.Handle(ctx, r); err != nil { + t.Fatal(err) + } + got := h.ringBuffer[0] + if !got.Time.Equal(r.Time) || !slices.EqualFunc(attrSlice(got), attrSlice(r), slog.Attr.Equal) { + t.Errorf("got %+v, want %+v", got, r) + } + }) +} + +func attrSlice(r slog.Record) []slog.Attr { + var as []slog.Attr + r.Attrs(func(a slog.Attr) bool { as = append(as, a); return true }) + return as +} diff --git a/src/log/slog/internal/buffer/buffer.go b/src/log/slog/internal/buffer/buffer.go new file mode 100644 index 0000000..c4fcefd --- /dev/null +++ b/src/log/slog/internal/buffer/buffer.go @@ -0,0 +1,84 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package buffer provides a pool-allocated byte buffer. +package buffer + +import "sync" + +// buffer adapted from go/src/fmt/print.go +type Buffer []byte + +// Having an initial size gives a dramatic speedup. +var bufPool = sync.Pool{ + New: func() any { + b := make([]byte, 0, 1024) + return (*Buffer)(&b) + }, +} + +func New() *Buffer { + return bufPool.Get().(*Buffer) +} + +func (b *Buffer) Free() { + // To reduce peak allocation, return only smaller buffers to the pool. + const maxBufferSize = 16 << 10 + if cap(*b) <= maxBufferSize { + *b = (*b)[:0] + bufPool.Put(b) + } +} + +func (b *Buffer) Reset() { + *b = (*b)[:0] +} + +func (b *Buffer) Write(p []byte) (int, error) { + *b = append(*b, p...) + return len(p), nil +} + +func (b *Buffer) WriteString(s string) (int, error) { + *b = append(*b, s...) + return len(s), nil +} + +func (b *Buffer) WriteByte(c byte) error { + *b = append(*b, c) + return nil +} + +func (b *Buffer) WritePosInt(i int) { + b.WritePosIntWidth(i, 0) +} + +// WritePosIntWidth writes non-negative integer i to the buffer, padded on the left +// by zeroes to the given width. Use a width of 0 to omit padding. +func (b *Buffer) WritePosIntWidth(i, width int) { + // Cheap integer to fixed-width decimal ASCII. + // Copied from log/log.go. + + if i < 0 { + panic("negative int") + } + + // Assemble decimal in reverse order. + var bb [20]byte + bp := len(bb) - 1 + for i >= 10 || width > 1 { + width-- + q := i / 10 + bb[bp] = byte('0' + i - q*10) + bp-- + i = q + } + // i < 10 + bb[bp] = byte('0' + i) + b.Write(bb[bp:]) +} + +func (b *Buffer) String() string { + return string(*b) +} diff --git a/src/log/slog/internal/buffer/buffer_test.go b/src/log/slog/internal/buffer/buffer_test.go new file mode 100644 index 0000000..40b1d1f --- /dev/null +++ b/src/log/slog/internal/buffer/buffer_test.go @@ -0,0 +1,41 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package buffer + +import ( + "internal/race" + "internal/testenv" + "testing" +) + +func Test(t *testing.T) { + b := New() + defer b.Free() + b.WriteString("hello") + b.WriteByte(',') + b.Write([]byte(" world")) + b.WritePosIntWidth(17, 4) + + got := b.String() + want := "hello, world0017" + if got != want { + t.Errorf("got %q, want %q", got, want) + } +} + +func TestAlloc(t *testing.T) { + if race.Enabled { + t.Skip("skipping test in race mode") + } + testenv.SkipIfOptimizationOff(t) + got := int(testing.AllocsPerRun(5, func() { + b := New() + defer b.Free() + b.WriteString("not 1K worth of bytes") + })) + if got != 0 { + t.Errorf("got %d allocs, want 0", got) + } +} diff --git a/src/log/slog/internal/ignorepc.go b/src/log/slog/internal/ignorepc.go new file mode 100644 index 0000000..d125642 --- /dev/null +++ b/src/log/slog/internal/ignorepc.go @@ -0,0 +1,9 @@ +// Copyright 2023 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package internal + +// If IgnorePC is true, do not invoke runtime.Callers to get the pc. +// This is solely for benchmarking the slowdown from runtime.Callers. +var IgnorePC = false diff --git a/src/log/slog/internal/slogtest/slogtest.go b/src/log/slog/internal/slogtest/slogtest.go new file mode 100644 index 0000000..d587662 --- /dev/null +++ b/src/log/slog/internal/slogtest/slogtest.go @@ -0,0 +1,18 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package slogtest contains support functions for testing slog. +package slogtest + +import "log/slog" + +// RemoveTime removes the top-level time attribute. +// It is intended to be used as a ReplaceAttr function, +// to make example output deterministic. +func RemoveTime(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey && len(groups) == 0 { + return slog.Attr{} + } + return a +} diff --git a/src/log/slog/json_handler.go b/src/log/slog/json_handler.go new file mode 100644 index 0000000..1c51ab0 --- /dev/null +++ b/src/log/slog/json_handler.go @@ -0,0 +1,336 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "fmt" + "io" + "log/slog/internal/buffer" + "strconv" + "sync" + "time" + "unicode/utf8" +) + +// JSONHandler is a Handler that writes Records to an io.Writer as +// line-delimited JSON objects. +type JSONHandler struct { + *commonHandler +} + +// NewJSONHandler creates a JSONHandler that writes to w, +// using the given options. +// If opts is nil, the default options are used. +func NewJSONHandler(w io.Writer, opts *HandlerOptions) *JSONHandler { + if opts == nil { + opts = &HandlerOptions{} + } + return &JSONHandler{ + &commonHandler{ + json: true, + w: w, + opts: *opts, + mu: &sync.Mutex{}, + }, + } +} + +// Enabled reports whether the handler handles records at the given level. +// The handler ignores records whose level is lower. +func (h *JSONHandler) Enabled(_ context.Context, level Level) bool { + return h.commonHandler.enabled(level) +} + +// WithAttrs returns a new JSONHandler whose attributes consists +// of h's attributes followed by attrs. +func (h *JSONHandler) WithAttrs(attrs []Attr) Handler { + return &JSONHandler{commonHandler: h.commonHandler.withAttrs(attrs)} +} + +func (h *JSONHandler) WithGroup(name string) Handler { + return &JSONHandler{commonHandler: h.commonHandler.withGroup(name)} +} + +// Handle formats its argument Record as a JSON object on a single line. +// +// If the Record's time is zero, the time is omitted. +// Otherwise, the key is "time" +// and the value is output as with json.Marshal. +// +// If the Record's level is zero, the level is omitted. +// Otherwise, the key is "level" +// and the value of [Level.String] is output. +// +// If the AddSource option is set and source information is available, +// the key is "source", and the value is a record of type [Source]. +// +// The message's key is "msg". +// +// To modify these or other attributes, or remove them from the output, use +// [HandlerOptions.ReplaceAttr]. +// +// Values are formatted as with an [encoding/json.Encoder] with SetEscapeHTML(false), +// with two exceptions. +// +// First, an Attr whose Value is of type error is formatted as a string, by +// calling its Error method. Only errors in Attrs receive this special treatment, +// not errors embedded in structs, slices, maps or other data structures that +// are processed by the encoding/json package. +// +// Second, an encoding failure does not cause Handle to return an error. +// Instead, the error message is formatted as a string. +// +// Each call to Handle results in a single serialized call to io.Writer.Write. +func (h *JSONHandler) Handle(_ context.Context, r Record) error { + return h.commonHandler.handle(r) +} + +// Adapted from time.Time.MarshalJSON to avoid allocation. +func appendJSONTime(s *handleState, t time.Time) { + if y := t.Year(); y < 0 || y >= 10000 { + // RFC 3339 is clear that years are 4 digits exactly. + // See golang.org/issue/4556#c15 for more discussion. + s.appendError(errors.New("time.Time year outside of range [0,9999]")) + } + s.buf.WriteByte('"') + *s.buf = t.AppendFormat(*s.buf, time.RFC3339Nano) + s.buf.WriteByte('"') +} + +func appendJSONValue(s *handleState, v Value) error { + switch v.Kind() { + case KindString: + s.appendString(v.str()) + case KindInt64: + *s.buf = strconv.AppendInt(*s.buf, v.Int64(), 10) + case KindUint64: + *s.buf = strconv.AppendUint(*s.buf, v.Uint64(), 10) + case KindFloat64: + // json.Marshal is funny about floats; it doesn't + // always match strconv.AppendFloat. So just call it. + // That's expensive, but floats are rare. + if err := appendJSONMarshal(s.buf, v.Float64()); err != nil { + return err + } + case KindBool: + *s.buf = strconv.AppendBool(*s.buf, v.Bool()) + case KindDuration: + // Do what json.Marshal does. + *s.buf = strconv.AppendInt(*s.buf, int64(v.Duration()), 10) + case KindTime: + s.appendTime(v.Time()) + case KindAny: + a := v.Any() + _, jm := a.(json.Marshaler) + if err, ok := a.(error); ok && !jm { + s.appendString(err.Error()) + } else { + return appendJSONMarshal(s.buf, a) + } + default: + panic(fmt.Sprintf("bad kind: %s", v.Kind())) + } + return nil +} + +func appendJSONMarshal(buf *buffer.Buffer, v any) error { + // Use a json.Encoder to avoid escaping HTML. + var bb bytes.Buffer + enc := json.NewEncoder(&bb) + enc.SetEscapeHTML(false) + if err := enc.Encode(v); err != nil { + return err + } + bs := bb.Bytes() + buf.Write(bs[:len(bs)-1]) // remove final newline + return nil +} + +// appendEscapedJSONString escapes s for JSON and appends it to buf. +// It does not surround the string in quotation marks. +// +// Modified from encoding/json/encode.go:encodeState.string, +// with escapeHTML set to false. +func appendEscapedJSONString(buf []byte, s string) []byte { + char := func(b byte) { buf = append(buf, b) } + str := func(s string) { buf = append(buf, s...) } + + start := 0 + for i := 0; i < len(s); { + if b := s[i]; b < utf8.RuneSelf { + if safeSet[b] { + i++ + continue + } + if start < i { + str(s[start:i]) + } + char('\\') + switch b { + case '\\', '"': + char(b) + case '\n': + char('n') + case '\r': + char('r') + case '\t': + char('t') + default: + // This encodes bytes < 0x20 except for \t, \n and \r. + str(`u00`) + char(hex[b>>4]) + char(hex[b&0xF]) + } + i++ + start = i + continue + } + c, size := utf8.DecodeRuneInString(s[i:]) + if c == utf8.RuneError && size == 1 { + if start < i { + str(s[start:i]) + } + str(`\ufffd`) + i += size + start = i + continue + } + // U+2028 is LINE SEPARATOR. + // U+2029 is PARAGRAPH SEPARATOR. + // They are both technically valid characters in JSON strings, + // but don't work in JSONP, which has to be evaluated as JavaScript, + // and can lead to security holes there. It is valid JSON to + // escape them, so we do so unconditionally. + // See http://timelessrepo.com/json-isnt-a-javascript-subset for discussion. + if c == '\u2028' || c == '\u2029' { + if start < i { + str(s[start:i]) + } + str(`\u202`) + char(hex[c&0xF]) + i += size + start = i + continue + } + i += size + } + if start < len(s) { + str(s[start:]) + } + return buf +} + +var hex = "0123456789abcdef" + +// Copied from encoding/json/tables.go. +// +// safeSet holds the value true if the ASCII character with the given array +// position can be represented inside a JSON string without any further +// escaping. +// +// All values are true except for the ASCII control characters (0-31), the +// double quote ("), and the backslash character ("\"). +var safeSet = [utf8.RuneSelf]bool{ + ' ': true, + '!': true, + '"': false, + '#': true, + '$': true, + '%': true, + '&': true, + '\'': true, + '(': true, + ')': true, + '*': true, + '+': true, + ',': true, + '-': true, + '.': true, + '/': true, + '0': true, + '1': true, + '2': true, + '3': true, + '4': true, + '5': true, + '6': true, + '7': true, + '8': true, + '9': true, + ':': true, + ';': true, + '<': true, + '=': true, + '>': true, + '?': true, + '@': true, + 'A': true, + 'B': true, + 'C': true, + 'D': true, + 'E': true, + 'F': true, + 'G': true, + 'H': true, + 'I': true, + 'J': true, + 'K': true, + 'L': true, + 'M': true, + 'N': true, + 'O': true, + 'P': true, + 'Q': true, + 'R': true, + 'S': true, + 'T': true, + 'U': true, + 'V': true, + 'W': true, + 'X': true, + 'Y': true, + 'Z': true, + '[': true, + '\\': false, + ']': true, + '^': true, + '_': true, + '`': true, + 'a': true, + 'b': true, + 'c': true, + 'd': true, + 'e': true, + 'f': true, + 'g': true, + 'h': true, + 'i': true, + 'j': true, + 'k': true, + 'l': true, + 'm': true, + 'n': true, + 'o': true, + 'p': true, + 'q': true, + 'r': true, + 's': true, + 't': true, + 'u': true, + 'v': true, + 'w': true, + 'x': true, + 'y': true, + 'z': true, + '{': true, + '|': true, + '}': true, + '~': true, + '\u007f': true, +} diff --git a/src/log/slog/json_handler_test.go b/src/log/slog/json_handler_test.go new file mode 100644 index 0000000..65130f2 --- /dev/null +++ b/src/log/slog/json_handler_test.go @@ -0,0 +1,284 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "fmt" + "io" + "log/slog/internal/buffer" + "math" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +func TestJSONHandler(t *testing.T) { + for _, test := range []struct { + name string + opts HandlerOptions + want string + }{ + { + "none", + HandlerOptions{}, + `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"m","a":1,"m":{"b":2}}`, + }, + { + "replace", + HandlerOptions{ReplaceAttr: upperCaseKey}, + `{"TIME":"2000-01-02T03:04:05Z","LEVEL":"INFO","MSG":"m","A":1,"M":{"b":2}}`, + }, + } { + t.Run(test.name, func(t *testing.T) { + var buf bytes.Buffer + h := NewJSONHandler(&buf, &test.opts) + r := NewRecord(testTime, LevelInfo, "m", 0) + r.AddAttrs(Int("a", 1), Any("m", map[string]int{"b": 2})) + if err := h.Handle(context.Background(), r); err != nil { + t.Fatal(err) + } + got := strings.TrimSuffix(buf.String(), "\n") + if got != test.want { + t.Errorf("\ngot %s\nwant %s", got, test.want) + } + }) + } +} + +// for testing json.Marshaler +type jsonMarshaler struct { + s string +} + +func (j jsonMarshaler) String() string { return j.s } // should be ignored + +func (j jsonMarshaler) MarshalJSON() ([]byte, error) { + if j.s == "" { + return nil, errors.New("json: empty string") + } + return []byte(fmt.Sprintf(`[%q]`, j.s)), nil +} + +type jsonMarshalerError struct { + jsonMarshaler +} + +func (jsonMarshalerError) Error() string { return "oops" } + +func TestAppendJSONValue(t *testing.T) { + // jsonAppendAttrValue should always agree with json.Marshal. + for _, value := range []any{ + "hello\r\n\t\a", + `"[{escape}]"`, + "<escapeHTML&>", + // \u2028\u2029 is an edge case in JavaScript vs JSON. + // \xF6 is an incomplete encoding. + "\u03B8\u2028\u2029\uFFFF\xF6", + `-123`, + int64(-9_200_123_456_789_123_456), + uint64(9_200_123_456_789_123_456), + -12.75, + 1.23e-9, + false, + time.Minute, + testTime, + jsonMarshaler{"xyz"}, + jsonMarshalerError{jsonMarshaler{"pqr"}}, + LevelWarn, + } { + got := jsonValueString(AnyValue(value)) + want, err := marshalJSON(value) + if err != nil { + t.Fatal(err) + } + if got != want { + t.Errorf("%v: got %s, want %s", value, got, want) + } + } +} + +func marshalJSON(x any) (string, error) { + var buf bytes.Buffer + enc := json.NewEncoder(&buf) + enc.SetEscapeHTML(false) + if err := enc.Encode(x); err != nil { + return "", err + } + return strings.TrimSpace(buf.String()), nil +} + +func TestJSONAppendAttrValueSpecial(t *testing.T) { + // Attr values that render differently from json.Marshal. + for _, test := range []struct { + value any + want string + }{ + {math.NaN(), `"!ERROR:json: unsupported value: NaN"`}, + {math.Inf(+1), `"!ERROR:json: unsupported value: +Inf"`}, + {math.Inf(-1), `"!ERROR:json: unsupported value: -Inf"`}, + {io.EOF, `"EOF"`}, + } { + got := jsonValueString(AnyValue(test.value)) + if got != test.want { + t.Errorf("%v: got %s, want %s", test.value, got, test.want) + } + } +} + +func jsonValueString(v Value) string { + var buf []byte + s := &handleState{h: &commonHandler{json: true}, buf: (*buffer.Buffer)(&buf)} + if err := appendJSONValue(s, v); err != nil { + s.appendError(err) + } + return string(buf) +} + +func BenchmarkJSONHandler(b *testing.B) { + for _, bench := range []struct { + name string + opts HandlerOptions + }{ + {"defaults", HandlerOptions{}}, + {"time format", HandlerOptions{ + ReplaceAttr: func(_ []string, a Attr) Attr { + v := a.Value + if v.Kind() == KindTime { + return String(a.Key, v.Time().Format(rfc3339Millis)) + } + if a.Key == "level" { + return Attr{"severity", a.Value} + } + return a + }, + }}, + {"time unix", HandlerOptions{ + ReplaceAttr: func(_ []string, a Attr) Attr { + v := a.Value + if v.Kind() == KindTime { + return Int64(a.Key, v.Time().UnixNano()) + } + if a.Key == "level" { + return Attr{"severity", a.Value} + } + return a + }, + }}, + } { + b.Run(bench.name, func(b *testing.B) { + ctx := context.Background() + l := New(NewJSONHandler(io.Discard, &bench.opts)).With( + String("program", "my-test-program"), + String("package", "log/slog"), + String("traceID", "2039232309232309"), + String("URL", "https://pkg.go.dev/golang.org/x/log/slog")) + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + l.LogAttrs(ctx, LevelInfo, "this is a typical log message", + String("module", "github.com/google/go-cmp"), + String("version", "v1.23.4"), + Int("count", 23), + Int("number", 123456), + ) + } + }) + } +} + +func BenchmarkPreformatting(b *testing.B) { + type req struct { + Method string + URL string + TraceID string + Addr string + } + + structAttrs := []any{ + String("program", "my-test-program"), + String("package", "log/slog"), + Any("request", &req{ + Method: "GET", + URL: "https://pkg.go.dev/golang.org/x/log/slog", + TraceID: "2039232309232309", + Addr: "127.0.0.1:8080", + }), + } + + outFile, err := os.Create(filepath.Join(b.TempDir(), "bench.log")) + if err != nil { + b.Fatal(err) + } + defer func() { + if err := outFile.Close(); err != nil { + b.Fatal(err) + } + }() + + for _, bench := range []struct { + name string + wc io.Writer + attrs []any + }{ + {"separate", io.Discard, []any{ + String("program", "my-test-program"), + String("package", "log/slog"), + String("method", "GET"), + String("URL", "https://pkg.go.dev/golang.org/x/log/slog"), + String("traceID", "2039232309232309"), + String("addr", "127.0.0.1:8080"), + }}, + {"struct", io.Discard, structAttrs}, + {"struct file", outFile, structAttrs}, + } { + ctx := context.Background() + b.Run(bench.name, func(b *testing.B) { + l := New(NewJSONHandler(bench.wc, nil)).With(bench.attrs...) + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + l.LogAttrs(ctx, LevelInfo, "this is a typical log message", + String("module", "github.com/google/go-cmp"), + String("version", "v1.23.4"), + Int("count", 23), + Int("number", 123456), + ) + } + }) + } +} + +func BenchmarkJSONEncoding(b *testing.B) { + value := 3.14 + buf := buffer.New() + defer buf.Free() + b.Run("json.Marshal", func(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + by, err := json.Marshal(value) + if err != nil { + b.Fatal(err) + } + buf.Write(by) + *buf = (*buf)[:0] + } + }) + b.Run("Encoder.Encode", func(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + if err := json.NewEncoder(buf).Encode(value); err != nil { + b.Fatal(err) + } + *buf = (*buf)[:0] + } + }) + _ = buf +} diff --git a/src/log/slog/level.go b/src/log/slog/level.go new file mode 100644 index 0000000..cd1213a --- /dev/null +++ b/src/log/slog/level.go @@ -0,0 +1,200 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "errors" + "fmt" + "strconv" + "strings" + "sync/atomic" +) + +// A Level is the importance or severity of a log event. +// The higher the level, the more important or severe the event. +type Level int + +// Level numbers are inherently arbitrary, +// but we picked them to satisfy three constraints. +// Any system can map them to another numbering scheme if it wishes. +// +// First, we wanted the default level to be Info, Since Levels are ints, Info is +// the default value for int, zero. +// +// Second, we wanted to make it easy to use levels to specify logger verbosity. +// Since a larger level means a more severe event, a logger that accepts events +// with smaller (or more negative) level means a more verbose logger. Logger +// verbosity is thus the negation of event severity, and the default verbosity +// of 0 accepts all events at least as severe as INFO. +// +// Third, we wanted some room between levels to accommodate schemes with named +// levels between ours. For example, Google Cloud Logging defines a Notice level +// between Info and Warn. Since there are only a few of these intermediate +// levels, the gap between the numbers need not be large. Our gap of 4 matches +// OpenTelemetry's mapping. Subtracting 9 from an OpenTelemetry level in the +// DEBUG, INFO, WARN and ERROR ranges converts it to the corresponding slog +// Level range. OpenTelemetry also has the names TRACE and FATAL, which slog +// does not. But those OpenTelemetry levels can still be represented as slog +// Levels by using the appropriate integers. +// +// Names for common levels. +const ( + LevelDebug Level = -4 + LevelInfo Level = 0 + LevelWarn Level = 4 + LevelError Level = 8 +) + +// String returns a name for the level. +// If the level has a name, then that name +// in uppercase is returned. +// If the level is between named values, then +// an integer is appended to the uppercased name. +// Examples: +// +// LevelWarn.String() => "WARN" +// (LevelInfo+2).String() => "INFO+2" +func (l Level) String() string { + str := func(base string, val Level) string { + if val == 0 { + return base + } + return fmt.Sprintf("%s%+d", base, val) + } + + switch { + case l < LevelInfo: + return str("DEBUG", l-LevelDebug) + case l < LevelWarn: + return str("INFO", l-LevelInfo) + case l < LevelError: + return str("WARN", l-LevelWarn) + default: + return str("ERROR", l-LevelError) + } +} + +// MarshalJSON implements [encoding/json.Marshaler] +// by quoting the output of [Level.String]. +func (l Level) MarshalJSON() ([]byte, error) { + // AppendQuote is sufficient for JSON-encoding all Level strings. + // They don't contain any runes that would produce invalid JSON + // when escaped. + return strconv.AppendQuote(nil, l.String()), nil +} + +// UnmarshalJSON implements [encoding/json.Unmarshaler] +// It accepts any string produced by [Level.MarshalJSON], +// ignoring case. +// It also accepts numeric offsets that would result in a different string on +// output. For example, "Error-8" would marshal as "INFO". +func (l *Level) UnmarshalJSON(data []byte) error { + s, err := strconv.Unquote(string(data)) + if err != nil { + return err + } + return l.parse(s) +} + +// MarshalText implements [encoding.TextMarshaler] +// by calling [Level.String]. +func (l Level) MarshalText() ([]byte, error) { + return []byte(l.String()), nil +} + +// UnmarshalText implements [encoding.TextUnmarshaler]. +// It accepts any string produced by [Level.MarshalText], +// ignoring case. +// It also accepts numeric offsets that would result in a different string on +// output. For example, "Error-8" would marshal as "INFO". +func (l *Level) UnmarshalText(data []byte) error { + return l.parse(string(data)) +} + +func (l *Level) parse(s string) (err error) { + defer func() { + if err != nil { + err = fmt.Errorf("slog: level string %q: %w", s, err) + } + }() + + name := s + offset := 0 + if i := strings.IndexAny(s, "+-"); i >= 0 { + name = s[:i] + offset, err = strconv.Atoi(s[i:]) + if err != nil { + return err + } + } + switch strings.ToUpper(name) { + case "DEBUG": + *l = LevelDebug + case "INFO": + *l = LevelInfo + case "WARN": + *l = LevelWarn + case "ERROR": + *l = LevelError + default: + return errors.New("unknown name") + } + *l += Level(offset) + return nil +} + +// Level returns the receiver. +// It implements Leveler. +func (l Level) Level() Level { return l } + +// A LevelVar is a Level variable, to allow a Handler level to change +// dynamically. +// It implements Leveler as well as a Set method, +// and it is safe for use by multiple goroutines. +// The zero LevelVar corresponds to LevelInfo. +type LevelVar struct { + val atomic.Int64 +} + +// Level returns v's level. +func (v *LevelVar) Level() Level { + return Level(int(v.val.Load())) +} + +// Set sets v's level to l. +func (v *LevelVar) Set(l Level) { + v.val.Store(int64(l)) +} + +func (v *LevelVar) String() string { + return fmt.Sprintf("LevelVar(%s)", v.Level()) +} + +// MarshalText implements [encoding.TextMarshaler] +// by calling [Level.MarshalText]. +func (v *LevelVar) MarshalText() ([]byte, error) { + return v.Level().MarshalText() +} + +// UnmarshalText implements [encoding.TextUnmarshaler] +// by calling [Level.UnmarshalText]. +func (v *LevelVar) UnmarshalText(data []byte) error { + var l Level + if err := l.UnmarshalText(data); err != nil { + return err + } + v.Set(l) + return nil +} + +// A Leveler provides a Level value. +// +// As Level itself implements Leveler, clients typically supply +// a Level value wherever a Leveler is needed, such as in HandlerOptions. +// Clients who need to vary the level dynamically can provide a more complex +// Leveler implementation such as *LevelVar. +type Leveler interface { + Level() Level +} diff --git a/src/log/slog/level_test.go b/src/log/slog/level_test.go new file mode 100644 index 0000000..0b28e71 --- /dev/null +++ b/src/log/slog/level_test.go @@ -0,0 +1,178 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "flag" + "strings" + "testing" +) + +func TestLevelString(t *testing.T) { + for _, test := range []struct { + in Level + want string + }{ + {0, "INFO"}, + {LevelError, "ERROR"}, + {LevelError + 2, "ERROR+2"}, + {LevelError - 2, "WARN+2"}, + {LevelWarn, "WARN"}, + {LevelWarn - 1, "INFO+3"}, + {LevelInfo, "INFO"}, + {LevelInfo + 1, "INFO+1"}, + {LevelInfo - 3, "DEBUG+1"}, + {LevelDebug, "DEBUG"}, + {LevelDebug - 2, "DEBUG-2"}, + } { + got := test.in.String() + if got != test.want { + t.Errorf("%d: got %s, want %s", test.in, got, test.want) + } + } +} + +func TestLevelVar(t *testing.T) { + var al LevelVar + if got, want := al.Level(), LevelInfo; got != want { + t.Errorf("got %v, want %v", got, want) + } + al.Set(LevelWarn) + if got, want := al.Level(), LevelWarn; got != want { + t.Errorf("got %v, want %v", got, want) + } + al.Set(LevelInfo) + if got, want := al.Level(), LevelInfo; got != want { + t.Errorf("got %v, want %v", got, want) + } + +} + +func TestMarshalJSON(t *testing.T) { + want := LevelWarn - 3 + data, err := want.MarshalJSON() + if err != nil { + t.Fatal(err) + } + var got Level + if err := got.UnmarshalJSON(data); err != nil { + t.Fatal(err) + } + if got != want { + t.Errorf("got %s, want %s", got, want) + } +} + +func TestLevelMarshalText(t *testing.T) { + want := LevelWarn - 3 + data, err := want.MarshalText() + if err != nil { + t.Fatal(err) + } + var got Level + if err := got.UnmarshalText(data); err != nil { + t.Fatal(err) + } + if got != want { + t.Errorf("got %s, want %s", got, want) + } +} + +func TestLevelParse(t *testing.T) { + for _, test := range []struct { + in string + want Level + }{ + {"DEBUG", LevelDebug}, + {"INFO", LevelInfo}, + {"WARN", LevelWarn}, + {"ERROR", LevelError}, + {"debug", LevelDebug}, + {"iNfo", LevelInfo}, + {"INFO+87", LevelInfo + 87}, + {"Error-18", LevelError - 18}, + {"Error-8", LevelInfo}, + } { + var got Level + if err := got.parse(test.in); err != nil { + t.Fatalf("%q: %v", test.in, err) + } + if got != test.want { + t.Errorf("%q: got %s, want %s", test.in, got, test.want) + } + } +} + +func TestLevelParseError(t *testing.T) { + for _, test := range []struct { + in string + want string // error string should contain this + }{ + {"", "unknown name"}, + {"dbg", "unknown name"}, + {"INFO+", "invalid syntax"}, + {"INFO-", "invalid syntax"}, + {"ERROR+23x", "invalid syntax"}, + } { + var l Level + err := l.parse(test.in) + if err == nil || !strings.Contains(err.Error(), test.want) { + t.Errorf("%q: got %v, want string containing %q", test.in, err, test.want) + } + } +} + +func TestLevelFlag(t *testing.T) { + fs := flag.NewFlagSet("test", flag.ContinueOnError) + lf := LevelInfo + fs.TextVar(&lf, "level", lf, "set level") + err := fs.Parse([]string{"-level", "WARN+3"}) + if err != nil { + t.Fatal(err) + } + if g, w := lf, LevelWarn+3; g != w { + t.Errorf("got %v, want %v", g, w) + } +} + +func TestLevelVarMarshalText(t *testing.T) { + var v LevelVar + v.Set(LevelWarn) + data, err := v.MarshalText() + if err != nil { + t.Fatal(err) + } + var v2 LevelVar + if err := v2.UnmarshalText(data); err != nil { + t.Fatal(err) + } + if g, w := v2.Level(), LevelWarn; g != w { + t.Errorf("got %s, want %s", g, w) + } +} + +func TestLevelVarFlag(t *testing.T) { + fs := flag.NewFlagSet("test", flag.ContinueOnError) + v := &LevelVar{} + v.Set(LevelWarn + 3) + fs.TextVar(v, "level", v, "set level") + err := fs.Parse([]string{"-level", "WARN+3"}) + if err != nil { + t.Fatal(err) + } + if g, w := v.Level(), LevelWarn+3; g != w { + t.Errorf("got %v, want %v", g, w) + } +} + +func TestLevelVarString(t *testing.T) { + var v LevelVar + v.Set(LevelError) + got := v.String() + want := "LevelVar(ERROR)" + if got != want { + t.Errorf("got %q, want %q", got, want) + } +} diff --git a/src/log/slog/logger.go b/src/log/slog/logger.go new file mode 100644 index 0000000..a068085 --- /dev/null +++ b/src/log/slog/logger.go @@ -0,0 +1,296 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "context" + "log" + loginternal "log/internal" + "log/slog/internal" + "runtime" + "sync/atomic" + "time" +) + +var defaultLogger atomic.Value + +func init() { + defaultLogger.Store(New(newDefaultHandler(loginternal.DefaultOutput))) +} + +// Default returns the default Logger. +func Default() *Logger { return defaultLogger.Load().(*Logger) } + +// SetDefault makes l the default Logger. +// After this call, output from the log package's default Logger +// (as with [log.Print], etc.) will be logged at LevelInfo using l's Handler. +func SetDefault(l *Logger) { + defaultLogger.Store(l) + // If the default's handler is a defaultHandler, then don't use a handleWriter, + // or we'll deadlock as they both try to acquire the log default mutex. + // The defaultHandler will use whatever the log default writer is currently + // set to, which is correct. + // This can occur with SetDefault(Default()). + // See TestSetDefault. + if _, ok := l.Handler().(*defaultHandler); !ok { + capturePC := log.Flags()&(log.Lshortfile|log.Llongfile) != 0 + log.SetOutput(&handlerWriter{l.Handler(), LevelInfo, capturePC}) + log.SetFlags(0) // we want just the log message, no time or location + } +} + +// handlerWriter is an io.Writer that calls a Handler. +// It is used to link the default log.Logger to the default slog.Logger. +type handlerWriter struct { + h Handler + level Level + capturePC bool +} + +func (w *handlerWriter) Write(buf []byte) (int, error) { + if !w.h.Enabled(context.Background(), w.level) { + return 0, nil + } + var pc uintptr + if !internal.IgnorePC && w.capturePC { + // skip [runtime.Callers, w.Write, Logger.Output, log.Print] + var pcs [1]uintptr + runtime.Callers(4, pcs[:]) + pc = pcs[0] + } + + // Remove final newline. + origLen := len(buf) // Report that the entire buf was written. + if len(buf) > 0 && buf[len(buf)-1] == '\n' { + buf = buf[:len(buf)-1] + } + r := NewRecord(time.Now(), w.level, string(buf), pc) + return origLen, w.h.Handle(context.Background(), r) +} + +// A Logger records structured information about each call to its +// Log, Debug, Info, Warn, and Error methods. +// For each call, it creates a Record and passes it to a Handler. +// +// To create a new Logger, call [New] or a Logger method +// that begins "With". +type Logger struct { + handler Handler // for structured logging +} + +func (l *Logger) clone() *Logger { + c := *l + return &c +} + +// Handler returns l's Handler. +func (l *Logger) Handler() Handler { return l.handler } + +// With returns a Logger that includes the given attributes +// in each output operation. Arguments are converted to +// attributes as if by [Logger.Log]. +func (l *Logger) With(args ...any) *Logger { + if len(args) == 0 { + return l + } + c := l.clone() + c.handler = l.handler.WithAttrs(argsToAttrSlice(args)) + return c +} + +// WithGroup returns a Logger that starts a group, if name is non-empty. +// The keys of all attributes added to the Logger will be qualified by the given +// name. (How that qualification happens depends on the [Handler.WithGroup] +// method of the Logger's Handler.) +// +// If name is empty, WithGroup returns the receiver. +func (l *Logger) WithGroup(name string) *Logger { + if name == "" { + return l + } + c := l.clone() + c.handler = l.handler.WithGroup(name) + return c + +} + +// New creates a new Logger with the given non-nil Handler. +func New(h Handler) *Logger { + if h == nil { + panic("nil Handler") + } + return &Logger{handler: h} +} + +// With calls Logger.With on the default logger. +func With(args ...any) *Logger { + return Default().With(args...) +} + +// Enabled reports whether l emits log records at the given context and level. +func (l *Logger) Enabled(ctx context.Context, level Level) bool { + if ctx == nil { + ctx = context.Background() + } + return l.Handler().Enabled(ctx, level) +} + +// NewLogLogger returns a new log.Logger such that each call to its Output method +// dispatches a Record to the specified handler. The logger acts as a bridge from +// the older log API to newer structured logging handlers. +func NewLogLogger(h Handler, level Level) *log.Logger { + return log.New(&handlerWriter{h, level, true}, "", 0) +} + +// Log emits a log record with the current time and the given level and message. +// The Record's Attrs consist of the Logger's attributes followed by +// the Attrs specified by args. +// +// The attribute arguments are processed as follows: +// - If an argument is an Attr, it is used as is. +// - If an argument is a string and this is not the last argument, +// the following argument is treated as the value and the two are combined +// into an Attr. +// - Otherwise, the argument is treated as a value with key "!BADKEY". +func (l *Logger) Log(ctx context.Context, level Level, msg string, args ...any) { + l.log(ctx, level, msg, args...) +} + +// LogAttrs is a more efficient version of [Logger.Log] that accepts only Attrs. +func (l *Logger) LogAttrs(ctx context.Context, level Level, msg string, attrs ...Attr) { + l.logAttrs(ctx, level, msg, attrs...) +} + +// Debug logs at LevelDebug. +func (l *Logger) Debug(msg string, args ...any) { + l.log(context.Background(), LevelDebug, msg, args...) +} + +// DebugContext logs at LevelDebug with the given context. +func (l *Logger) DebugContext(ctx context.Context, msg string, args ...any) { + l.log(ctx, LevelDebug, msg, args...) +} + +// Info logs at LevelInfo. +func (l *Logger) Info(msg string, args ...any) { + l.log(context.Background(), LevelInfo, msg, args...) +} + +// InfoContext logs at LevelInfo with the given context. +func (l *Logger) InfoContext(ctx context.Context, msg string, args ...any) { + l.log(ctx, LevelInfo, msg, args...) +} + +// Warn logs at LevelWarn. +func (l *Logger) Warn(msg string, args ...any) { + l.log(context.Background(), LevelWarn, msg, args...) +} + +// WarnContext logs at LevelWarn with the given context. +func (l *Logger) WarnContext(ctx context.Context, msg string, args ...any) { + l.log(ctx, LevelWarn, msg, args...) +} + +// Error logs at LevelError. +func (l *Logger) Error(msg string, args ...any) { + l.log(context.Background(), LevelError, msg, args...) +} + +// ErrorContext logs at LevelError with the given context. +func (l *Logger) ErrorContext(ctx context.Context, msg string, args ...any) { + l.log(ctx, LevelError, msg, args...) +} + +// log is the low-level logging method for methods that take ...any. +// It must always be called directly by an exported logging method +// or function, because it uses a fixed call depth to obtain the pc. +func (l *Logger) log(ctx context.Context, level Level, msg string, args ...any) { + if !l.Enabled(ctx, level) { + return + } + var pc uintptr + if !internal.IgnorePC { + var pcs [1]uintptr + // skip [runtime.Callers, this function, this function's caller] + runtime.Callers(3, pcs[:]) + pc = pcs[0] + } + r := NewRecord(time.Now(), level, msg, pc) + r.Add(args...) + if ctx == nil { + ctx = context.Background() + } + _ = l.Handler().Handle(ctx, r) +} + +// logAttrs is like [Logger.log], but for methods that take ...Attr. +func (l *Logger) logAttrs(ctx context.Context, level Level, msg string, attrs ...Attr) { + if !l.Enabled(ctx, level) { + return + } + var pc uintptr + if !internal.IgnorePC { + var pcs [1]uintptr + // skip [runtime.Callers, this function, this function's caller] + runtime.Callers(3, pcs[:]) + pc = pcs[0] + } + r := NewRecord(time.Now(), level, msg, pc) + r.AddAttrs(attrs...) + if ctx == nil { + ctx = context.Background() + } + _ = l.Handler().Handle(ctx, r) +} + +// Debug calls Logger.Debug on the default logger. +func Debug(msg string, args ...any) { + Default().log(context.Background(), LevelDebug, msg, args...) +} + +// DebugContext calls Logger.DebugContext on the default logger. +func DebugContext(ctx context.Context, msg string, args ...any) { + Default().log(ctx, LevelDebug, msg, args...) +} + +// Info calls Logger.Info on the default logger. +func Info(msg string, args ...any) { + Default().log(context.Background(), LevelInfo, msg, args...) +} + +// InfoContext calls Logger.InfoContext on the default logger. +func InfoContext(ctx context.Context, msg string, args ...any) { + Default().log(ctx, LevelInfo, msg, args...) +} + +// Warn calls Logger.Warn on the default logger. +func Warn(msg string, args ...any) { + Default().log(context.Background(), LevelWarn, msg, args...) +} + +// WarnContext calls Logger.WarnContext on the default logger. +func WarnContext(ctx context.Context, msg string, args ...any) { + Default().log(ctx, LevelWarn, msg, args...) +} + +// Error calls Logger.Error on the default logger. +func Error(msg string, args ...any) { + Default().log(context.Background(), LevelError, msg, args...) +} + +// ErrorContext calls Logger.ErrorContext on the default logger. +func ErrorContext(ctx context.Context, msg string, args ...any) { + Default().log(ctx, LevelError, msg, args...) +} + +// Log calls Logger.Log on the default logger. +func Log(ctx context.Context, level Level, msg string, args ...any) { + Default().log(ctx, level, msg, args...) +} + +// LogAttrs calls Logger.LogAttrs on the default logger. +func LogAttrs(ctx context.Context, level Level, msg string, attrs ...Attr) { + Default().logAttrs(ctx, level, msg, attrs...) +} diff --git a/src/log/slog/logger_test.go b/src/log/slog/logger_test.go new file mode 100644 index 0000000..2f5b319 --- /dev/null +++ b/src/log/slog/logger_test.go @@ -0,0 +1,573 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "bytes" + "context" + "internal/race" + "internal/testenv" + "io" + "log" + loginternal "log/internal" + "path/filepath" + "regexp" + "runtime" + "slices" + "strings" + "sync" + "testing" + "time" +) + +const timeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}(Z|[+-]\d{2}:\d{2})` + +func TestLogTextHandler(t *testing.T) { + ctx := context.Background() + var buf bytes.Buffer + + l := New(NewTextHandler(&buf, nil)) + + check := func(want string) { + t.Helper() + if want != "" { + want = "time=" + timeRE + " " + want + } + checkLogOutput(t, buf.String(), want) + buf.Reset() + } + + l.Info("msg", "a", 1, "b", 2) + check(`level=INFO msg=msg a=1 b=2`) + + // By default, debug messages are not printed. + l.Debug("bg", Int("a", 1), "b", 2) + check("") + + l.Warn("w", Duration("dur", 3*time.Second)) + check(`level=WARN msg=w dur=3s`) + + l.Error("bad", "a", 1) + check(`level=ERROR msg=bad a=1`) + + l.Log(ctx, LevelWarn+1, "w", Int("a", 1), String("b", "two")) + check(`level=WARN\+1 msg=w a=1 b=two`) + + l.LogAttrs(ctx, LevelInfo+1, "a b c", Int("a", 1), String("b", "two")) + check(`level=INFO\+1 msg="a b c" a=1 b=two`) + + l.Info("info", "a", []Attr{Int("i", 1)}) + check(`level=INFO msg=info a.i=1`) + + l.Info("info", "a", GroupValue(Int("i", 1))) + check(`level=INFO msg=info a.i=1`) +} + +func TestConnections(t *testing.T) { + var logbuf, slogbuf bytes.Buffer + + // Revert any changes to the default logger. This is important because other + // tests might change the default logger using SetDefault. Also ensure we + // restore the default logger at the end of the test. + currentLogger := Default() + SetDefault(New(newDefaultHandler(loginternal.DefaultOutput))) + t.Cleanup(func() { + SetDefault(currentLogger) + }) + + // The default slog.Logger's handler uses the log package's default output. + log.SetOutput(&logbuf) + log.SetFlags(log.Lshortfile &^ log.LstdFlags) + Info("msg", "a", 1) + checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg a=1`) + logbuf.Reset() + Warn("msg", "b", 2) + checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: WARN msg b=2`) + logbuf.Reset() + Error("msg", "err", io.EOF, "c", 3) + checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: ERROR msg err=EOF c=3`) + + // Levels below Info are not printed. + logbuf.Reset() + Debug("msg", "c", 3) + checkLogOutput(t, logbuf.String(), "") + + t.Run("wrap default handler", func(t *testing.T) { + // It should be possible to wrap the default handler and get the right output. + // This works because the default handler uses the pc in the Record + // to get the source line, rather than a call depth. + logger := New(wrappingHandler{Default().Handler()}) + logger.Info("msg", "d", 4) + checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg d=4`) + }) + + // Once slog.SetDefault is called, the direction is reversed: the default + // log.Logger's output goes through the handler. + SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{AddSource: true}))) + log.Print("msg2") + checkLogOutput(t, slogbuf.String(), "time="+timeRE+` level=INFO source=.*logger_test.go:\d{3}"? msg=msg2`) + + // The default log.Logger always outputs at Info level. + slogbuf.Reset() + SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{Level: LevelWarn}))) + log.Print("should not appear") + if got := slogbuf.String(); got != "" { + t.Errorf("got %q, want empty", got) + } + + // Setting log's output again breaks the connection. + logbuf.Reset() + slogbuf.Reset() + log.SetOutput(&logbuf) + log.SetFlags(log.Lshortfile &^ log.LstdFlags) + log.Print("msg3") + checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: msg3`) + if got := slogbuf.String(); got != "" { + t.Errorf("got %q, want empty", got) + } +} + +type wrappingHandler struct { + h Handler +} + +func (h wrappingHandler) Enabled(ctx context.Context, level Level) bool { + return h.h.Enabled(ctx, level) +} +func (h wrappingHandler) WithGroup(name string) Handler { return h.h.WithGroup(name) } +func (h wrappingHandler) WithAttrs(as []Attr) Handler { return h.h.WithAttrs(as) } +func (h wrappingHandler) Handle(ctx context.Context, r Record) error { return h.h.Handle(ctx, r) } + +func TestAttrs(t *testing.T) { + check := func(got []Attr, want ...Attr) { + t.Helper() + if !attrsEqual(got, want) { + t.Errorf("got %v, want %v", got, want) + } + } + + l1 := New(&captureHandler{}).With("a", 1) + l2 := New(l1.Handler()).With("b", 2) + l2.Info("m", "c", 3) + h := l2.Handler().(*captureHandler) + check(h.attrs, Int("a", 1), Int("b", 2)) + check(attrsSlice(h.r), Int("c", 3)) +} + +func TestCallDepth(t *testing.T) { + ctx := context.Background() + h := &captureHandler{} + var startLine int + + check := func(count int) { + t.Helper() + const wantFunc = "log/slog.TestCallDepth" + const wantFile = "logger_test.go" + wantLine := startLine + count*2 + got := h.r.source() + gotFile := filepath.Base(got.File) + if got.Function != wantFunc || gotFile != wantFile || got.Line != wantLine { + t.Errorf("got (%s, %s, %d), want (%s, %s, %d)", + got.Function, gotFile, got.Line, wantFunc, wantFile, wantLine) + } + } + + logger := New(h) + SetDefault(logger) + + // Calls to check must be one line apart. + // Determine line where calls start. + f, _ := runtime.CallersFrames([]uintptr{callerPC(2)}).Next() + startLine = f.Line + 4 + // Do not change the number of lines between here and the call to check(0). + + logger.Log(ctx, LevelInfo, "") + check(0) + logger.LogAttrs(ctx, LevelInfo, "") + check(1) + logger.Debug("") + check(2) + logger.Info("") + check(3) + logger.Warn("") + check(4) + logger.Error("") + check(5) + Debug("") + check(6) + Info("") + check(7) + Warn("") + check(8) + Error("") + check(9) + Log(ctx, LevelInfo, "") + check(10) + LogAttrs(ctx, LevelInfo, "") + check(11) +} + +func TestAlloc(t *testing.T) { + ctx := context.Background() + dl := New(discardHandler{}) + defer SetDefault(Default()) // restore + SetDefault(dl) + + t.Run("Info", func(t *testing.T) { + wantAllocs(t, 0, func() { Info("hello") }) + }) + t.Run("Error", func(t *testing.T) { + wantAllocs(t, 0, func() { Error("hello") }) + }) + t.Run("logger.Info", func(t *testing.T) { + wantAllocs(t, 0, func() { dl.Info("hello") }) + }) + t.Run("logger.Log", func(t *testing.T) { + wantAllocs(t, 0, func() { dl.Log(ctx, LevelDebug, "hello") }) + }) + t.Run("2 pairs", func(t *testing.T) { + s := "abc" + i := 2000 + wantAllocs(t, 2, func() { + dl.Info("hello", + "n", i, + "s", s, + ) + }) + }) + t.Run("2 pairs disabled inline", func(t *testing.T) { + l := New(discardHandler{disabled: true}) + s := "abc" + i := 2000 + wantAllocs(t, 2, func() { + l.Log(ctx, LevelInfo, "hello", + "n", i, + "s", s, + ) + }) + }) + t.Run("2 pairs disabled", func(t *testing.T) { + l := New(discardHandler{disabled: true}) + s := "abc" + i := 2000 + wantAllocs(t, 0, func() { + if l.Enabled(ctx, LevelInfo) { + l.Log(ctx, LevelInfo, "hello", + "n", i, + "s", s, + ) + } + }) + }) + t.Run("9 kvs", func(t *testing.T) { + s := "abc" + i := 2000 + d := time.Second + wantAllocs(t, 11, func() { + dl.Info("hello", + "n", i, "s", s, "d", d, + "n", i, "s", s, "d", d, + "n", i, "s", s, "d", d) + }) + }) + t.Run("pairs", func(t *testing.T) { + wantAllocs(t, 0, func() { dl.Info("", "error", io.EOF) }) + }) + t.Run("attrs1", func(t *testing.T) { + wantAllocs(t, 0, func() { dl.LogAttrs(ctx, LevelInfo, "", Int("a", 1)) }) + wantAllocs(t, 0, func() { dl.LogAttrs(ctx, LevelInfo, "", Any("error", io.EOF)) }) + }) + t.Run("attrs3", func(t *testing.T) { + wantAllocs(t, 0, func() { + dl.LogAttrs(ctx, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second)) + }) + }) + t.Run("attrs3 disabled", func(t *testing.T) { + logger := New(discardHandler{disabled: true}) + wantAllocs(t, 0, func() { + logger.LogAttrs(ctx, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second)) + }) + }) + t.Run("attrs6", func(t *testing.T) { + wantAllocs(t, 1, func() { + dl.LogAttrs(ctx, LevelInfo, "hello", + Int("a", 1), String("b", "two"), Duration("c", time.Second), + Int("d", 1), String("e", "two"), Duration("f", time.Second)) + }) + }) + t.Run("attrs9", func(t *testing.T) { + wantAllocs(t, 1, func() { + dl.LogAttrs(ctx, LevelInfo, "hello", + Int("a", 1), String("b", "two"), Duration("c", time.Second), + Int("d", 1), String("e", "two"), Duration("f", time.Second), + Int("d", 1), String("e", "two"), Duration("f", time.Second)) + }) + }) +} + +func TestSetAttrs(t *testing.T) { + for _, test := range []struct { + args []any + want []Attr + }{ + {nil, nil}, + {[]any{"a", 1}, []Attr{Int("a", 1)}}, + {[]any{"a", 1, "b", "two"}, []Attr{Int("a", 1), String("b", "two")}}, + {[]any{"a"}, []Attr{String(badKey, "a")}}, + {[]any{"a", 1, "b"}, []Attr{Int("a", 1), String(badKey, "b")}}, + {[]any{"a", 1, 2, 3}, []Attr{Int("a", 1), Int(badKey, 2), Int(badKey, 3)}}, + } { + r := NewRecord(time.Time{}, 0, "", 0) + r.Add(test.args...) + got := attrsSlice(r) + if !attrsEqual(got, test.want) { + t.Errorf("%v:\ngot %v\nwant %v", test.args, got, test.want) + } + } +} + +func TestSetDefault(t *testing.T) { + // Verify that setting the default to itself does not result in deadlock. + ctx, cancel := context.WithTimeout(context.Background(), time.Second) + defer cancel() + defer func(w io.Writer) { log.SetOutput(w) }(log.Writer()) + log.SetOutput(io.Discard) + go func() { + Info("A") + SetDefault(Default()) + Info("B") + cancel() + }() + <-ctx.Done() + if err := ctx.Err(); err != context.Canceled { + t.Errorf("wanted canceled, got %v", err) + } +} + +func TestLoggerError(t *testing.T) { + var buf bytes.Buffer + + removeTime := func(_ []string, a Attr) Attr { + if a.Key == TimeKey { + return Attr{} + } + return a + } + l := New(NewTextHandler(&buf, &HandlerOptions{ReplaceAttr: removeTime})) + l.Error("msg", "err", io.EOF, "a", 1) + checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF a=1`) + buf.Reset() + // use local var 'args' to defeat vet check + args := []any{"err", io.EOF, "a"} + l.Error("msg", args...) + checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF !BADKEY=a`) +} + +func TestNewLogLogger(t *testing.T) { + var buf bytes.Buffer + h := NewTextHandler(&buf, nil) + ll := NewLogLogger(h, LevelWarn) + ll.Print("hello") + checkLogOutput(t, buf.String(), "time="+timeRE+` level=WARN msg=hello`) +} + +func TestLoggerNoOps(t *testing.T) { + l := Default() + if l.With() != l { + t.Error("wanted receiver, didn't get it") + } + if With() != l { + t.Error("wanted receiver, didn't get it") + } + if l.WithGroup("") != l { + t.Error("wanted receiver, didn't get it") + } +} + +func TestContext(t *testing.T) { + // Verify that the context argument to log output methods is passed to the handler. + // Also check the level. + h := &captureHandler{} + l := New(h) + defer SetDefault(Default()) // restore + SetDefault(l) + + for _, test := range []struct { + f func(context.Context, string, ...any) + wantLevel Level + }{ + {l.DebugContext, LevelDebug}, + {l.InfoContext, LevelInfo}, + {l.WarnContext, LevelWarn}, + {l.ErrorContext, LevelError}, + {DebugContext, LevelDebug}, + {InfoContext, LevelInfo}, + {WarnContext, LevelWarn}, + {ErrorContext, LevelError}, + } { + h.clear() + ctx := context.WithValue(context.Background(), "L", test.wantLevel) + + test.f(ctx, "msg") + if gv := h.ctx.Value("L"); gv != test.wantLevel || h.r.Level != test.wantLevel { + t.Errorf("got context value %v, level %s; want %s for both", gv, h.r.Level, test.wantLevel) + } + } +} + +func checkLogOutput(t *testing.T, got, wantRegexp string) { + t.Helper() + got = clean(got) + wantRegexp = "^" + wantRegexp + "$" + matched, err := regexp.MatchString(wantRegexp, got) + if err != nil { + t.Fatal(err) + } + if !matched { + t.Errorf("\ngot %s\nwant %s", got, wantRegexp) + } +} + +// clean prepares log output for comparison. +func clean(s string) string { + if len(s) > 0 && s[len(s)-1] == '\n' { + s = s[:len(s)-1] + } + return strings.ReplaceAll(s, "\n", "~") +} + +type captureHandler struct { + mu sync.Mutex + ctx context.Context + r Record + attrs []Attr + groups []string +} + +func (h *captureHandler) Handle(ctx context.Context, r Record) error { + h.mu.Lock() + defer h.mu.Unlock() + h.ctx = ctx + h.r = r + return nil +} + +func (*captureHandler) Enabled(context.Context, Level) bool { return true } + +func (c *captureHandler) WithAttrs(as []Attr) Handler { + c.mu.Lock() + defer c.mu.Unlock() + var c2 captureHandler + c2.r = c.r + c2.groups = c.groups + c2.attrs = concat(c.attrs, as) + return &c2 +} + +func (c *captureHandler) WithGroup(name string) Handler { + c.mu.Lock() + defer c.mu.Unlock() + var c2 captureHandler + c2.r = c.r + c2.attrs = c.attrs + c2.groups = append(slices.Clip(c.groups), name) + return &c2 +} + +func (c *captureHandler) clear() { + c.mu.Lock() + defer c.mu.Unlock() + c.ctx = nil + c.r = Record{} +} + +type discardHandler struct { + disabled bool + attrs []Attr +} + +func (d discardHandler) Enabled(context.Context, Level) bool { return !d.disabled } +func (discardHandler) Handle(context.Context, Record) error { return nil } +func (d discardHandler) WithAttrs(as []Attr) Handler { + d.attrs = concat(d.attrs, as) + return d +} +func (h discardHandler) WithGroup(name string) Handler { + return h +} + +// concat returns a new slice with the elements of s1 followed +// by those of s2. The slice has no additional capacity. +func concat[T any](s1, s2 []T) []T { + s := make([]T, len(s1)+len(s2)) + copy(s, s1) + copy(s[len(s1):], s2) + return s +} + +// This is a simple benchmark. See the benchmarks subdirectory for more extensive ones. +func BenchmarkNopLog(b *testing.B) { + ctx := context.Background() + l := New(&captureHandler{}) + b.Run("no attrs", func(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + l.LogAttrs(ctx, LevelInfo, "msg") + } + }) + b.Run("attrs", func(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true)) + } + }) + b.Run("attrs-parallel", func(b *testing.B) { + b.ReportAllocs() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true)) + } + }) + }) + b.Run("keys-values", func(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + l.Log(ctx, LevelInfo, "msg", "a", 1, "b", "two", "c", true) + } + }) + b.Run("WithContext", func(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + l.LogAttrs(ctx, LevelInfo, "msg2", Int("a", 1), String("b", "two"), Bool("c", true)) + } + }) + b.Run("WithContext-parallel", func(b *testing.B) { + b.ReportAllocs() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true)) + } + }) + }) +} + +// callerPC returns the program counter at the given stack depth. +func callerPC(depth int) uintptr { + var pcs [1]uintptr + runtime.Callers(depth, pcs[:]) + return pcs[0] +} + +func wantAllocs(t *testing.T, want int, f func()) { + if race.Enabled { + t.Skip("skipping test in race mode") + } + testenv.SkipIfOptimizationOff(t) + t.Helper() + got := int(testing.AllocsPerRun(5, f)) + if got != want { + t.Errorf("got %d allocs, want %d", got, want) + } +} diff --git a/src/log/slog/record.go b/src/log/slog/record.go new file mode 100644 index 0000000..67b76f3 --- /dev/null +++ b/src/log/slog/record.go @@ -0,0 +1,225 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "runtime" + "slices" + "time" +) + +const nAttrsInline = 5 + +// A Record holds information about a log event. +// Copies of a Record share state. +// Do not modify a Record after handing out a copy to it. +// Call [NewRecord] to create a new Record. +// Use [Record.Clone] to create a copy with no shared state. +type Record struct { + // The time at which the output method (Log, Info, etc.) was called. + Time time.Time + + // The log message. + Message string + + // The level of the event. + Level Level + + // The program counter at the time the record was constructed, as determined + // by runtime.Callers. If zero, no program counter is available. + // + // The only valid use for this value is as an argument to + // [runtime.CallersFrames]. In particular, it must not be passed to + // [runtime.FuncForPC]. + PC uintptr + + // Allocation optimization: an inline array sized to hold + // the majority of log calls (based on examination of open-source + // code). It holds the start of the list of Attrs. + front [nAttrsInline]Attr + + // The number of Attrs in front. + nFront int + + // The list of Attrs except for those in front. + // Invariants: + // - len(back) > 0 iff nFront == len(front) + // - Unused array elements are zero. Used to detect mistakes. + back []Attr +} + +// NewRecord creates a Record from the given arguments. +// Use [Record.AddAttrs] to add attributes to the Record. +// +// NewRecord is intended for logging APIs that want to support a [Handler] as +// a backend. +func NewRecord(t time.Time, level Level, msg string, pc uintptr) Record { + return Record{ + Time: t, + Message: msg, + Level: level, + PC: pc, + } +} + +// Clone returns a copy of the record with no shared state. +// The original record and the clone can both be modified +// without interfering with each other. +func (r Record) Clone() Record { + r.back = slices.Clip(r.back) // prevent append from mutating shared array + return r +} + +// NumAttrs returns the number of attributes in the Record. +func (r Record) NumAttrs() int { + return r.nFront + len(r.back) +} + +// Attrs calls f on each Attr in the Record. +// Iteration stops if f returns false. +func (r Record) Attrs(f func(Attr) bool) { + for i := 0; i < r.nFront; i++ { + if !f(r.front[i]) { + return + } + } + for _, a := range r.back { + if !f(a) { + return + } + } +} + +// AddAttrs appends the given Attrs to the Record's list of Attrs. +// It omits empty groups. +func (r *Record) AddAttrs(attrs ...Attr) { + var i int + for i = 0; i < len(attrs) && r.nFront < len(r.front); i++ { + a := attrs[i] + if a.Value.isEmptyGroup() { + continue + } + r.front[r.nFront] = a + r.nFront++ + } + // Check if a copy was modified by slicing past the end + // and seeing if the Attr there is non-zero. + if cap(r.back) > len(r.back) { + end := r.back[:len(r.back)+1][len(r.back)] + if !end.isEmpty() { + panic("copies of a slog.Record were both modified") + } + } + ne := countEmptyGroups(attrs[i:]) + r.back = slices.Grow(r.back, len(attrs[i:])-ne) + for _, a := range attrs[i:] { + if !a.Value.isEmptyGroup() { + r.back = append(r.back, a) + } + } +} + +// Add converts the args to Attrs as described in [Logger.Log], +// then appends the Attrs to the Record's list of Attrs. +// It omits empty groups. +func (r *Record) Add(args ...any) { + var a Attr + for len(args) > 0 { + a, args = argsToAttr(args) + if a.Value.isEmptyGroup() { + continue + } + if r.nFront < len(r.front) { + r.front[r.nFront] = a + r.nFront++ + } else { + if r.back == nil { + r.back = make([]Attr, 0, countAttrs(args)) + } + r.back = append(r.back, a) + } + } + +} + +// countAttrs returns the number of Attrs that would be created from args. +func countAttrs(args []any) int { + n := 0 + for i := 0; i < len(args); i++ { + n++ + if _, ok := args[i].(string); ok { + i++ + } + } + return n +} + +const badKey = "!BADKEY" + +// argsToAttr turns a prefix of the nonempty args slice into an Attr +// and returns the unconsumed portion of the slice. +// If args[0] is an Attr, it returns it. +// If args[0] is a string, it treats the first two elements as +// a key-value pair. +// Otherwise, it treats args[0] as a value with a missing key. +func argsToAttr(args []any) (Attr, []any) { + switch x := args[0].(type) { + case string: + if len(args) == 1 { + return String(badKey, x), nil + } + return Any(x, args[1]), args[2:] + + case Attr: + return x, args[1:] + + default: + return Any(badKey, x), args[1:] + } +} + +// Source describes the location of a line of source code. +type Source struct { + // Function is the package path-qualified function name containing the + // source line. If non-empty, this string uniquely identifies a single + // function in the program. This may be the empty string if not known. + Function string `json:"function"` + // File and Line are the file name and line number (1-based) of the source + // line. These may be the empty string and zero, respectively, if not known. + File string `json:"file"` + Line int `json:"line"` +} + +// attrs returns the non-zero fields of s as a slice of attrs. +// It is similar to a LogValue method, but we don't want Source +// to implement LogValuer because it would be resolved before +// the ReplaceAttr function was called. +func (s *Source) group() Value { + var as []Attr + if s.Function != "" { + as = append(as, String("function", s.Function)) + } + if s.File != "" { + as = append(as, String("file", s.File)) + } + if s.Line != 0 { + as = append(as, Int("line", s.Line)) + } + return GroupValue(as...) +} + +// source returns a Source for the log event. +// If the Record was created without the necessary information, +// or if the location is unavailable, it returns a non-nil *Source +// with zero fields. +func (r Record) source() *Source { + fs := runtime.CallersFrames([]uintptr{r.PC}) + f, _ := fs.Next() + return &Source{ + Function: f.Function, + File: f.File, + Line: f.Line, + } +} diff --git a/src/log/slog/record_test.go b/src/log/slog/record_test.go new file mode 100644 index 0000000..15d9330 --- /dev/null +++ b/src/log/slog/record_test.go @@ -0,0 +1,156 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "slices" + "strconv" + "strings" + "testing" + "time" +) + +func TestRecordAttrs(t *testing.T) { + as := []Attr{Int("k1", 1), String("k2", "foo"), Int("k3", 3), + Int64("k4", -1), Float64("f", 3.1), Uint64("u", 999)} + r := newRecordWithAttrs(as) + if g, w := r.NumAttrs(), len(as); g != w { + t.Errorf("NumAttrs: got %d, want %d", g, w) + } + if got := attrsSlice(r); !attrsEqual(got, as) { + t.Errorf("got %v, want %v", got, as) + } + + // Early return. + // Hit both loops in Record.Attrs: front and back. + for _, stop := range []int{2, 6} { + var got []Attr + r.Attrs(func(a Attr) bool { + got = append(got, a) + return len(got) < stop + }) + want := as[:stop] + if !attrsEqual(got, want) { + t.Errorf("got %v, want %v", got, want) + } + } +} + +func TestRecordSource(t *testing.T) { + // Zero call depth => empty *Source. + for _, test := range []struct { + depth int + wantFunction string + wantFile string + wantLinePositive bool + }{ + {0, "", "", false}, + {-16, "", "", false}, + {1, "log/slog.TestRecordSource", "record_test.go", true}, // 1: caller of NewRecord + {2, "testing.tRunner", "testing.go", true}, + } { + var pc uintptr + if test.depth > 0 { + pc = callerPC(test.depth + 1) + } + r := NewRecord(time.Time{}, 0, "", pc) + got := r.source() + if i := strings.LastIndexByte(got.File, '/'); i >= 0 { + got.File = got.File[i+1:] + } + if got.Function != test.wantFunction || got.File != test.wantFile || (got.Line > 0) != test.wantLinePositive { + t.Errorf("depth %d: got (%q, %q, %d), want (%q, %q, %t)", + test.depth, + got.Function, got.File, got.Line, + test.wantFunction, test.wantFile, test.wantLinePositive) + } + } +} + +func TestAliasingAndClone(t *testing.T) { + intAttrs := func(from, to int) []Attr { + var as []Attr + for i := from; i < to; i++ { + as = append(as, Int("k", i)) + } + return as + } + + check := func(r Record, want []Attr) { + t.Helper() + got := attrsSlice(r) + if !attrsEqual(got, want) { + t.Errorf("got %v, want %v", got, want) + } + } + + // Create a record whose Attrs overflow the inline array, + // creating a slice in r.back. + r1 := NewRecord(time.Time{}, 0, "", 0) + r1.AddAttrs(intAttrs(0, nAttrsInline+1)...) + // Ensure that r1.back's capacity exceeds its length. + b := make([]Attr, len(r1.back), len(r1.back)+1) + copy(b, r1.back) + r1.back = b + // Make a copy that shares state. + r2 := r1 + // Adding to both should panic. + r1.AddAttrs(Int("p", 0)) + if !panics(func() { r2.AddAttrs(Int("p", 1)) }) { + t.Error("expected panic") + } + r1Attrs := attrsSlice(r1) + // Adding to a clone is fine. + r2 = r1.Clone() + check(r2, r1Attrs) + r2.AddAttrs(Int("p", 2)) + check(r1, r1Attrs) // r1 is unchanged + check(r2, append(slices.Clip(r1Attrs), Int("p", 2))) +} + +func newRecordWithAttrs(as []Attr) Record { + r := NewRecord(time.Now(), LevelInfo, "", 0) + r.AddAttrs(as...) + return r +} + +func attrsSlice(r Record) []Attr { + s := make([]Attr, 0, r.NumAttrs()) + r.Attrs(func(a Attr) bool { s = append(s, a); return true }) + return s +} + +func attrsEqual(as1, as2 []Attr) bool { + return slices.EqualFunc(as1, as2, Attr.Equal) +} + +// Currently, pc(2) takes over 400ns, which is too expensive +// to call it for every log message. +func BenchmarkPC(b *testing.B) { + for depth := 0; depth < 5; depth++ { + b.Run(strconv.Itoa(depth), func(b *testing.B) { + b.ReportAllocs() + var x uintptr + for i := 0; i < b.N; i++ { + x = callerPC(depth) + } + _ = x + }) + } +} + +func BenchmarkRecord(b *testing.B) { + const nAttrs = nAttrsInline * 10 + var a Attr + + for i := 0; i < b.N; i++ { + r := NewRecord(time.Time{}, LevelInfo, "", 0) + for j := 0; j < nAttrs; j++ { + r.AddAttrs(Int("k", j)) + } + r.Attrs(func(b Attr) bool { a = b; return true }) + } + _ = a +} diff --git a/src/log/slog/slogtest_test.go b/src/log/slog/slogtest_test.go new file mode 100644 index 0000000..4887cc8 --- /dev/null +++ b/src/log/slog/slogtest_test.go @@ -0,0 +1,104 @@ +// Copyright 2023 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog_test + +import ( + "bytes" + "encoding/json" + "fmt" + "io" + "log/slog" + "strings" + "testing" + "testing/slogtest" +) + +func TestSlogtest(t *testing.T) { + for _, test := range []struct { + name string + new func(io.Writer) slog.Handler + parse func([]byte) (map[string]any, error) + }{ + {"JSON", func(w io.Writer) slog.Handler { return slog.NewJSONHandler(w, nil) }, parseJSON}, + {"Text", func(w io.Writer) slog.Handler { return slog.NewTextHandler(w, nil) }, parseText}, + } { + t.Run(test.name, func(t *testing.T) { + var buf bytes.Buffer + h := test.new(&buf) + results := func() []map[string]any { + ms, err := parseLines(buf.Bytes(), test.parse) + if err != nil { + t.Fatal(err) + } + return ms + } + if err := slogtest.TestHandler(h, results); err != nil { + t.Fatal(err) + } + }) + } +} + +func parseLines(src []byte, parse func([]byte) (map[string]any, error)) ([]map[string]any, error) { + var records []map[string]any + for _, line := range bytes.Split(src, []byte{'\n'}) { + if len(line) == 0 { + continue + } + m, err := parse(line) + if err != nil { + return nil, fmt.Errorf("%s: %w", string(line), err) + } + records = append(records, m) + } + return records, nil +} + +func parseJSON(bs []byte) (map[string]any, error) { + var m map[string]any + if err := json.Unmarshal(bs, &m); err != nil { + return nil, err + } + return m, nil +} + +// parseText parses the output of a single call to TextHandler.Handle. +// It can parse the output of the tests in this package, +// but it doesn't handle quoted keys or values. +// It doesn't need to handle all cases, because slogtest deliberately +// uses simple inputs so handler writers can focus on testing +// handler behavior, not parsing. +func parseText(bs []byte) (map[string]any, error) { + top := map[string]any{} + s := string(bytes.TrimSpace(bs)) + for len(s) > 0 { + kv, rest, _ := strings.Cut(s, " ") // assumes exactly one space between attrs + k, value, found := strings.Cut(kv, "=") + if !found { + return nil, fmt.Errorf("no '=' in %q", kv) + } + keys := strings.Split(k, ".") + // Populate a tree of maps for a dotted path such as "a.b.c=x". + m := top + for _, key := range keys[:len(keys)-1] { + x, ok := m[key] + var m2 map[string]any + if !ok { + m2 = map[string]any{} + m[key] = m2 + } else { + m2, ok = x.(map[string]any) + if !ok { + return nil, fmt.Errorf("value for %q in composite key %q is not map[string]any", key, k) + + } + } + m = m2 + } + m[keys[len(keys)-1]] = value + s = rest + } + return top, nil +} diff --git a/src/log/slog/text_handler.go b/src/log/slog/text_handler.go new file mode 100644 index 0000000..58edb2f --- /dev/null +++ b/src/log/slog/text_handler.go @@ -0,0 +1,163 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "context" + "encoding" + "fmt" + "io" + "reflect" + "strconv" + "sync" + "unicode" + "unicode/utf8" +) + +// TextHandler is a Handler that writes Records to an io.Writer as a +// sequence of key=value pairs separated by spaces and followed by a newline. +type TextHandler struct { + *commonHandler +} + +// NewTextHandler creates a TextHandler that writes to w, +// using the given options. +// If opts is nil, the default options are used. +func NewTextHandler(w io.Writer, opts *HandlerOptions) *TextHandler { + if opts == nil { + opts = &HandlerOptions{} + } + return &TextHandler{ + &commonHandler{ + json: false, + w: w, + opts: *opts, + mu: &sync.Mutex{}, + }, + } +} + +// Enabled reports whether the handler handles records at the given level. +// The handler ignores records whose level is lower. +func (h *TextHandler) Enabled(_ context.Context, level Level) bool { + return h.commonHandler.enabled(level) +} + +// WithAttrs returns a new TextHandler whose attributes consists +// of h's attributes followed by attrs. +func (h *TextHandler) WithAttrs(attrs []Attr) Handler { + return &TextHandler{commonHandler: h.commonHandler.withAttrs(attrs)} +} + +func (h *TextHandler) WithGroup(name string) Handler { + return &TextHandler{commonHandler: h.commonHandler.withGroup(name)} +} + +// Handle formats its argument Record as a single line of space-separated +// key=value items. +// +// If the Record's time is zero, the time is omitted. +// Otherwise, the key is "time" +// and the value is output in RFC3339 format with millisecond precision. +// +// If the Record's level is zero, the level is omitted. +// Otherwise, the key is "level" +// and the value of [Level.String] is output. +// +// If the AddSource option is set and source information is available, +// the key is "source" and the value is output as FILE:LINE. +// +// The message's key is "msg". +// +// To modify these or other attributes, or remove them from the output, use +// [HandlerOptions.ReplaceAttr]. +// +// If a value implements [encoding.TextMarshaler], the result of MarshalText is +// written. Otherwise, the result of fmt.Sprint is written. +// +// Keys and values are quoted with [strconv.Quote] if they contain Unicode space +// characters, non-printing characters, '"' or '='. +// +// Keys inside groups consist of components (keys or group names) separated by +// dots. No further escaping is performed. +// Thus there is no way to determine from the key "a.b.c" whether there +// are two groups "a" and "b" and a key "c", or a single group "a.b" and a key "c", +// or single group "a" and a key "b.c". +// If it is necessary to reconstruct the group structure of a key +// even in the presence of dots inside components, use +// [HandlerOptions.ReplaceAttr] to encode that information in the key. +// +// Each call to Handle results in a single serialized call to +// io.Writer.Write. +func (h *TextHandler) Handle(_ context.Context, r Record) error { + return h.commonHandler.handle(r) +} + +func appendTextValue(s *handleState, v Value) error { + switch v.Kind() { + case KindString: + s.appendString(v.str()) + case KindTime: + s.appendTime(v.time()) + case KindAny: + if tm, ok := v.any.(encoding.TextMarshaler); ok { + data, err := tm.MarshalText() + if err != nil { + return err + } + // TODO: avoid the conversion to string. + s.appendString(string(data)) + return nil + } + if bs, ok := byteSlice(v.any); ok { + // As of Go 1.19, this only allocates for strings longer than 32 bytes. + s.buf.WriteString(strconv.Quote(string(bs))) + return nil + } + s.appendString(fmt.Sprintf("%+v", v.Any())) + default: + *s.buf = v.append(*s.buf) + } + return nil +} + +// byteSlice returns its argument as a []byte if the argument's +// underlying type is []byte, along with a second return value of true. +// Otherwise it returns nil, false. +func byteSlice(a any) ([]byte, bool) { + if bs, ok := a.([]byte); ok { + return bs, true + } + // Like Printf's %s, we allow both the slice type and the byte element type to be named. + t := reflect.TypeOf(a) + if t != nil && t.Kind() == reflect.Slice && t.Elem().Kind() == reflect.Uint8 { + return reflect.ValueOf(a).Bytes(), true + } + return nil, false +} + +func needsQuoting(s string) bool { + if len(s) == 0 { + return true + } + for i := 0; i < len(s); { + b := s[i] + if b < utf8.RuneSelf { + // Quote anything except a backslash that would need quoting in a + // JSON string, as well as space and '=' + if b != '\\' && (b == ' ' || b == '=' || !safeSet[b]) { + return true + } + i++ + continue + } + r, size := utf8.DecodeRuneInString(s[i:]) + if r == utf8.RuneError || unicode.IsSpace(r) || !unicode.IsPrint(r) { + return true + } + i += size + } + return false +} diff --git a/src/log/slog/text_handler_test.go b/src/log/slog/text_handler_test.go new file mode 100644 index 0000000..591c243 --- /dev/null +++ b/src/log/slog/text_handler_test.go @@ -0,0 +1,176 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "bytes" + "context" + "errors" + "fmt" + "internal/testenv" + "io" + "strings" + "testing" + "time" +) + +var testTime = time.Date(2000, 1, 2, 3, 4, 5, 0, time.UTC) + +func TestTextHandler(t *testing.T) { + for _, test := range []struct { + name string + attr Attr + wantKey, wantVal string + }{ + { + "unquoted", + Int("a", 1), + "a", "1", + }, + { + "quoted", + String("x = y", `qu"o`), + `"x = y"`, `"qu\"o"`, + }, + { + "String method", + Any("name", name{"Ren", "Hoek"}), + `name`, `"Hoek, Ren"`, + }, + { + "struct", + Any("x", &struct{ A, b int }{A: 1, b: 2}), + `x`, `"&{A:1 b:2}"`, + }, + { + "TextMarshaler", + Any("t", text{"abc"}), + `t`, `"text{\"abc\"}"`, + }, + { + "TextMarshaler error", + Any("t", text{""}), + `t`, `"!ERROR:text: empty string"`, + }, + { + "nil value", + Any("a", nil), + `a`, `<nil>`, + }, + } { + t.Run(test.name, func(t *testing.T) { + for _, opts := range []struct { + name string + opts HandlerOptions + wantPrefix string + modKey func(string) string + }{ + { + "none", + HandlerOptions{}, + `time=2000-01-02T03:04:05.000Z level=INFO msg="a message"`, + func(s string) string { return s }, + }, + { + "replace", + HandlerOptions{ReplaceAttr: upperCaseKey}, + `TIME=2000-01-02T03:04:05.000Z LEVEL=INFO MSG="a message"`, + strings.ToUpper, + }, + } { + t.Run(opts.name, func(t *testing.T) { + var buf bytes.Buffer + h := NewTextHandler(&buf, &opts.opts) + r := NewRecord(testTime, LevelInfo, "a message", 0) + r.AddAttrs(test.attr) + if err := h.Handle(context.Background(), r); err != nil { + t.Fatal(err) + } + got := buf.String() + // Remove final newline. + got = got[:len(got)-1] + want := opts.wantPrefix + " " + opts.modKey(test.wantKey) + "=" + test.wantVal + if got != want { + t.Errorf("\ngot %s\nwant %s", got, want) + } + }) + } + }) + } +} + +// for testing fmt.Sprint +type name struct { + First, Last string +} + +func (n name) String() string { return n.Last + ", " + n.First } + +// for testing TextMarshaler +type text struct { + s string +} + +func (t text) String() string { return t.s } // should be ignored + +func (t text) MarshalText() ([]byte, error) { + if t.s == "" { + return nil, errors.New("text: empty string") + } + return []byte(fmt.Sprintf("text{%q}", t.s)), nil +} + +func TestTextHandlerPreformatted(t *testing.T) { + var buf bytes.Buffer + var h Handler = NewTextHandler(&buf, nil) + h = h.WithAttrs([]Attr{Duration("dur", time.Minute), Bool("b", true)}) + // Also test omitting time. + r := NewRecord(time.Time{}, 0 /* 0 Level is INFO */, "m", 0) + r.AddAttrs(Int("a", 1)) + if err := h.Handle(context.Background(), r); err != nil { + t.Fatal(err) + } + got := strings.TrimSuffix(buf.String(), "\n") + want := `level=INFO msg=m dur=1m0s b=true a=1` + if got != want { + t.Errorf("got %s, want %s", got, want) + } +} + +func TestTextHandlerAlloc(t *testing.T) { + testenv.SkipIfOptimizationOff(t) + r := NewRecord(time.Now(), LevelInfo, "msg", 0) + for i := 0; i < 10; i++ { + r.AddAttrs(Int("x = y", i)) + } + var h Handler = NewTextHandler(io.Discard, nil) + wantAllocs(t, 0, func() { h.Handle(context.Background(), r) }) + + h = h.WithGroup("s") + r.AddAttrs(Group("g", Int("a", 1))) + wantAllocs(t, 0, func() { h.Handle(context.Background(), r) }) +} + +func TestNeedsQuoting(t *testing.T) { + for _, test := range []struct { + in string + want bool + }{ + {"", true}, + {"ab", false}, + {"a=b", true}, + {`"ab"`, true}, + {"\a\b", true}, + {"a\tb", true}, + {"µåπ", false}, + {"a b", true}, + {"badutf8\xF6", true}, + } { + got := needsQuoting(test.in) + if got != test.want { + t.Errorf("%q: got %t, want %t", test.in, got, test.want) + } + } +} diff --git a/src/log/slog/value.go b/src/log/slog/value.go new file mode 100644 index 0000000..224848f --- /dev/null +++ b/src/log/slog/value.go @@ -0,0 +1,520 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "fmt" + "math" + "runtime" + "slices" + "strconv" + "strings" + "time" + "unsafe" +) + +// A Value can represent any Go value, but unlike type any, +// it can represent most small values without an allocation. +// The zero Value corresponds to nil. +type Value struct { + _ [0]func() // disallow == + // num holds the value for Kinds Int64, Uint64, Float64, Bool and Duration, + // the string length for KindString, and nanoseconds since the epoch for KindTime. + num uint64 + // If any is of type Kind, then the value is in num as described above. + // If any is of type *time.Location, then the Kind is Time and time.Time value + // can be constructed from the Unix nanos in num and the location (monotonic time + // is not preserved). + // If any is of type stringptr, then the Kind is String and the string value + // consists of the length in num and the pointer in any. + // Otherwise, the Kind is Any and any is the value. + // (This implies that Attrs cannot store values of type Kind, *time.Location + // or stringptr.) + any any +} + +type ( + stringptr *byte // used in Value.any when the Value is a string + groupptr *Attr // used in Value.any when the Value is a []Attr +) + +// Kind is the kind of a Value. +type Kind int + +// The following list is sorted alphabetically, but it's also important that +// KindAny is 0 so that a zero Value represents nil. + +const ( + KindAny Kind = iota + KindBool + KindDuration + KindFloat64 + KindInt64 + KindString + KindTime + KindUint64 + KindGroup + KindLogValuer +) + +var kindStrings = []string{ + "Any", + "Bool", + "Duration", + "Float64", + "Int64", + "String", + "Time", + "Uint64", + "Group", + "LogValuer", +} + +func (k Kind) String() string { + if k >= 0 && int(k) < len(kindStrings) { + return kindStrings[k] + } + return "<unknown slog.Kind>" +} + +// Unexported version of Kind, just so we can store Kinds in Values. +// (No user-provided value has this type.) +type kind Kind + +// Kind returns v's Kind. +func (v Value) Kind() Kind { + switch x := v.any.(type) { + case Kind: + return x + case stringptr: + return KindString + case timeLocation: + return KindTime + case groupptr: + return KindGroup + case LogValuer: + return KindLogValuer + case kind: // a kind is just a wrapper for a Kind + return KindAny + default: + return KindAny + } +} + +//////////////// Constructors + +// StringValue returns a new Value for a string. +func StringValue(value string) Value { + return Value{num: uint64(len(value)), any: stringptr(unsafe.StringData(value))} +} + +// IntValue returns a Value for an int. +func IntValue(v int) Value { + return Int64Value(int64(v)) +} + +// Int64Value returns a Value for an int64. +func Int64Value(v int64) Value { + return Value{num: uint64(v), any: KindInt64} +} + +// Uint64Value returns a Value for a uint64. +func Uint64Value(v uint64) Value { + return Value{num: v, any: KindUint64} +} + +// Float64Value returns a Value for a floating-point number. +func Float64Value(v float64) Value { + return Value{num: math.Float64bits(v), any: KindFloat64} +} + +// BoolValue returns a Value for a bool. +func BoolValue(v bool) Value { + u := uint64(0) + if v { + u = 1 + } + return Value{num: u, any: KindBool} +} + +// Unexported version of *time.Location, just so we can store *time.Locations in +// Values. (No user-provided value has this type.) +type timeLocation *time.Location + +// TimeValue returns a Value for a time.Time. +// It discards the monotonic portion. +func TimeValue(v time.Time) Value { + if v.IsZero() { + // UnixNano on the zero time is undefined, so represent the zero time + // with a nil *time.Location instead. time.Time.Location method never + // returns nil, so a Value with any == timeLocation(nil) cannot be + // mistaken for any other Value, time.Time or otherwise. + return Value{any: timeLocation(nil)} + } + return Value{num: uint64(v.UnixNano()), any: timeLocation(v.Location())} +} + +// DurationValue returns a Value for a time.Duration. +func DurationValue(v time.Duration) Value { + return Value{num: uint64(v.Nanoseconds()), any: KindDuration} +} + +// GroupValue returns a new Value for a list of Attrs. +// The caller must not subsequently mutate the argument slice. +func GroupValue(as ...Attr) Value { + // Remove empty groups. + // It is simpler overall to do this at construction than + // to check each Group recursively for emptiness. + if n := countEmptyGroups(as); n > 0 { + as2 := make([]Attr, 0, len(as)-n) + for _, a := range as { + if !a.Value.isEmptyGroup() { + as2 = append(as2, a) + } + } + as = as2 + } + return Value{num: uint64(len(as)), any: groupptr(unsafe.SliceData(as))} +} + +// countEmptyGroups returns the number of empty group values in its argument. +func countEmptyGroups(as []Attr) int { + n := 0 + for _, a := range as { + if a.Value.isEmptyGroup() { + n++ + } + } + return n +} + +// AnyValue returns a Value for the supplied value. +// +// If the supplied value is of type Value, it is returned +// unmodified. +// +// Given a value of one of Go's predeclared string, bool, or +// (non-complex) numeric types, AnyValue returns a Value of kind +// String, Bool, Uint64, Int64, or Float64. The width of the +// original numeric type is not preserved. +// +// Given a time.Time or time.Duration value, AnyValue returns a Value of kind +// KindTime or KindDuration. The monotonic time is not preserved. +// +// For nil, or values of all other types, including named types whose +// underlying type is numeric, AnyValue returns a value of kind KindAny. +func AnyValue(v any) Value { + switch v := v.(type) { + case string: + return StringValue(v) + case int: + return Int64Value(int64(v)) + case uint: + return Uint64Value(uint64(v)) + case int64: + return Int64Value(v) + case uint64: + return Uint64Value(v) + case bool: + return BoolValue(v) + case time.Duration: + return DurationValue(v) + case time.Time: + return TimeValue(v) + case uint8: + return Uint64Value(uint64(v)) + case uint16: + return Uint64Value(uint64(v)) + case uint32: + return Uint64Value(uint64(v)) + case uintptr: + return Uint64Value(uint64(v)) + case int8: + return Int64Value(int64(v)) + case int16: + return Int64Value(int64(v)) + case int32: + return Int64Value(int64(v)) + case float64: + return Float64Value(v) + case float32: + return Float64Value(float64(v)) + case []Attr: + return GroupValue(v...) + case Kind: + return Value{any: kind(v)} + case Value: + return v + default: + return Value{any: v} + } +} + +//////////////// Accessors + +// Any returns v's value as an any. +func (v Value) Any() any { + switch v.Kind() { + case KindAny: + if k, ok := v.any.(kind); ok { + return Kind(k) + } + return v.any + case KindLogValuer: + return v.any + case KindGroup: + return v.group() + case KindInt64: + return int64(v.num) + case KindUint64: + return v.num + case KindFloat64: + return v.float() + case KindString: + return v.str() + case KindBool: + return v.bool() + case KindDuration: + return v.duration() + case KindTime: + return v.time() + default: + panic(fmt.Sprintf("bad kind: %s", v.Kind())) + } +} + +// String returns Value's value as a string, formatted like fmt.Sprint. Unlike +// the methods Int64, Float64, and so on, which panic if v is of the +// wrong kind, String never panics. +func (v Value) String() string { + if sp, ok := v.any.(stringptr); ok { + return unsafe.String(sp, v.num) + } + var buf []byte + return string(v.append(buf)) +} + +func (v Value) str() string { + return unsafe.String(v.any.(stringptr), v.num) +} + +// Int64 returns v's value as an int64. It panics +// if v is not a signed integer. +func (v Value) Int64() int64 { + if g, w := v.Kind(), KindInt64; g != w { + panic(fmt.Sprintf("Value kind is %s, not %s", g, w)) + } + return int64(v.num) +} + +// Uint64 returns v's value as a uint64. It panics +// if v is not an unsigned integer. +func (v Value) Uint64() uint64 { + if g, w := v.Kind(), KindUint64; g != w { + panic(fmt.Sprintf("Value kind is %s, not %s", g, w)) + } + return v.num +} + +// Bool returns v's value as a bool. It panics +// if v is not a bool. +func (v Value) Bool() bool { + if g, w := v.Kind(), KindBool; g != w { + panic(fmt.Sprintf("Value kind is %s, not %s", g, w)) + } + return v.bool() +} + +func (a Value) bool() bool { + return a.num == 1 +} + +// Duration returns v's value as a time.Duration. It panics +// if v is not a time.Duration. +func (a Value) Duration() time.Duration { + if g, w := a.Kind(), KindDuration; g != w { + panic(fmt.Sprintf("Value kind is %s, not %s", g, w)) + } + + return a.duration() +} + +func (a Value) duration() time.Duration { + return time.Duration(int64(a.num)) +} + +// Float64 returns v's value as a float64. It panics +// if v is not a float64. +func (v Value) Float64() float64 { + if g, w := v.Kind(), KindFloat64; g != w { + panic(fmt.Sprintf("Value kind is %s, not %s", g, w)) + } + + return v.float() +} + +func (a Value) float() float64 { + return math.Float64frombits(a.num) +} + +// Time returns v's value as a time.Time. It panics +// if v is not a time.Time. +func (v Value) Time() time.Time { + if g, w := v.Kind(), KindTime; g != w { + panic(fmt.Sprintf("Value kind is %s, not %s", g, w)) + } + return v.time() +} + +func (v Value) time() time.Time { + loc := v.any.(timeLocation) + if loc == nil { + return time.Time{} + } + return time.Unix(0, int64(v.num)).In(loc) +} + +// LogValuer returns v's value as a LogValuer. It panics +// if v is not a LogValuer. +func (v Value) LogValuer() LogValuer { + return v.any.(LogValuer) +} + +// Group returns v's value as a []Attr. +// It panics if v's Kind is not KindGroup. +func (v Value) Group() []Attr { + if sp, ok := v.any.(groupptr); ok { + return unsafe.Slice((*Attr)(sp), v.num) + } + panic("Group: bad kind") +} + +func (v Value) group() []Attr { + return unsafe.Slice((*Attr)(v.any.(groupptr)), v.num) +} + +//////////////// Other + +// Equal reports whether v and w represent the same Go value. +func (v Value) Equal(w Value) bool { + k1 := v.Kind() + k2 := w.Kind() + if k1 != k2 { + return false + } + switch k1 { + case KindInt64, KindUint64, KindBool, KindDuration: + return v.num == w.num + case KindString: + return v.str() == w.str() + case KindFloat64: + return v.float() == w.float() + case KindTime: + return v.time().Equal(w.time()) + case KindAny, KindLogValuer: + return v.any == w.any // may panic if non-comparable + case KindGroup: + return slices.EqualFunc(v.group(), w.group(), Attr.Equal) + default: + panic(fmt.Sprintf("bad kind: %s", k1)) + } +} + +// isEmptyGroup reports whether v is a group that has no attributes. +func (v Value) isEmptyGroup() bool { + if v.Kind() != KindGroup { + return false + } + // We do not need to recursively examine the group's Attrs for emptiness, + // because GroupValue removed them when the group was constructed, and + // groups are immutable. + return len(v.group()) == 0 +} + +// append appends a text representation of v to dst. +// v is formatted as with fmt.Sprint. +func (v Value) append(dst []byte) []byte { + switch v.Kind() { + case KindString: + return append(dst, v.str()...) + case KindInt64: + return strconv.AppendInt(dst, int64(v.num), 10) + case KindUint64: + return strconv.AppendUint(dst, v.num, 10) + case KindFloat64: + return strconv.AppendFloat(dst, v.float(), 'g', -1, 64) + case KindBool: + return strconv.AppendBool(dst, v.bool()) + case KindDuration: + return append(dst, v.duration().String()...) + case KindTime: + return append(dst, v.time().String()...) + case KindGroup: + return fmt.Append(dst, v.group()) + case KindAny, KindLogValuer: + return fmt.Append(dst, v.any) + default: + panic(fmt.Sprintf("bad kind: %s", v.Kind())) + } +} + +// A LogValuer is any Go value that can convert itself into a Value for logging. +// +// This mechanism may be used to defer expensive operations until they are +// needed, or to expand a single value into a sequence of components. +type LogValuer interface { + LogValue() Value +} + +const maxLogValues = 100 + +// Resolve repeatedly calls LogValue on v while it implements LogValuer, +// and returns the result. +// If v resolves to a group, the group's attributes' values are not recursively +// resolved. +// If the number of LogValue calls exceeds a threshold, a Value containing an +// error is returned. +// Resolve's return value is guaranteed not to be of Kind KindLogValuer. +func (v Value) Resolve() (rv Value) { + orig := v + defer func() { + if r := recover(); r != nil { + rv = AnyValue(fmt.Errorf("LogValue panicked\n%s", stack(3, 5))) + } + }() + + for i := 0; i < maxLogValues; i++ { + if v.Kind() != KindLogValuer { + return v + } + v = v.LogValuer().LogValue() + } + err := fmt.Errorf("LogValue called too many times on Value of type %T", orig.Any()) + return AnyValue(err) +} + +func stack(skip, nFrames int) string { + pcs := make([]uintptr, nFrames+1) + n := runtime.Callers(skip+1, pcs) + if n == 0 { + return "(no stack)" + } + frames := runtime.CallersFrames(pcs[:n]) + var b strings.Builder + i := 0 + for { + frame, more := frames.Next() + fmt.Fprintf(&b, "called from %s (%s:%d)\n", frame.Function, frame.File, frame.Line) + if !more { + break + } + i++ + if i >= nFrames { + fmt.Fprintf(&b, "(rest of stack elided)\n") + break + } + } + return b.String() +} diff --git a/src/log/slog/value_access_benchmark_test.go b/src/log/slog/value_access_benchmark_test.go new file mode 100644 index 0000000..3bd7071 --- /dev/null +++ b/src/log/slog/value_access_benchmark_test.go @@ -0,0 +1,215 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Benchmark for accessing Value values. + +package slog + +import ( + "testing" + "time" +) + +// The "As" form is the slowest. +// The switch-panic and visitor times are almost the same. +// BenchmarkDispatch/switch-checked-8 8669427 137.7 ns/op +// BenchmarkDispatch/As-8 8212087 145.3 ns/op +// BenchmarkDispatch/Visit-8 8926146 135.3 ns/op +func BenchmarkDispatch(b *testing.B) { + vs := []Value{ + Int64Value(32768), + Uint64Value(0xfacecafe), + StringValue("anything"), + BoolValue(true), + Float64Value(1.2345), + DurationValue(time.Second), + AnyValue(b), + } + var ( + ii int64 + s string + bb bool + u uint64 + d time.Duration + f float64 + a any + ) + b.Run("switch-checked", func(b *testing.B) { + for i := 0; i < b.N; i++ { + for _, v := range vs { + switch v.Kind() { + case KindString: + s = v.String() + case KindInt64: + ii = v.Int64() + case KindUint64: + u = v.Uint64() + case KindFloat64: + f = v.Float64() + case KindBool: + bb = v.Bool() + case KindDuration: + d = v.Duration() + case KindAny: + a = v.Any() + default: + panic("bad kind") + } + } + } + _ = ii + _ = s + _ = bb + _ = u + _ = d + _ = f + _ = a + + }) + b.Run("As", func(b *testing.B) { + for i := 0; i < b.N; i++ { + for _, kv := range vs { + if v, ok := kv.AsString(); ok { + s = v + } else if v, ok := kv.AsInt64(); ok { + ii = v + } else if v, ok := kv.AsUint64(); ok { + u = v + } else if v, ok := kv.AsFloat64(); ok { + f = v + } else if v, ok := kv.AsBool(); ok { + bb = v + } else if v, ok := kv.AsDuration(); ok { + d = v + } else if v, ok := kv.AsAny(); ok { + a = v + } else { + panic("bad kind") + } + } + } + _ = ii + _ = s + _ = bb + _ = u + _ = d + _ = f + _ = a + }) + + b.Run("Visit", func(b *testing.B) { + v := &setVisitor{} + b.ResetTimer() + for i := 0; i < b.N; i++ { + for _, kv := range vs { + kv.Visit(v) + } + } + }) +} + +type setVisitor struct { + i int64 + s string + b bool + u uint64 + d time.Duration + f float64 + a any +} + +func (v *setVisitor) String(s string) { v.s = s } +func (v *setVisitor) Int64(i int64) { v.i = i } +func (v *setVisitor) Uint64(x uint64) { v.u = x } +func (v *setVisitor) Float64(x float64) { v.f = x } +func (v *setVisitor) Bool(x bool) { v.b = x } +func (v *setVisitor) Duration(x time.Duration) { v.d = x } +func (v *setVisitor) Any(x any) { v.a = x } + +// When dispatching on all types, the "As" functions are slightly slower +// than switching on the kind and then calling a function that checks +// the kind again. See BenchmarkDispatch above. + +func (a Value) AsString() (string, bool) { + if a.Kind() == KindString { + return a.str(), true + } + return "", false +} + +func (a Value) AsInt64() (int64, bool) { + if a.Kind() == KindInt64 { + return int64(a.num), true + } + return 0, false +} + +func (a Value) AsUint64() (uint64, bool) { + if a.Kind() == KindUint64 { + return a.num, true + } + return 0, false +} + +func (a Value) AsFloat64() (float64, bool) { + if a.Kind() == KindFloat64 { + return a.float(), true + } + return 0, false +} + +func (a Value) AsBool() (bool, bool) { + if a.Kind() == KindBool { + return a.bool(), true + } + return false, false +} + +func (a Value) AsDuration() (time.Duration, bool) { + if a.Kind() == KindDuration { + return a.duration(), true + } + return 0, false +} + +func (a Value) AsAny() (any, bool) { + if a.Kind() == KindAny { + return a.any, true + } + return nil, false +} + +// Problem: adding a type means adding a method, which is a breaking change. +// Using an unexported method to force embedding will make programs compile, +// But they will panic at runtime when we call the new method. +type Visitor interface { + String(string) + Int64(int64) + Uint64(uint64) + Float64(float64) + Bool(bool) + Duration(time.Duration) + Any(any) +} + +func (a Value) Visit(v Visitor) { + switch a.Kind() { + case KindString: + v.String(a.str()) + case KindInt64: + v.Int64(int64(a.num)) + case KindUint64: + v.Uint64(a.num) + case KindBool: + v.Bool(a.bool()) + case KindFloat64: + v.Float64(a.float()) + case KindDuration: + v.Duration(a.duration()) + case KindAny: + v.Any(a.any) + default: + panic("bad kind") + } +} diff --git a/src/log/slog/value_test.go b/src/log/slog/value_test.go new file mode 100644 index 0000000..923a4e0 --- /dev/null +++ b/src/log/slog/value_test.go @@ -0,0 +1,276 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package slog + +import ( + "fmt" + "reflect" + "strings" + "testing" + "time" + "unsafe" +) + +func TestKindString(t *testing.T) { + if got, want := KindGroup.String(), "Group"; got != want { + t.Errorf("got %q, want %q", got, want) + } +} + +func TestValueEqual(t *testing.T) { + var x, y int + vals := []Value{ + {}, + Int64Value(1), + Int64Value(2), + Float64Value(3.5), + Float64Value(3.7), + BoolValue(true), + BoolValue(false), + TimeValue(testTime), + AnyValue(&x), + AnyValue(&y), + GroupValue(Bool("b", true), Int("i", 3)), + } + for i, v1 := range vals { + for j, v2 := range vals { + got := v1.Equal(v2) + want := i == j + if got != want { + t.Errorf("%v.Equal(%v): got %t, want %t", v1, v2, got, want) + } + } + } +} + +func panics(f func()) (b bool) { + defer func() { + if x := recover(); x != nil { + b = true + } + }() + f() + return false +} + +func TestValueString(t *testing.T) { + for _, test := range []struct { + v Value + want string + }{ + {Int64Value(-3), "-3"}, + {Uint64Value(1), "1"}, + {Float64Value(.15), "0.15"}, + {BoolValue(true), "true"}, + {StringValue("foo"), "foo"}, + {TimeValue(testTime), "2000-01-02 03:04:05 +0000 UTC"}, + {AnyValue(time.Duration(3 * time.Second)), "3s"}, + {GroupValue(Int("a", 1), Bool("b", true)), "[a=1 b=true]"}, + } { + if got := test.v.String(); got != test.want { + t.Errorf("%#v:\ngot %q\nwant %q", test.v, got, test.want) + } + } +} + +func TestValueNoAlloc(t *testing.T) { + // Assign values just to make sure the compiler doesn't optimize away the statements. + var ( + i int64 + u uint64 + f float64 + b bool + s string + x any + p = &i + d time.Duration + tm time.Time + ) + a := int(testing.AllocsPerRun(5, func() { + i = Int64Value(1).Int64() + u = Uint64Value(1).Uint64() + f = Float64Value(1).Float64() + b = BoolValue(true).Bool() + s = StringValue("foo").String() + d = DurationValue(d).Duration() + tm = TimeValue(testTime).Time() + x = AnyValue(p).Any() + })) + if a != 0 { + t.Errorf("got %d allocs, want zero", a) + } + _ = u + _ = f + _ = b + _ = s + _ = x + _ = tm +} + +func TestAnyLevelAlloc(t *testing.T) { + // Because typical Levels are small integers, + // they are zero-alloc. + var a Value + x := LevelDebug + 100 + wantAllocs(t, 0, func() { a = AnyValue(x) }) + _ = a +} + +func TestAnyValue(t *testing.T) { + for _, test := range []struct { + in any + want Value + }{ + {1, IntValue(1)}, + {1.5, Float64Value(1.5)}, + {float32(2.5), Float64Value(2.5)}, + {"s", StringValue("s")}, + {true, BoolValue(true)}, + {testTime, TimeValue(testTime)}, + {time.Hour, DurationValue(time.Hour)}, + {[]Attr{Int("i", 3)}, GroupValue(Int("i", 3))}, + {IntValue(4), IntValue(4)}, + {uint(2), Uint64Value(2)}, + {uint8(3), Uint64Value(3)}, + {uint16(4), Uint64Value(4)}, + {uint32(5), Uint64Value(5)}, + {uint64(6), Uint64Value(6)}, + {uintptr(7), Uint64Value(7)}, + {int8(8), Int64Value(8)}, + {int16(9), Int64Value(9)}, + {int32(10), Int64Value(10)}, + {int64(11), Int64Value(11)}, + } { + got := AnyValue(test.in) + if !got.Equal(test.want) { + t.Errorf("%v (%[1]T): got %v (kind %s), want %v (kind %s)", + test.in, got, got.Kind(), test.want, test.want.Kind()) + } + } +} + +func TestValueAny(t *testing.T) { + for _, want := range []any{ + nil, + LevelDebug + 100, + time.UTC, // time.Locations treated specially... + KindBool, // ...as are Kinds + []Attr{Int("a", 1)}, + int64(2), + uint64(3), + true, + time.Minute, + time.Time{}, + 3.14, + } { + v := AnyValue(want) + got := v.Any() + if !reflect.DeepEqual(got, want) { + t.Errorf("got %v, want %v", got, want) + } + } +} + +func TestLogValue(t *testing.T) { + want := "replaced" + r := &replace{StringValue(want)} + v := AnyValue(r) + if g, w := v.Kind(), KindLogValuer; g != w { + t.Errorf("got %s, want %s", g, w) + } + got := v.LogValuer().LogValue().Any() + if got != want { + t.Errorf("got %#v, want %#v", got, want) + } + + // Test Resolve. + got = v.Resolve().Any() + if got != want { + t.Errorf("got %#v, want %#v", got, want) + } + + // Test Resolve max iteration. + r.v = AnyValue(r) // create a cycle + got = AnyValue(r).Resolve().Any() + if _, ok := got.(error); !ok { + t.Errorf("expected error, got %T", got) + } + + // Groups are not recursively resolved. + c := Any("c", &replace{StringValue("d")}) + v = AnyValue(&replace{GroupValue(Int("a", 1), Group("b", c))}) + got2 := v.Resolve().Any().([]Attr) + want2 := []Attr{Int("a", 1), Group("b", c)} + if !attrsEqual(got2, want2) { + t.Errorf("got %v, want %v", got2, want2) + } + + // Verify that panics in Resolve are caught and turn into errors. + v = AnyValue(panickingLogValue{}) + got = v.Resolve().Any() + gotErr, ok := got.(error) + if !ok { + t.Errorf("expected error, got %T", got) + } + // The error should provide some context information. + // We'll just check that this function name appears in it. + if got, want := gotErr.Error(), "TestLogValue"; !strings.Contains(got, want) { + t.Errorf("got %q, want substring %q", got, want) + } +} + +func TestZeroTime(t *testing.T) { + z := time.Time{} + got := TimeValue(z).Time() + if !got.IsZero() { + t.Errorf("got %s (%#[1]v), not zero time (%#v)", got, z) + } +} + +func TestEmptyGroup(t *testing.T) { + g := GroupValue( + Int("a", 1), + Group("g1", Group("g2")), + Group("g3", Group("g4", Int("b", 2)))) + got := g.Group() + want := []Attr{Int("a", 1), Group("g3", Group("g4", Int("b", 2)))} + if !attrsEqual(got, want) { + t.Errorf("\ngot %v\nwant %v", got, want) + } +} + +type replace struct { + v Value +} + +func (r *replace) LogValue() Value { return r.v } + +type panickingLogValue struct{} + +func (panickingLogValue) LogValue() Value { panic("bad") } + +// A Value with "unsafe" strings is significantly faster: +// safe: 1785 ns/op, 0 allocs +// unsafe: 690 ns/op, 0 allocs + +// Run this with and without -tags unsafe_kvs to compare. +func BenchmarkUnsafeStrings(b *testing.B) { + b.ReportAllocs() + dst := make([]Value, 100) + src := make([]Value, len(dst)) + b.Logf("Value size = %d", unsafe.Sizeof(Value{})) + for i := range src { + src[i] = StringValue(fmt.Sprintf("string#%d", i)) + } + b.ResetTimer() + var d string + for i := 0; i < b.N; i++ { + copy(dst, src) + for _, a := range dst { + d = a.String() + } + } + _ = d +} diff --git a/src/log/syslog/doc.go b/src/log/syslog/doc.go new file mode 100644 index 0000000..9a33eeb --- /dev/null +++ b/src/log/syslog/doc.go @@ -0,0 +1,24 @@ +// Copyright 2012 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package syslog provides a simple interface to the system log +// service. It can send messages to the syslog daemon using UNIX +// domain sockets, UDP or TCP. +// +// Only one call to Dial is necessary. On write failures, +// the syslog client will attempt to reconnect to the server +// and write again. +// +// The syslog package is frozen and is not accepting new features. +// Some external packages provide more functionality. See: +// +// https://godoc.org/?q=syslog +package syslog + +// BUG(brainman): This package is not implemented on Windows. As the +// syslog package is frozen, Windows users are encouraged to +// use a package outside of the standard library. For background, +// see https://golang.org/issue/1108. + +// BUG(akumar): This package is not implemented on Plan 9. diff --git a/src/log/syslog/example_test.go b/src/log/syslog/example_test.go new file mode 100644 index 0000000..4df29c0 --- /dev/null +++ b/src/log/syslog/example_test.go @@ -0,0 +1,23 @@ +// Copyright 2016 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +//go:build !windows && !plan9 + +package syslog_test + +import ( + "fmt" + "log" + "log/syslog" +) + +func ExampleDial() { + sysLog, err := syslog.Dial("tcp", "localhost:1234", + syslog.LOG_WARNING|syslog.LOG_DAEMON, "demotag") + if err != nil { + log.Fatal(err) + } + fmt.Fprintf(sysLog, "This is a daemon warning with demotag.") + sysLog.Emerg("And this is a daemon emergency with demotag.") +} diff --git a/src/log/syslog/syslog.go b/src/log/syslog/syslog.go new file mode 100644 index 0000000..03e5263 --- /dev/null +++ b/src/log/syslog/syslog.go @@ -0,0 +1,318 @@ +// Copyright 2009 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +//go:build !windows && !plan9 + +package syslog + +import ( + "errors" + "fmt" + "log" + "net" + "os" + "strings" + "sync" + "time" +) + +// The Priority is a combination of the syslog facility and +// severity. For example, LOG_ALERT | LOG_FTP sends an alert severity +// message from the FTP facility. The default severity is LOG_EMERG; +// the default facility is LOG_KERN. +type Priority int + +const severityMask = 0x07 +const facilityMask = 0xf8 + +const ( + // Severity. + + // From /usr/include/sys/syslog.h. + // These are the same on Linux, BSD, and OS X. + LOG_EMERG Priority = iota + LOG_ALERT + LOG_CRIT + LOG_ERR + LOG_WARNING + LOG_NOTICE + LOG_INFO + LOG_DEBUG +) + +const ( + // Facility. + + // From /usr/include/sys/syslog.h. + // These are the same up to LOG_FTP on Linux, BSD, and OS X. + LOG_KERN Priority = iota << 3 + LOG_USER + LOG_MAIL + LOG_DAEMON + LOG_AUTH + LOG_SYSLOG + LOG_LPR + LOG_NEWS + LOG_UUCP + LOG_CRON + LOG_AUTHPRIV + LOG_FTP + _ // unused + _ // unused + _ // unused + _ // unused + LOG_LOCAL0 + LOG_LOCAL1 + LOG_LOCAL2 + LOG_LOCAL3 + LOG_LOCAL4 + LOG_LOCAL5 + LOG_LOCAL6 + LOG_LOCAL7 +) + +// A Writer is a connection to a syslog server. +type Writer struct { + priority Priority + tag string + hostname string + network string + raddr string + + mu sync.Mutex // guards conn + conn serverConn +} + +// This interface and the separate syslog_unix.go file exist for +// Solaris support as implemented by gccgo. On Solaris you cannot +// simply open a TCP connection to the syslog daemon. The gccgo +// sources have a syslog_solaris.go file that implements unixSyslog to +// return a type that satisfies this interface and simply calls the C +// library syslog function. +type serverConn interface { + writeString(p Priority, hostname, tag, s, nl string) error + close() error +} + +type netConn struct { + local bool + conn net.Conn +} + +// New establishes a new connection to the system log daemon. Each +// write to the returned writer sends a log message with the given +// priority (a combination of the syslog facility and severity) and +// prefix tag. If tag is empty, the os.Args[0] is used. +func New(priority Priority, tag string) (*Writer, error) { + return Dial("", "", priority, tag) +} + +// Dial establishes a connection to a log daemon by connecting to +// address raddr on the specified network. Each write to the returned +// writer sends a log message with the facility and severity +// (from priority) and tag. If tag is empty, the os.Args[0] is used. +// If network is empty, Dial will connect to the local syslog server. +// Otherwise, see the documentation for net.Dial for valid values +// of network and raddr. +func Dial(network, raddr string, priority Priority, tag string) (*Writer, error) { + if priority < 0 || priority > LOG_LOCAL7|LOG_DEBUG { + return nil, errors.New("log/syslog: invalid priority") + } + + if tag == "" { + tag = os.Args[0] + } + hostname, _ := os.Hostname() + + w := &Writer{ + priority: priority, + tag: tag, + hostname: hostname, + network: network, + raddr: raddr, + } + + w.mu.Lock() + defer w.mu.Unlock() + + err := w.connect() + if err != nil { + return nil, err + } + return w, err +} + +// connect makes a connection to the syslog server. +// It must be called with w.mu held. +func (w *Writer) connect() (err error) { + if w.conn != nil { + // ignore err from close, it makes sense to continue anyway + w.conn.close() + w.conn = nil + } + + if w.network == "" { + w.conn, err = unixSyslog() + if w.hostname == "" { + w.hostname = "localhost" + } + } else { + var c net.Conn + c, err = net.Dial(w.network, w.raddr) + if err == nil { + w.conn = &netConn{ + conn: c, + local: w.network == "unixgram" || w.network == "unix", + } + if w.hostname == "" { + w.hostname = c.LocalAddr().String() + } + } + } + return +} + +// Write sends a log message to the syslog daemon. +func (w *Writer) Write(b []byte) (int, error) { + return w.writeAndRetry(w.priority, string(b)) +} + +// Close closes a connection to the syslog daemon. +func (w *Writer) Close() error { + w.mu.Lock() + defer w.mu.Unlock() + + if w.conn != nil { + err := w.conn.close() + w.conn = nil + return err + } + return nil +} + +// Emerg logs a message with severity LOG_EMERG, ignoring the severity +// passed to New. +func (w *Writer) Emerg(m string) error { + _, err := w.writeAndRetry(LOG_EMERG, m) + return err +} + +// Alert logs a message with severity LOG_ALERT, ignoring the severity +// passed to New. +func (w *Writer) Alert(m string) error { + _, err := w.writeAndRetry(LOG_ALERT, m) + return err +} + +// Crit logs a message with severity LOG_CRIT, ignoring the severity +// passed to New. +func (w *Writer) Crit(m string) error { + _, err := w.writeAndRetry(LOG_CRIT, m) + return err +} + +// Err logs a message with severity LOG_ERR, ignoring the severity +// passed to New. +func (w *Writer) Err(m string) error { + _, err := w.writeAndRetry(LOG_ERR, m) + return err +} + +// Warning logs a message with severity LOG_WARNING, ignoring the +// severity passed to New. +func (w *Writer) Warning(m string) error { + _, err := w.writeAndRetry(LOG_WARNING, m) + return err +} + +// Notice logs a message with severity LOG_NOTICE, ignoring the +// severity passed to New. +func (w *Writer) Notice(m string) error { + _, err := w.writeAndRetry(LOG_NOTICE, m) + return err +} + +// Info logs a message with severity LOG_INFO, ignoring the severity +// passed to New. +func (w *Writer) Info(m string) error { + _, err := w.writeAndRetry(LOG_INFO, m) + return err +} + +// Debug logs a message with severity LOG_DEBUG, ignoring the severity +// passed to New. +func (w *Writer) Debug(m string) error { + _, err := w.writeAndRetry(LOG_DEBUG, m) + return err +} + +func (w *Writer) writeAndRetry(p Priority, s string) (int, error) { + pr := (w.priority & facilityMask) | (p & severityMask) + + w.mu.Lock() + defer w.mu.Unlock() + + if w.conn != nil { + if n, err := w.write(pr, s); err == nil { + return n, nil + } + } + if err := w.connect(); err != nil { + return 0, err + } + return w.write(pr, s) +} + +// write generates and writes a syslog formatted string. The +// format is as follows: <PRI>TIMESTAMP HOSTNAME TAG[PID]: MSG +func (w *Writer) write(p Priority, msg string) (int, error) { + // ensure it ends in a \n + nl := "" + if !strings.HasSuffix(msg, "\n") { + nl = "\n" + } + + err := w.conn.writeString(p, w.hostname, w.tag, msg, nl) + if err != nil { + return 0, err + } + // Note: return the length of the input, not the number of + // bytes printed by Fprintf, because this must behave like + // an io.Writer. + return len(msg), nil +} + +func (n *netConn) writeString(p Priority, hostname, tag, msg, nl string) error { + if n.local { + // Compared to the network form below, the changes are: + // 1. Use time.Stamp instead of time.RFC3339. + // 2. Drop the hostname field from the Fprintf. + timestamp := time.Now().Format(time.Stamp) + _, err := fmt.Fprintf(n.conn, "<%d>%s %s[%d]: %s%s", + p, timestamp, + tag, os.Getpid(), msg, nl) + return err + } + timestamp := time.Now().Format(time.RFC3339) + _, err := fmt.Fprintf(n.conn, "<%d>%s %s %s[%d]: %s%s", + p, timestamp, hostname, + tag, os.Getpid(), msg, nl) + return err +} + +func (n *netConn) close() error { + return n.conn.Close() +} + +// NewLogger creates a log.Logger whose output is written to the +// system log service with the specified priority, a combination of +// the syslog facility and severity. The logFlag argument is the flag +// set passed through to log.New to create the Logger. +func NewLogger(p Priority, logFlag int) (*log.Logger, error) { + s, err := New(p, "") + if err != nil { + return nil, err + } + return log.New(s, "", logFlag), nil +} diff --git a/src/log/syslog/syslog_test.go b/src/log/syslog/syslog_test.go new file mode 100644 index 0000000..cec225f --- /dev/null +++ b/src/log/syslog/syslog_test.go @@ -0,0 +1,432 @@ +// Copyright 2009 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +//go:build !windows && !plan9 && !js && !wasip1 + +package syslog + +import ( + "bufio" + "fmt" + "io" + "net" + "os" + "path/filepath" + "runtime" + "sync" + "testing" + "time" +) + +func runPktSyslog(c net.PacketConn, done chan<- string) { + var buf [4096]byte + var rcvd string + ct := 0 + for { + var n int + var err error + + c.SetReadDeadline(time.Now().Add(100 * time.Millisecond)) + n, _, err = c.ReadFrom(buf[:]) + rcvd += string(buf[:n]) + if err != nil { + if oe, ok := err.(*net.OpError); ok { + if ct < 3 && oe.Temporary() { + ct++ + continue + } + } + break + } + } + c.Close() + done <- rcvd +} + +var crashy = false + +func testableNetwork(network string) bool { + switch network { + case "unix", "unixgram": + switch runtime.GOOS { + case "ios", "android": + return false + } + } + return true +} + +func runStreamSyslog(l net.Listener, done chan<- string, wg *sync.WaitGroup) { + for { + var c net.Conn + var err error + if c, err = l.Accept(); err != nil { + return + } + wg.Add(1) + go func(c net.Conn) { + defer wg.Done() + c.SetReadDeadline(time.Now().Add(5 * time.Second)) + b := bufio.NewReader(c) + for ct := 1; !crashy || ct&7 != 0; ct++ { + s, err := b.ReadString('\n') + if err != nil { + break + } + done <- s + } + c.Close() + }(c) + } +} + +func startServer(t *testing.T, n, la string, done chan<- string) (addr string, sock io.Closer, wg *sync.WaitGroup) { + if n == "udp" || n == "tcp" { + la = "127.0.0.1:0" + } else { + // unix and unixgram: choose an address if none given. + if la == "" { + // The address must be short to fit in the sun_path field of the + // sockaddr_un passed to the underlying system calls, so we use + // os.MkdirTemp instead of t.TempDir: t.TempDir generally includes all or + // part of the test name in the directory, which can be much more verbose + // and risks running up against the limit. + dir, err := os.MkdirTemp("", "") + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + if err := os.RemoveAll(dir); err != nil { + t.Errorf("failed to remove socket temp directory: %v", err) + } + }) + la = filepath.Join(dir, "sock") + } + } + + wg = new(sync.WaitGroup) + if n == "udp" || n == "unixgram" { + l, e := net.ListenPacket(n, la) + if e != nil { + t.Helper() + t.Fatalf("startServer failed: %v", e) + } + addr = l.LocalAddr().String() + sock = l + wg.Add(1) + go func() { + defer wg.Done() + runPktSyslog(l, done) + }() + } else { + l, e := net.Listen(n, la) + if e != nil { + t.Helper() + t.Fatalf("startServer failed: %v", e) + } + addr = l.Addr().String() + sock = l + wg.Add(1) + go func() { + defer wg.Done() + runStreamSyslog(l, done, wg) + }() + } + return +} + +func TestWithSimulated(t *testing.T) { + t.Parallel() + + msg := "Test 123" + for _, tr := range []string{"unix", "unixgram", "udp", "tcp"} { + if !testableNetwork(tr) { + continue + } + + tr := tr + t.Run(tr, func(t *testing.T) { + t.Parallel() + + done := make(chan string) + addr, sock, srvWG := startServer(t, tr, "", done) + defer srvWG.Wait() + defer sock.Close() + if tr == "unix" || tr == "unixgram" { + defer os.Remove(addr) + } + s, err := Dial(tr, addr, LOG_INFO|LOG_USER, "syslog_test") + if err != nil { + t.Fatalf("Dial() failed: %v", err) + } + err = s.Info(msg) + if err != nil { + t.Fatalf("log failed: %v", err) + } + check(t, msg, <-done, tr) + s.Close() + }) + } +} + +func TestFlap(t *testing.T) { + net := "unix" + if !testableNetwork(net) { + t.Skipf("skipping on %s/%s; 'unix' is not supported", runtime.GOOS, runtime.GOARCH) + } + + done := make(chan string) + addr, sock, srvWG := startServer(t, net, "", done) + defer srvWG.Wait() + defer os.Remove(addr) + defer sock.Close() + + s, err := Dial(net, addr, LOG_INFO|LOG_USER, "syslog_test") + if err != nil { + t.Fatalf("Dial() failed: %v", err) + } + msg := "Moo 2" + err = s.Info(msg) + if err != nil { + t.Fatalf("log failed: %v", err) + } + check(t, msg, <-done, net) + + // restart the server + if err := os.Remove(addr); err != nil { + t.Fatal(err) + } + _, sock2, srvWG2 := startServer(t, net, addr, done) + defer srvWG2.Wait() + defer sock2.Close() + + // and try retransmitting + msg = "Moo 3" + err = s.Info(msg) + if err != nil { + t.Fatalf("log failed: %v", err) + } + check(t, msg, <-done, net) + + s.Close() +} + +func TestNew(t *testing.T) { + if LOG_LOCAL7 != 23<<3 { + t.Fatalf("LOG_LOCAL7 has wrong value") + } + if testing.Short() { + // Depends on syslog daemon running, and sometimes it's not. + t.Skip("skipping syslog test during -short") + } + + s, err := New(LOG_INFO|LOG_USER, "the_tag") + if err != nil { + if err.Error() == "Unix syslog delivery error" { + t.Skip("skipping: syslogd not running") + } + t.Fatalf("New() failed: %s", err) + } + // Don't send any messages. + s.Close() +} + +func TestNewLogger(t *testing.T) { + if testing.Short() { + t.Skip("skipping syslog test during -short") + } + f, err := NewLogger(LOG_USER|LOG_INFO, 0) + if f == nil { + if err.Error() == "Unix syslog delivery error" { + t.Skip("skipping: syslogd not running") + } + t.Error(err) + } +} + +func TestDial(t *testing.T) { + if testing.Short() { + t.Skip("skipping syslog test during -short") + } + f, err := Dial("", "", (LOG_LOCAL7|LOG_DEBUG)+1, "syslog_test") + if f != nil { + t.Fatalf("Should have trapped bad priority") + } + f, err = Dial("", "", -1, "syslog_test") + if f != nil { + t.Fatalf("Should have trapped bad priority") + } + l, err := Dial("", "", LOG_USER|LOG_ERR, "syslog_test") + if err != nil { + if err.Error() == "Unix syslog delivery error" { + t.Skip("skipping: syslogd not running") + } + t.Fatalf("Dial() failed: %s", err) + } + l.Close() +} + +func check(t *testing.T, in, out, transport string) { + hostname, err := os.Hostname() + if err != nil { + t.Errorf("Error retrieving hostname: %v", err) + return + } + + if transport == "unixgram" || transport == "unix" { + var month, date, ts string + var pid int + tmpl := fmt.Sprintf("<%d>%%s %%s %%s syslog_test[%%d]: %s\n", LOG_USER+LOG_INFO, in) + n, err := fmt.Sscanf(out, tmpl, &month, &date, &ts, &pid) + if n != 4 || err != nil { + t.Errorf("Got %q, does not match template %q (%d %s)", out, tmpl, n, err) + } + return + } + + // Non-UNIX domain transports. + var parsedHostname, timestamp string + var pid int + tmpl := fmt.Sprintf("<%d>%%s %%s syslog_test[%%d]: %s\n", LOG_USER+LOG_INFO, in) + n, err := fmt.Sscanf(out, tmpl, ×tamp, &parsedHostname, &pid) + if n != 3 || err != nil { + t.Errorf("Got %q, does not match template %q (%d %s)", out, tmpl, n, err) + } + if hostname != parsedHostname { + t.Errorf("Hostname got %q want %q in %q", parsedHostname, hostname, out) + } +} + +func TestWrite(t *testing.T) { + t.Parallel() + + tests := []struct { + pri Priority + pre string + msg string + exp string + }{ + {LOG_USER | LOG_ERR, "syslog_test", "", "%s %s syslog_test[%d]: \n"}, + {LOG_USER | LOG_ERR, "syslog_test", "write test", "%s %s syslog_test[%d]: write test\n"}, + // Write should not add \n if there already is one + {LOG_USER | LOG_ERR, "syslog_test", "write test 2\n", "%s %s syslog_test[%d]: write test 2\n"}, + } + + if hostname, err := os.Hostname(); err != nil { + t.Fatalf("Error retrieving hostname") + } else { + for _, test := range tests { + done := make(chan string) + addr, sock, srvWG := startServer(t, "udp", "", done) + defer srvWG.Wait() + defer sock.Close() + l, err := Dial("udp", addr, test.pri, test.pre) + if err != nil { + t.Fatalf("syslog.Dial() failed: %v", err) + } + defer l.Close() + _, err = io.WriteString(l, test.msg) + if err != nil { + t.Fatalf("WriteString() failed: %v", err) + } + rcvd := <-done + test.exp = fmt.Sprintf("<%d>", test.pri) + test.exp + var parsedHostname, timestamp string + var pid int + if n, err := fmt.Sscanf(rcvd, test.exp, ×tamp, &parsedHostname, &pid); n != 3 || err != nil || hostname != parsedHostname { + t.Errorf("s.Info() = '%q', didn't match '%q' (%d %s)", rcvd, test.exp, n, err) + } + } + } +} + +func TestConcurrentWrite(t *testing.T) { + addr, sock, srvWG := startServer(t, "udp", "", make(chan string, 1)) + defer srvWG.Wait() + defer sock.Close() + w, err := Dial("udp", addr, LOG_USER|LOG_ERR, "how's it going?") + if err != nil { + t.Fatalf("syslog.Dial() failed: %v", err) + } + var wg sync.WaitGroup + for i := 0; i < 10; i++ { + wg.Add(1) + go func() { + defer wg.Done() + err := w.Info("test") + if err != nil { + t.Errorf("Info() failed: %v", err) + return + } + }() + } + wg.Wait() +} + +func TestConcurrentReconnect(t *testing.T) { + crashy = true + defer func() { crashy = false }() + + const N = 10 + const M = 100 + net := "unix" + if !testableNetwork(net) { + net = "tcp" + if !testableNetwork(net) { + t.Skipf("skipping on %s/%s; neither 'unix' or 'tcp' is supported", runtime.GOOS, runtime.GOARCH) + } + } + done := make(chan string, N*M) + addr, sock, srvWG := startServer(t, net, "", done) + if net == "unix" { + defer os.Remove(addr) + } + + // count all the messages arriving + count := make(chan int, 1) + go func() { + ct := 0 + for range done { + ct++ + // we are looking for 500 out of 1000 events + // here because lots of log messages are lost + // in buffers (kernel and/or bufio) + if ct > N*M/2 { + break + } + } + count <- ct + }() + + var wg sync.WaitGroup + wg.Add(N) + for i := 0; i < N; i++ { + go func() { + defer wg.Done() + w, err := Dial(net, addr, LOG_USER|LOG_ERR, "tag") + if err != nil { + t.Errorf("syslog.Dial() failed: %v", err) + return + } + defer w.Close() + for i := 0; i < M; i++ { + err := w.Info("test") + if err != nil { + t.Errorf("Info() failed: %v", err) + return + } + } + }() + } + wg.Wait() + sock.Close() + srvWG.Wait() + close(done) + + select { + case <-count: + case <-time.After(100 * time.Millisecond): + t.Error("timeout in concurrent reconnect") + } +} diff --git a/src/log/syslog/syslog_unix.go b/src/log/syslog/syslog_unix.go new file mode 100644 index 0000000..f9cdcdc --- /dev/null +++ b/src/log/syslog/syslog_unix.go @@ -0,0 +1,29 @@ +// Copyright 2009 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +//go:build !windows && !plan9 + +package syslog + +import ( + "errors" + "net" +) + +// unixSyslog opens a connection to the syslog daemon running on the +// local machine using a Unix domain socket. + +func unixSyslog() (conn serverConn, err error) { + logTypes := []string{"unixgram", "unix"} + logPaths := []string{"/dev/log", "/var/run/syslog", "/var/run/log"} + for _, network := range logTypes { + for _, path := range logPaths { + conn, err := net.Dial(network, path) + if err == nil { + return &netConn{conn: conn, local: true}, nil + } + } + } + return nil, errors.New("Unix syslog delivery error") +} |