diff --git a/README.md b/README.md index 9f477a5..856ff66 100644 --- a/README.md +++ b/README.md @@ -48,7 +48,7 @@ The timestamp `ts` is in seconds.microseconds since epoch (golang UnixMicro() sp Since 1.8 the Go Routine ID is present in json (`r` field) or colorized log output (for multi threaded server types). -Optional additional `KeyValue` pairs can be added to the base structure using the new `log.S` or passed to `log.LogRequest` using `log.Attr` and `log.Str`. +Optional additional `KeyValue` pairs can be added to the base structure using the new `log.S` or passed to `log.LogRequest` using `log.Any` and `log.Str`. Note that numbers, as well as arrays of any type and maps of string keys to any type are supported (but more expensive to serialize recursively). If console output is detected (and ConsoleColor is true, which is the default) or if ForceColor is set, colorized output similar to `logc` will be done instead of JSON. [levelsDemo/levels.go](levelsDemo/levels.go) produces the following output: @@ -58,7 +58,7 @@ When output is redirected, JSON output: {"ts":1689986143.463374,"level":"trace","r":1,"file":"levels.go","line":17,"msg":"This is a verbose message"} {"ts":1689986143.463378,"level":"info","r":1,"msg":"This an always printed, file:line omitted message"} {"ts":1689986143.463382,"level":"info","r":1,"file":"levels.go","line":19,"msg":"This is an info message with no attributes but with \"quotes\"..."} -{"ts":1689986143.463389,"level":"info","r":1,"file":"levels.go","line":20,"msg":"This is multi line\n\tstructured info message with 3 attributes","attr1":"value1","attr2":"42","attr3":"\"quoted\nvalue\""} +{"ts":1689986143.463389,"level":"info","r":1,"file":"levels.go","line":20,"msg":"This is multi line\n\tstructured info message with 3 attributes","attr1":"value1","attr2":42,"attr3":"\"quoted\nvalue\""} {"ts":1689986143.463396,"level":"warn","r":1,"file":"levels.go","line":22,"msg":"This is a warning message"} {"ts":1689986143.4634,"level":"err","r":1,"file":"levels.go","line":23,"msg":"This is an error message"} {"ts":1689986143.463403,"level":"crit","r":1,"file":"levels.go","line":24,"msg":"This is a critical message"} diff --git a/console_logging.go b/console_logging.go index 1ab3679..ba7583e 100644 --- a/console_logging.go +++ b/console_logging.go @@ -90,7 +90,7 @@ var ( // ConsoleLogging is a utility to check if the current logger output is a console (terminal). func ConsoleLogging() bool { - f, ok := jsonWriter.(*os.File) + f, ok := jWriter.w.(*os.File) if !ok { return false } diff --git a/http_logging_test.go b/http_logging_test.go index eca58e0..09558ab 100644 --- a/http_logging_test.go +++ b/http_logging_test.go @@ -30,7 +30,7 @@ func TestLogRequest(t *testing.T) { w.Flush() actual := b.String() //nolint: lll - expected := `{"level":"info","msg":"test1","method":"","url":"","proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","tls":"true","tls.peer_cn":"x\nyz","header.foo":"bar1,bar2"} + expected := `{"level":"info","msg":"test1","method":"","url":"","proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","tls":true,"tls.peer_cn":"x\nyz","header.foo":"bar1,bar2"} {"level":"info","msg":"test2","method":"","url":"","proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","extra1":"v1","extra2":"v2"} ` if actual != expected { diff --git a/logger.go b/logger.go index 0b688df..5499121 100644 --- a/logger.go +++ b/logger.go @@ -17,10 +17,14 @@ Fortio's log is simple logger built on top of go's default one with additional opinionated levels similar to glog but simpler to use and configure. See [Config] object for options like whether to include line number and file name of caller or not etc + +So far it's a "global" logger as in you just use the functions in the package directly (e.g log.S()) +and the configuration is global for the process. */ package log // import "fortio.org/log" import ( + "bytes" "flag" "fmt" "io" @@ -28,6 +32,8 @@ import ( "math" "os" "runtime" + "sort" + "strconv" "strings" "sync" "sync/atomic" @@ -173,6 +179,7 @@ func init() { } log.SetFlags(log.Ltime) SetColorMode() + jWriter.buf.Grow(2048) } func setLevel(lvl Level) { @@ -304,14 +311,24 @@ func Logf(lvl Level, format string, rest ...interface{}) { // Used when doing our own logging writing, in JSON/structured mode. var ( - jsonWriter io.Writer = os.Stderr - jsonWriterMutex sync.Mutex + jWriter = jsonWriter{w: os.Stderr, tsBuf: make([]byte, 0, 32)} ) +type jsonWriter struct { + w io.Writer + mutex sync.Mutex + buf bytes.Buffer + tsBuf []byte +} + func jsonWrite(msg string) { - jsonWriterMutex.Lock() - _, _ = jsonWriter.Write([]byte(msg)) // if we get errors while logging... can't quite ... log errors - jsonWriterMutex.Unlock() + jsonWriteBytes([]byte(msg)) +} + +func jsonWriteBytes(msg []byte) { + jWriter.mutex.Lock() + _, _ = jWriter.w.Write(msg) // if we get errors while logging... can't quite ... log errors + jWriter.mutex.Unlock() } // Converts a time.Time to a float64 timestamp (seconds since epoch at microsecond resolution). @@ -351,9 +368,28 @@ func logPrintf(lvl Level, format string, rest ...interface{}) { if !Log(lvl) { return } + if Config.JSON && !Config.LogFileAndLine && !Color && !Config.NoTimestamp && !Config.GoroutineID && len(rest) == 0 { + logSimpleJSON(lvl, format) + return + } logUnconditionalf(Config.LogFileAndLine, lvl, format, rest...) } +func logSimpleJSON(lvl Level, msg string) { + jWriter.mutex.Lock() + jWriter.buf.Reset() + jWriter.buf.WriteString("{\"ts\":") + t := TimeToTS(time.Now()) + jWriter.tsBuf = jWriter.tsBuf[:0] // reset the slice + jWriter.tsBuf = strconv.AppendFloat(jWriter.tsBuf, t, 'f', 6, 64) + jWriter.buf.Write(jWriter.tsBuf) + fmt.Fprintf(&jWriter.buf, ",\"level\":%s,\"msg\":%q}\n", + LevelToJSON[lvl], + msg) + _, _ = jWriter.w.Write(jWriter.buf.Bytes()) + jWriter.mutex.Unlock() +} + func logUnconditionalf(logFileAndLine bool, lvl Level, format string, rest ...interface{}) { prefix := Config.LogPrefix if prefix == "" { @@ -362,8 +398,6 @@ func logUnconditionalf(logFileAndLine bool, lvl Level, format string, rest ...in lvl1Char := "" if lvl == NoLevel { prefix = "" - } else { - lvl1Char = "[" + LevelToStrA[lvl][0:1] + "]" } if logFileAndLine { //nolint:nestif _, file, line, _ := runtime.Caller(3) @@ -376,6 +410,9 @@ func logUnconditionalf(logFileAndLine bool, lvl Level, format string, rest ...in jsonWrite(fmt.Sprintf("{%s\"level\":%s,%s\"file\":%q,\"line\":%d,\"msg\":%q}\n", jsonTimestamp(), LevelToJSON[lvl], jsonGID(), file, line, fmt.Sprintf(format, rest...))) } else { + if lvl != NoLevel { + lvl1Char = "[" + LevelToStrA[lvl][0:1] + "]" + } log.Print(lvl1Char, " ", file, ":", line, prefix, fmt.Sprintf(format, rest...)) } } else { @@ -384,9 +421,15 @@ func logUnconditionalf(logFileAndLine bool, lvl Level, format string, rest ...in colorTimestamp(), colorGID(), ColorLevelToStr(lvl), prefix, LevelToColor[lvl], fmt.Sprintf(format, rest...), Colors.Reset)) } else if Config.JSON { + if len(rest) != 0 { + format = fmt.Sprintf(format, rest...) + } jsonWrite(fmt.Sprintf("{%s\"level\":%s,%s\"msg\":%q}\n", - jsonTimestamp(), LevelToJSON[lvl], jsonGID(), fmt.Sprintf(format, rest...))) + jsonTimestamp(), LevelToJSON[lvl], jsonGID(), format)) } else { + if lvl != NoLevel { + lvl1Char = "[" + LevelToStrA[lvl][0:1] + "]" + } log.Print(lvl1Char, prefix, fmt.Sprintf(format, rest...)) } } @@ -399,7 +442,7 @@ func Printf(format string, rest ...interface{}) { // SetOutput sets the output to a different writer (forwards to system logger). func SetOutput(w io.Writer) { - jsonWriter = w + jWriter.w = w log.SetOutput(w) SetColorMode() // Colors.Reset color mode boolean } @@ -479,7 +522,8 @@ func LogVerbose() bool { //nolint:revive } // LoggerI defines a log.Logger like interface to pass to packages -// for simple logging. See [Logger()]. +// for simple logging. See [Logger()]. See also [NewStdLogger()] for +// intercepting with same type / when an interface can't be used. type LoggerI interface { Printf(format string, rest ...interface{}) } @@ -499,18 +543,44 @@ func Logger() LoggerI { // Somewhat slog compatible/style logger type KeyVal struct { - Key string - Value fmt.Stringer + Key string + StrValue string + Value fmt.Stringer + Cached bool } -type StringValue string - -func (s StringValue) String() string { - return string(s) +// String() is the slog compatible name for Str. Ends up calling Any() anyway. +func String(key, value string) KeyVal { + return Any(key, value) } func Str(key, value string) KeyVal { - return KeyVal{Key: key, Value: StringValue(value)} + return Any(key, value) +} + +// Few more slog style short cuts. +func Int(key string, value int) KeyVal { + return Any(key, value) +} + +func Int64(key string, value int64) KeyVal { + return Any(key, value) +} + +func Float64(key string, value float64) KeyVal { + return Any(key, value) +} + +func Bool(key string, value bool) KeyVal { + return Any(key, value) +} + +func (v *KeyVal) StringValue() string { + if !v.Cached { + v.StrValue = v.Value.String() + v.Cached = true + } + return v.StrValue } type ValueTypes interface{ any } @@ -519,14 +589,65 @@ type ValueType[T ValueTypes] struct { Val T } -func (v *ValueType[T]) String() string { - return fmt.Sprint(v.Val) +func arrayToString(s []interface{}) string { + var buf strings.Builder + buf.WriteString("[") + for i, e := range s { + if i != 0 { + buf.WriteString(",") + } + vv := ValueType[interface{}]{Val: e} + buf.WriteString(vv.String()) + } + buf.WriteString("]") + return buf.String() } +func mapToString(s map[string]interface{}) string { + var buf strings.Builder + buf.WriteString("{") + keys := make([]string, 0, len(s)) + for k := range s { + keys = append(keys, k) + } + sort.Strings(keys) + for i, k := range keys { + if i != 0 { + buf.WriteString(",") + } + buf.WriteString(fmt.Sprintf("%q", k)) + buf.WriteString(":") + vv := ValueType[interface{}]{Val: s[k]} + buf.WriteString(vv.String()) + } + buf.WriteString("}") + return buf.String() +} + +func (v ValueType[T]) String() string { + // if the type is numeric, use Sprint(v.val) otherwise use Sprintf("%q", v.Val) to quote it. + switch s := any(v.Val).(type) { + case bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, + float32, float64: + return fmt.Sprint(v.Val) + case []interface{}: + return arrayToString(s) + case map[string]interface{}: + return mapToString(s) + default: + return fmt.Sprintf("%q", fmt.Sprint(v.Val)) + } +} + +// Our original name, now switched to slog style Any. func Attr[T ValueTypes](key string, value T) KeyVal { + return Any(key, value) +} + +func Any[T ValueTypes](key string, value T) KeyVal { return KeyVal{ Key: key, - Value: &ValueType[T]{Val: value}, + Value: ValueType[T]{Val: value}, } } @@ -539,17 +660,21 @@ func s(lvl Level, logFileAndLine bool, json bool, msg string, attrs ...KeyVal) { if !Log(lvl) { return } + if Config.JSON && !Config.LogFileAndLine && !Color && !Config.NoTimestamp && !Config.GoroutineID && len(attrs) == 0 { + logSimpleJSON(lvl, msg) + return + } buf := strings.Builder{} var format string if Color { - format = Colors.Reset + ", " + Colors.Blue + "%s" + Colors.Reset + "=" + LevelToColor[lvl] + "%q" + format = Colors.Reset + ", " + Colors.Blue + "%s" + Colors.Reset + "=" + LevelToColor[lvl] + "%v" } else if json { - format = ",%q:%q" + format = ",%q:%s" } else { - format = ", %s=%q" + format = ", %s=%s" } for _, attr := range attrs { - buf.WriteString(fmt.Sprintf(format, attr.Key, attr.Value.String())) + buf.WriteString(fmt.Sprintf(format, attr.Key, attr.StringValue())) } // TODO share code with log.logUnconditionalf yet without extra locks or allocations/buffers? prefix := Config.LogPrefix diff --git a/logger_test.go b/logger_test.go index 5eef3a6..ed5b5db 100644 --- a/logger_test.go +++ b/logger_test.go @@ -110,7 +110,7 @@ func Test_LogS_JSON_no_json_with_filename(t *testing.T) { Printf("This will show too") // no filename/line and shows despite level _ = w.Flush() actual := b.String() - expected := "[W] logger_test.go:109-bar-This will show, key1=\"value 1\", key2=\"42\"\n" + + expected := "[W] logger_test.go:109-bar-This will show, key1=\"value 1\", key2=42\n" + "This will show too\n" if actual != expected { t.Errorf("got %q expected %q", actual, expected) @@ -136,8 +136,8 @@ func TestColorMode(t *testing.T) { if !Color { t.Errorf("expected to be in color mode after ForceColor=true and SetColorMode()") } - S(Warning, "With file and line", Str("attr", "value with space")) // line 139 - Infof("info with file and line = %v", Config.LogFileAndLine) // line 140 + S(Warning, "With file and line", String("attr", "value with space")) // line 139 + Infof("info with file and line = %v", Config.LogFileAndLine) // line 140 Config.LogFileAndLine = false Config.GoroutineID = false S(Warning, "Without file and line", Str("attr", "value with space")) @@ -151,7 +151,7 @@ func TestColorMode(t *testing.T) { "\x1b[90m[\x1b[33mWRN\x1b[90m] \x1b[33mWithout file and line\x1b[0m, \x1b[34mattr\x1b[0m=\x1b[33m\"value with space\"\x1b[0m\n" + "\x1b[90m[\x1b[32mINF\x1b[90m] \x1b[32minfo with file and line = false\x1b[0m\n" if actual != expected { - t.Errorf("got:\n%q\nexpected:\n%q", actual, expected) + t.Errorf("got:\n%s\nexpected:\n%s", actual, expected) } // See color timestamp Config.NoTimestamp = false @@ -330,7 +330,7 @@ func Test_LogS_JSON(t *testing.T) { now := time.Now() value2 := 42 value3 := 3.14 - S(Verbose, "Test Verbose", Str("key1", "value 1"), Attr("key2", value2), Attr("key3", value3)) + S(Verbose, "Test Verbose", Str("key1", "value 1"), Int("key2", value2), Float64("key3", value3)) _ = w.Flush() actual := b.String() e := JSONEntry{} @@ -368,11 +368,10 @@ func Test_LogS_JSON(t *testing.T) { if tmp["key1"] != "value 1" { t.Errorf("unexpected key1 %v", tmp["key1"]) } - // it all gets converted to %q quoted strings - tbd if that's good or bad - if tmp["key2"] != "42" { + if tmp["key2"] != float64(42) { t.Errorf("unexpected key2 %v", tmp["key2"]) } - if tmp["key3"] != "3.14" { + if tmp["key3"] != 3.14 { // comparing floats with == is dicey but... this passes... t.Errorf("unexpected key3 %v", tmp["key3"]) } if tmp["file"] != thisFilename { @@ -424,10 +423,10 @@ func Test_LogS_JSON_no_json_no_file(t *testing.T) { S(NoLevel, "This NoLevel will show despite logically info level") _ = w.Flush() actual := b.String() - expected := "[W]-foo-This will show, key1=\"value 1\", key2=\"42\"\n" + + expected := "[W]-foo-This will show, key1=\"value 1\", key2=42\n" + "This NoLevel will show despite logically info level\n" if actual != expected { - t.Errorf("got %q expected %q", actual, expected) + t.Errorf("---got:---\n%s\n---expected:---\n%s\n", actual, expected) } } @@ -468,6 +467,54 @@ func TestLoggerJSONNoTimestampNoFilename(t *testing.T) { } } +func TestLoggerSimpleJSON(t *testing.T) { + // Setup + var b bytes.Buffer + w := bufio.NewWriter(&b) + SetLogLevel(LevelByName("Verbose")) + Config.LogFileAndLine = false + Config.LogPrefix = "no used" + Config.JSON = true + Config.NoTimestamp = false + SetOutput(w) + // Start of the actual test + w.WriteString("[") + Critf("Test Critf2") + w.WriteString(",") + S(Critical, "Test Critf3") + w.WriteString("]") + _ = w.Flush() + actual := b.String() + e := []JSONEntry{} + err := json.Unmarshal([]byte(actual), &e) + t.Logf("got: %s -> %#v", actual, e) + if err != nil { + t.Errorf("unexpected JSON deserialization error %v for %q", err, actual) + } + if len(e) != 2 { + t.Errorf("unexpected number of entries %d", len(e)) + } + for i := 0; i < 2; i++ { + e := e[i] + if e.Level != "crit" { + t.Errorf("unexpected level %s", e.Level) + } + exp := fmt.Sprintf("Test Critf%d", i+2) + if e.Msg != exp { + t.Errorf("unexpected body %s", e.Msg) + } + if e.File != "" { + t.Errorf("unexpected file %q", e.File) + } + if e.Line != 0 { + t.Errorf("unexpected line %d", e.Line) + } + if e.TS == 0 { + t.Errorf("unexpected 0 time should have been present") + } + } +} + // Test that TimeToTs and Time() are inverse of one another. func TestTimeToTs(t *testing.T) { var prev float64 @@ -732,20 +779,36 @@ func BenchmarkLogDirect2(b *testing.B) { } } -func BenchmarkLogSnologNotOptimized(b *testing.B) { +func BenchmarkMultipleStrNoLog(b *testing.B) { setLevel(Error) for n := 0; n < b.N; n++ { - S(Debug, "foo bar", Attr("n", n)) + S(Debug, "foo bar", Str("a", "aval"), Str("b", "bval"), Str("c", "cval"), Str("d", "dval")) + } +} + +func BenchmarkLogSnologNotOptimized1(b *testing.B) { + for n := 0; n < b.N; n++ { + // Avoid optimization for n < 256 that skews memory number (and combined with truncation gives 0 instead of 1) + // https://github.com/golang/go/blob/go1.21.0/src/runtime/iface.go#L493 + S(Debug, "foo bar", Attr("n1", 12345+n)) + } +} + +func BenchmarkLogSnologNotOptimized4(b *testing.B) { + for n := 0; n < b.N; n++ { + v := n + 12345 + S(Debug, "foo bar", Attr("n1", v), Attr("n2", v+1), Attr("n3", v+2), Attr("n4", v+3)) } } func BenchmarkLogSnologOptimized(b *testing.B) { setLevel(Error) v := ValueType[int]{0} - a := KeyVal{Key: "n", Value: &v} + aa := KeyVal{Key: "n", Value: &v} + ba := Str("b", "bval") for n := 0; n < b.N; n++ { - v.Val = n - S(Debug, "foo bar", a) + v.Val = n + 1235 + S(Debug, "foo bar", aa, ba) } } diff --git a/special_test.go b/special_test.go new file mode 100644 index 0000000..decd365 --- /dev/null +++ b/special_test.go @@ -0,0 +1,77 @@ +package log + +import ( + "bufio" + "bytes" + "math" + "testing" +) + +func Test_LogS_JSON_NaN(t *testing.T) { + // Setup + var b bytes.Buffer + w := bufio.NewWriter(&b) + SetLogLevel(LevelByName("Verbose")) + Config.LogFileAndLine = false + Config.JSON = true + Config.NoTimestamp = true + SetOutput(w) + // Start of the actual test + value := math.NaN() + zero := 0.0 + S(Verbose, "Test NaN", Any("nan", value), Any("minus-inf", -1.0/zero)) + _ = w.Flush() + actual := b.String() + // Note that we serialize that way but can't deserialize with go default json unmarshaller + expected := `{"level":"trace","msg":"Test NaN","nan":NaN,"minus-inf":-Inf}` + "\n" + if actual != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) + } +} + +func Test_LogS_JSON_Array(t *testing.T) { + // Setup + var b bytes.Buffer + w := bufio.NewWriter(&b) + SetLogLevel(LevelByName("Verbose")) + Config.LogFileAndLine = false + Config.JSON = true + Config.NoTimestamp = true + SetOutput(w) + // Start of the actual test + S(Verbose, "Test Array", Any("arr", []interface{}{"x", 42, "y"})) + _ = w.Flush() + actual := b.String() + expected := `{"level":"trace","msg":"Test Array","arr":["x",42,"y"]}` + "\n" + if actual != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) + } +} + +func Test_LogS_JSON_Map(t *testing.T) { + // Setup + var b bytes.Buffer + w := bufio.NewWriter(&b) + SetLogLevel(LevelByName("Verbose")) + Config.LogFileAndLine = false + Config.JSON = true + Config.NoTimestamp = true + SetOutput(w) + // Start of the actual test + tst := map[string]interface{}{ + "str1": "val 1", + "subArray": []interface{}{ + "x", 42, "y", + }, + "number": 3.14, + } + S(Verbose, "Test Map", Any("map", tst), Int64("in64", 0), Bool("bool", true)) + _ = w.Flush() + actual := b.String() + //nolint:lll + expected := `{"level":"trace","msg":"Test Map","map":{"number":3.14,"str1":"val 1","subArray":["x",42,"y"]},"in64":0,"bool":true}` + + "\n" + if actual != expected { + t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) + } +}