diff --git a/README.md b/README.md index 555d174..7c0903d 100644 --- a/README.md +++ b/README.md @@ -44,7 +44,9 @@ In JSON mode the output looks like this ``` Which can be converted to JSONEntry but is also a fixed, optimized format (ie ts is always first etc) -The timestamp `ts` is in microseconds since epoch (golang UnixMicro()) +The timestamp `ts` is in seconds.microseconds since epoch (golang UnixMicro() split into seconds part before decimal and microseconds after) + +Since 1.8 the Goroutine ID is present in json 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`. @@ -52,15 +54,15 @@ If console output is detected (and ConsoleColor is true, which is the default) o When output is redirected, JSON output: ```json -{"ts":1688674146.025678,"level":"dbug","file":"levels.go","line":15,"msg":"This is a debug message ending with backslash"} -{"ts":1688674146.025708,"level":"trace","file":"levels.go","line":16,"msg":"This is a verbose message"} -{"ts":1688674146.025714,"level":"info","msg":"This an always printed, file:line omitted message"} -{"ts":1688674146.025717,"level":"info","file":"levels.go","line":18,"msg":"This is an info message with no attributes but with \"quotes\"..."} -{"ts":1688674146.025735,"level":"info","file":"levels.go","line":19,"msg":"This is multi line\n\tstructured info message with 3 attributes","attr1":"value1","attr2":"42","attr3":"\"quoted\nvalue\""} -{"ts":1688674146.025741,"level":"warn","file":"levels.go","line":21,"msg":"This is a warning message"} -{"ts":1688674146.025743,"level":"err","file":"levels.go","line":22,"msg":"This is an error message"} -{"ts":1688674146.025745,"level":"crit","file":"levels.go","line":23,"msg":"This is a critical message"} -{"ts":1688674146.025748,"level":"fatal","file":"levels.go","line":24,"msg":"This is a fatal message"} +{"ts":1689982778.034675,"level":"dbug","grid":1,"file":"levels.go","line":16,"msg":"This is a debug message ending with backslash \\"} +{"ts":1689982778.034703,"level":"trace","grid":1,"file":"levels.go","line":17,"msg":"This is a verbose message"} +{"ts":1689982778.034707,"level":"info","grid":1,"msg":"This an always printed, file:line omitted message"} +{"ts":1689982778.034710,"level":"info","grid":1,"file":"levels.go","line":19,"msg":"This is an info message with no attributes but with \"quotes\"..."} +{"ts":1689982778.034716,"level":"info","grid":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":1689982778.034721,"level":"warn","grid":1,"file":"levels.go","line":22,"msg":"This is a warning message"} +{"ts":1689982778.034723,"level":"err","grid":1,"file":"levels.go","line":23,"msg":"This is an error message"} +{"ts":1689982778.034726,"level":"crit","grid":1,"file":"levels.go","line":24,"msg":"This is a critical message"} +{"ts":1689982778.034728,"level":"fatal","grid":1,"file":"levels.go","line":25,"msg":"This is a fatal message"} This is stdout normal output ``` diff --git a/console_logging.go b/console_logging.go index 479c188..010114e 100644 --- a/console_logging.go +++ b/console_logging.go @@ -15,8 +15,11 @@ package log import ( + "fmt" "os" "time" + + "fortio.org/log/goroutine" ) // to avoid making a new package/namespace for colors, we use a struct. @@ -95,3 +98,11 @@ func colorTimestamp() string { } return time.Now().Format(Colors.DarkGray + "15:04:05.000 ") } + +// Color version of jsonGID(). +func colorGID() string { + if !Config.GoroutineID { + return "" + } + return Colors.Gray + fmt.Sprintf("[%d] ", goroutine.ID()) +} diff --git a/goroutine/LICENSE b/goroutine/LICENSE new file mode 100644 index 0000000..a2a16dd --- /dev/null +++ b/goroutine/LICENSE @@ -0,0 +1,22 @@ +Copyright ©2020 Dan Kortschak. All rights reserved. + +Redistribution and use in source and binary forms, with or without +modification, are permitted provided that the following conditions are met: + * Redistributions of source code must retain the above copyright + notice, this list of conditions and the following disclaimer. + * Redistributions in binary form must reproduce the above copyright + notice, this list of conditions and the following disclaimer in the + documentation and/or other materials provided with the distribution. + * The name of the author may not be used to endorse or promote products + derived from this software without specific prior written permission. + +THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" AND +ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED +WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE +DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE +FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL +DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR +SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER +CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, +OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. diff --git a/goroutine/README.md b/goroutine/README.md new file mode 100644 index 0000000..5871fd5 --- /dev/null +++ b/goroutine/README.md @@ -0,0 +1,18 @@ +If you just want a thread ID / goroutine ID use the original this was imported from: + +https://github.com/kortschak/goroutine/ + +Credits goes to Dan Kortschak and Laevus Dexter + +# goroutine identification + +Package goroutine provides a single function that will return the runtime's +ID number for the calling goroutine. + +The implementation is derived from Laevus Dexter's comment in Gophers' Slack +#darkarts, https://gophers.slack.com/archives/C1C1YSQBT/p1593885226448300 +post which linked to this playground snippet https://play.golang.org/p/CSOp9wyzydP. + +The code here is an exercise in minimalism, doing as little as possible by +deferring nearly all of the logic to runtime functions co-opted via +`//go:linkname` comments. diff --git a/goroutine/gid.go b/goroutine/gid.go new file mode 100644 index 0000000..f377292 --- /dev/null +++ b/goroutine/gid.go @@ -0,0 +1,52 @@ +// Copyright ©2020 Dan Kortschak. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package goroutine provides a single function that will return the runtime's +// ID number for the calling goroutine. +// +// The implementation is derived from Laevus Dexter's comment in Gophers' Slack #darkarts, +// https://gophers.slack.com/archives/C1C1YSQBT/p1593885226448300 post which linked to +// this playground snippet https://play.golang.org/p/CSOp9wyzydP. +package goroutine + +import ( + "reflect" + "unsafe" +) + +// ID returns the runtime ID of the calling goroutine. +func ID() int64 { + return *(*int64)(add(getg(), goidoff)) +} + +//go:nosplit +func getg() unsafe.Pointer { + return *(*unsafe.Pointer)(add(getm(), curgoff)) +} + +//go:linkname add runtime.add +//go:nosplit +func add(p unsafe.Pointer, x uintptr) unsafe.Pointer + +//go:linkname getm runtime.getm +//go:nosplit +func getm() unsafe.Pointer + +var ( + curgoff = offset("*runtime.m", "curg") + goidoff = offset("*runtime.g", "goid") +) + +// offset returns the offset into typ for the given field. +func offset(typ, field string) uintptr { + rt := toType(typesByString(typ)[0]) + f, _ := rt.Elem().FieldByName(field) + return f.Offset +} + +//go:linkname typesByString reflect.typesByString +func typesByString(s string) []unsafe.Pointer + +//go:linkname toType reflect.toType +func toType(t unsafe.Pointer) reflect.Type diff --git a/goroutine/gid_test.go b/goroutine/gid_test.go new file mode 100644 index 0000000..801e564 --- /dev/null +++ b/goroutine/gid_test.go @@ -0,0 +1,55 @@ +// Copyright ©2020 Dan Kortschak. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package goroutine + +import ( + "fmt" + "runtime" + "strconv" + "strings" + "sync" + "testing" +) + +func TestID(t *testing.T) { + got := ID() + want := goid() + if got != want { + t.Fatalf("unexpected id for main goroutine: got:%d want:%d", got, want) + } + var wg sync.WaitGroup + for i := 0; i < 1000000; i++ { + i := i + wg.Add(1) + go func() { + defer wg.Done() + got := ID() + want := goid() + if got != want { + t.Errorf("unexpected id for goroutine number %d: got:%d want:%d", i, got, want) + } + }() + } + wg.Wait() +} + +// goid returns the goroutine ID extracted from a stack trace. +func goid() int64 { + var buf [64]byte + n := runtime.Stack(buf[:], false) + idField := strings.Fields(strings.TrimPrefix(string(buf[:n]), "goroutine "))[0] + id, err := strconv.ParseInt(idField, 10, 64) + if err != nil { + panic(fmt.Sprintf("cannot get goroutine id: %v", err)) + } + return id +} + +func BenchmarkGID(b *testing.B) { + var gotid int64 + for n := 0; n < b.N; n++ { + gotid += ID() + } +} diff --git a/logger.go b/logger.go index f1c325d..6d36587 100644 --- a/logger.go +++ b/logger.go @@ -32,6 +32,8 @@ import ( "sync" "sync/atomic" "time" + + "fortio.org/log/goroutine" ) // Level is the level of logging (0 Debug -> 6 Fatal). @@ -61,6 +63,8 @@ type LogConfig struct { // Force color mode even if logger output is not console (useful for CI that recognize ansi colors). // SetColorMode() must be called if this or ConsoleColor are changed. ForceColor bool + // If true, log the goroutine ID (gid) in json. + GoroutineID bool } // DefaultConfig() returns the default initial configuration for the logger, best suited @@ -76,6 +80,7 @@ func DefaultConfig() *LogConfig { FatalExit: os.Exit, JSON: true, ConsoleColor: true, + GoroutineID: true, } } @@ -105,6 +110,8 @@ var ( "\"crit\"", "\"fatal\"", } + // Reverse mapping of level string used in JSON to Level. Used by https://github.com/fortio/logc + // to interpret and colorize pre existing JSON logs. JSONStringLevelToLevel map[string]Level ) @@ -118,6 +125,7 @@ func SetDefaultsForClientTools() { Config.FatalPanics = false Config.ConsoleColor = true Config.JSON = false + Config.GoroutineID = false SetColorMode() } @@ -126,6 +134,7 @@ func SetDefaultsForClientTools() { // structure. type JSONEntry struct { TS float64 // In seconds since epoch (unix micros resolution), see TimeToTS(). + GrID int64 // Goroutine ID (if enabled) Level string File string Line int @@ -328,6 +337,14 @@ func jsonTimestamp() string { return fmt.Sprintf("\"ts\":%.6f,", TimeToTS(time.Now())) } +// Returns the json GoRoutineID if enabled. +func jsonGID() string { + if !Config.GoroutineID { + return "" + } + return fmt.Sprintf("\"grid\":%d,", goroutine.ID()) +} + func logPrintf(lvl Level, format string, rest ...interface{}) { if !Log(lvl) { return @@ -340,22 +357,23 @@ func logUnconditionalf(logFileAndLine bool, lvl Level, format string, rest ...in _, file, line, _ := runtime.Caller(3) file = file[strings.LastIndex(file, "/")+1:] if Color { - jsonWrite(fmt.Sprintf("%s%s%s %s:%d%s%s%s\n", - colorTimestamp(), LevelToColor[lvl], LevelToStrA[lvl][0:1], + jsonWrite(fmt.Sprintf("%s%s%s%s %s:%d%s%s%s\n", + colorTimestamp(), colorGID(), LevelToColor[lvl], LevelToStrA[lvl][0:1], file, line, Config.LogPrefix, fmt.Sprintf(format, rest...), Colors.Reset)) } else if Config.JSON { - jsonWrite(fmt.Sprintf("{%s\"level\":%s,\"file\":%q,\"line\":%d,\"msg\":%q}\n", - jsonTimestamp(), LevelToJSON[lvl], file, line, fmt.Sprintf(format, rest...))) + 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 { log.Print(LevelToStrA[lvl][0:1], " ", file, ":", line, Config.LogPrefix, fmt.Sprintf(format, rest...)) } } else { if Color { - jsonWrite(fmt.Sprintf("%s%s%s %s%s%s\n", - colorTimestamp(), LevelToColor[lvl], LevelToStrA[lvl][0:1], Config.LogPrefix, fmt.Sprintf(format, rest...), Colors.Reset)) + jsonWrite(fmt.Sprintf("%s%s%s%s %s%s%s\n", + colorTimestamp(), colorGID(), LevelToColor[lvl], LevelToStrA[lvl][0:1], Config.LogPrefix, + fmt.Sprintf(format, rest...), Colors.Reset)) } else if Config.JSON { - jsonWrite(fmt.Sprintf("{%s\"level\":%s,\"msg\":%q}\n", - jsonTimestamp(), LevelToJSON[lvl], fmt.Sprintf(format, rest...))) + jsonWrite(fmt.Sprintf("{%s\"level\":%s,%s\"msg\":%q}\n", + jsonTimestamp(), LevelToJSON[lvl], jsonGID(), fmt.Sprintf(format, rest...))) } else { log.Print(LevelToStrA[lvl][0:1], " ", Config.LogPrefix, fmt.Sprintf(format, rest...)) } @@ -505,6 +523,9 @@ func S(lvl Level, msg string, attrs ...KeyVal) { if !Log(lvl) { return } + // extra := "" + // if Config.GoroutineID { + // } buf := strings.Builder{} var format string if Color { @@ -522,18 +543,19 @@ func S(lvl Level, msg string, attrs ...KeyVal) { _, file, line, _ := runtime.Caller(1) file = file[strings.LastIndex(file, "/")+1:] if Color { - jsonWrite(fmt.Sprintf("%s%s%s %s:%d%s%s%s%s\n", - colorTimestamp(), LevelToColor[lvl], LevelToStrA[lvl][0:1], file, line, Config.LogPrefix, msg, buf.String(), Colors.Reset)) + jsonWrite(fmt.Sprintf("%s%s%s%s %s:%d%s%s%s%s\n", + colorTimestamp(), colorGID(), LevelToColor[lvl], LevelToStrA[lvl][0:1], + file, line, Config.LogPrefix, msg, buf.String(), Colors.Reset)) } else if Config.JSON { - jsonWrite(fmt.Sprintf("{%s\"level\":%s,\"file\":%q,\"line\":%d,\"msg\":%q%s}\n", - jsonTimestamp(), LevelToJSON[lvl], file, line, msg, buf.String())) + jsonWrite(fmt.Sprintf("{%s\"level\":%s,%s\"file\":%q,\"line\":%d,\"msg\":%q%s}\n", + jsonTimestamp(), LevelToJSON[lvl], jsonGID(), file, line, msg, buf.String())) } else { log.Print(LevelToStrA[lvl][0:1], " ", file, ":", line, Config.LogPrefix, msg, buf.String()) } } else { if Color { - jsonWrite(fmt.Sprintf("%s%s%s %s%s%s%s\n", - colorTimestamp(), LevelToColor[lvl], LevelToStrA[lvl][0:1], Config.LogPrefix, msg, buf.String(), Colors.Reset)) + jsonWrite(fmt.Sprintf("%s%s%s%s %s%s%s%s\n", + colorTimestamp(), colorGID(), LevelToColor[lvl], LevelToStrA[lvl][0:1], Config.LogPrefix, msg, buf.String(), Colors.Reset)) } else if Config.JSON { jsonWrite(fmt.Sprintf("{%s\"level\":%s,\"msg\":%q%s}\n", jsonTimestamp(), LevelToJSON[lvl], msg, buf.String())) diff --git a/logger_test.go b/logger_test.go index 5c6aab9..96c29e8 100644 --- a/logger_test.go +++ b/logger_test.go @@ -20,6 +20,7 @@ import ( "encoding/json" "errors" "flag" + "fmt" "log" "os" "os/exec" @@ -28,6 +29,8 @@ import ( "sync" "testing" "time" + + "fortio.org/log/goroutine" ) const thisFilename = "logger_test.go" @@ -45,17 +48,17 @@ func TestLoggerFilenameLine(t *testing.T) { SetFlags(0) SetLogLevel(Debug) if LogDebug() { - Debugf("test") // line 48 + Debugf("test") // line 51 } - SetLogLevel(-1) // line 50 - SetLogLevel(Warning) // line 51 + SetLogLevel(-1) // line 53 + SetLogLevel(Warning) // line 54 Infof("should not show (info level)") Printf("Should show despite being Info - unconditional Printf without line/file") w.Flush() actual := b.String() - expected := "D logger_test.go:48-prefix-test\n" + - "E logger_test.go:50-prefix-SetLogLevel called with level -1 lower than Debug!\n" + - "I logger_test.go:51-prefix-Log level is now 3 Warning (was 0 Debug)\n" + + expected := "D logger_test.go:51-prefix-test\n" + + "E logger_test.go:53-prefix-SetLogLevel called with level -1 lower than Debug!\n" + + "I logger_test.go:54-prefix-Log level is now 3 Warning (was 0 Debug)\n" + "I -prefix-Should show despite being Info - unconditional Printf without line/file\n" if actual != expected { t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) @@ -75,11 +78,16 @@ func TestLoggerFilenameLineJSON(t *testing.T) { SetOutput(w) SetLogLevel(Debug) if LogDebug() { - Debugf("a test") // line 78 + Debugf("a test") // line 81 } w.Flush() actual := b.String() - expected := `{"level":"dbug","file":"` + thisFilename + `","line":78,"msg":"a test"}` + "\n" + grID := goroutine.ID() + if grID <= 0 { + t.Errorf("unexpected goroutine id %d", grID) + } + expected := `{"level":"dbug","grid":` + strconv.FormatInt(grID, 10) + + `,"file":"` + thisFilename + `","line":81,"msg":"a test"}` + "\n" if actual != expected { t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected) } @@ -98,11 +106,11 @@ func Test_LogS_JSON_no_json_with_filename(t *testing.T) { SetOutput(w) // Start of the actual test S(Verbose, "This won't show") - S(Warning, "This will show", Str("key1", "value 1"), Attr("key2", 42)) // line 101 + S(Warning, "This will show", Str("key1", "value 1"), Attr("key2", 42)) // line 109 Printf("This will show too") // no filename/line and shows despite level _ = w.Flush() actual := b.String() - expected := "W logger_test.go:101-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" + "I -bar-This will show too\n" if actual != expected { t.Errorf("got %q expected %q", actual, expected) @@ -127,15 +135,18 @@ 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 130 - Infof("info with file and line = %v", Config.LogFileAndLine) // line 131 + S(Warning, "With file and line", Str("attr", "value with space")) // line 138 + Infof("info with file and line = %v", Config.LogFileAndLine) // line 139 Config.LogFileAndLine = false + Config.GoroutineID = false S(Warning, "Without file and line", Str("attr", "value with space")) Infof("info with file and line = %v", Config.LogFileAndLine) _ = w.Flush() actual := b.String() - expected := "\x1b[33mW logger_test.go:130> With file and line\x1b[0m, \x1b[34mattr\x1b[0m=\x1b[33m\"value with space\"\x1b[0m\n" + - "\x1b[32mI logger_test.go:131> info with file and line = true\x1b[0m\n" + + grID := fmt.Sprintf("[%d] ", goroutine.ID()) + expected := "\x1b[37m" + grID + + "\x1b[33mW logger_test.go:138> With file and line\x1b[0m, \x1b[34mattr\x1b[0m=\x1b[33m\"value with space\"\x1b[0m\n" + + "\x1b[37m" + grID + "\x1b[32mI logger_test.go:139> info with file and line = true\x1b[0m\n" + "\x1b[33mW > Without file and line\x1b[0m, \x1b[34mattr\x1b[0m=\x1b[33m\"value with space\"\x1b[0m\n" + "\x1b[32mI > info with file and line = false\x1b[0m\n" if actual != expected { @@ -610,6 +621,7 @@ func TestTimeToTS(t *testing.T) { {1688763601, 42000, "1688763601.000042"}, // 42 usec after the seconds part, checking for leading zeroes {1688763601, 199999999, "1688763601.199999"}, // nanosec are truncated away not rounded (see note in TimeToTS) {1688763601, 200000999, "1688763601.200000"}, // boundary + {1689983019, 142600000, "1689983019.142600"}, // trailing zeroes } { tm := time.Unix(tst.sec, tst.nano) ts := timeToTStr(tm) @@ -630,6 +642,19 @@ func TestJSONLevelReverse(t *testing.T) { } } +// io.Discard but specially known to by logger optimizations for instance. +type discard struct{} + +func (discard) Write(p []byte) (int, error) { + return len(p), nil +} + +func (discard) WriteString(s string) (int, error) { + return len(s), nil +} + +var Discard = discard{} + func BenchmarkLogDirect1(b *testing.B) { setLevel(Error) for n := 0; n < b.N; n++ { @@ -643,3 +668,60 @@ func BenchmarkLogDirect2(b *testing.B) { Logf(Debug, "foo bar %d", n) } } + +func BenchmarkLogSnologNotOptimized(b *testing.B) { + setLevel(Error) + for n := 0; n < b.N; n++ { + S(Debug, "foo bar", Attr("n", n)) + } +} + +func BenchmarkLogSnologOptimized(b *testing.B) { + setLevel(Error) + v := ValueType[int]{0} + a := KeyVal{Key: "n", Value: &v} + for n := 0; n < b.N; n++ { + v.Val = n + S(Debug, "foo bar", a) + } +} + +func BenchmarkLogS_NotOptimized(b *testing.B) { + setLevel(Info) + Config.JSON = true + Config.LogFileAndLine = false + Config.ConsoleColor = false + Config.ForceColor = false + SetOutput(Discard) + for n := 0; n < b.N; n++ { + S(Info, "foo bar", Attr("n", n)) + } +} + +func BenchmarkLog_Optimized(b *testing.B) { + setLevel(Info) + Config.JSON = true + Config.LogFileAndLine = false + Config.ConsoleColor = false + Config.ForceColor = false + SetOutput(Discard) + v := ValueType[int]{0} + a := KeyVal{Key: "n", Value: &v} + for n := 0; n < b.N; n++ { + v.Val = n + S(Info, "foo bar", a) + } +} + +func BenchmarkLogOldStyle(b *testing.B) { + setLevel(Info) + Config.JSON = false + Config.LogFileAndLine = false + Config.ConsoleColor = false + Config.ForceColor = false + SetColorMode() + SetOutput(Discard) + for n := 0; n < b.N; n++ { + S(Info, "foo bar", Attr("n", n)) + } +}