add thread/goroutine id

README.md

@@ -44,23 +44,25 @@ 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`.
 
 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:
 
 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
 ```
 

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())
+}

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.

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.

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

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()
+	}
+}

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()))