From a8776baca428c4c7f31aef91c6a595201577fc05 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Mon, 15 Jul 2024 21:43:38 -0700 Subject: [PATCH 01/12] Fix panic for invalid stderr, add test --- console_logging.go | 5 ++++- logger_test.go | 11 +++++++++++ 2 files changed, 15 insertions(+), 1 deletion(-) diff --git a/console_logging.go b/console_logging.go index ba7583e..33752aa 100644 --- a/console_logging.go +++ b/console_logging.go @@ -94,7 +94,10 @@ func ConsoleLogging() bool { if !ok { return false } - s, _ := f.Stat() + s, err := f.Stat() + if err != nil { + return false + } return (s.Mode() & os.ModeCharDevice) == os.ModeCharDevice } diff --git a/logger_test.go b/logger_test.go index ef966c4..38bb785 100644 --- a/logger_test.go +++ b/logger_test.go @@ -930,6 +930,17 @@ func TestConfigFromEnvOk(t *testing.T) { } } +func TestInvalidFile(t *testing.T) { + prev := jWriter.w + invalidFile := os.NewFile(^uintptr(0), "invalid-file") + jWriter.w = invalidFile + b := ConsoleLogging() + jWriter.w = prev + if b { + t.Errorf("expected not to be console logging") + } +} + // io.Discard but specially known to by logger optimizations for instance. type discard struct{} From f9c8a2187f098f5dbe60f671444f2d2cb290229a Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Mon, 15 Jul 2024 23:59:54 -0700 Subject: [PATCH 02/12] auto switch to stdout for wasm - manual tested --- console_logging.go | 8 ++++++++ logger.go | 3 +++ 2 files changed, 11 insertions(+) diff --git a/console_logging.go b/console_logging.go index 33752aa..7dc3017 100644 --- a/console_logging.go +++ b/console_logging.go @@ -88,6 +88,14 @@ var ( Color = false ) +func IsValid(file *os.File) bool { + if file == nil { + return false + } + _, err := file.Stat() + return err == nil +} + // ConsoleLogging is a utility to check if the current logger output is a console (terminal). func ConsoleLogging() bool { f, ok := jWriter.w.(*os.File) diff --git a/logger.go b/logger.go index 6db46df..01851c3 100644 --- a/logger.go +++ b/logger.go @@ -174,6 +174,9 @@ func (l *JSONEntry) Time() time.Time { //nolint:gochecknoinits // needed func init() { + if !IsValid(os.Stderr) { // wasm in browser case for instance + SetOutput(os.Stdout) // this could also be invalid too but... we tried. + } setLevel(Info) // starting value levelToStrM = make(map[string]Level, 2*len(LevelToStrA)) JSONStringLevelToLevel = make(map[string]Level, len(LevelToJSON)-1) // -1 to not reverse info to NoLevel From eeef157d76b37e4aafaa831c427112ada81c09ae Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Tue, 16 Jul 2024 14:33:36 -0700 Subject: [PATCH 03/12] Throw the towel on goroutine, use the original directly, maintained for changes in linkname --- go.mod | 5 ++++- go.sum | 2 ++ goroutine/gid.go | 46 ++-------------------------------------------- 3 files changed, 8 insertions(+), 45 deletions(-) diff --git a/go.mod b/go.mod index b5254db..db257bc 100644 --- a/go.mod +++ b/go.mod @@ -2,4 +2,7 @@ module fortio.org/log go 1.18 -require fortio.org/struct2env v0.4.1 +require ( + fortio.org/struct2env v0.4.1 + github.com/kortschak/goroutine v1.1.2 +) diff --git a/go.sum b/go.sum index 064e82e..8254431 100644 --- a/go.sum +++ b/go.sum @@ -1,2 +1,4 @@ fortio.org/struct2env v0.4.1 h1:rJludAMO5eBvpWplWEQNqoVDFZr4RWMQX7RUapgZyc0= fortio.org/struct2env v0.4.1/go.mod h1:lENUe70UwA1zDUCX+8AsO663QCFqYaprk5lnPhjD410= +github.com/kortschak/goroutine v1.1.2 h1:lhllcCuERxMIK5cYr8yohZZScL1na+JM5JYPRclWjck= +github.com/kortschak/goroutine v1.1.2/go.mod h1:zKpXs1FWN/6mXasDQzfl7g0LrGFIOiA6cLs9eXKyaMY= diff --git a/goroutine/gid.go b/goroutine/gid.go index f377292..2704fa0 100644 --- a/goroutine/gid.go +++ b/goroutine/gid.go @@ -1,52 +1,10 @@ -// 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" + "github.com/kortschak/goroutine" // Rely on and forward to the original rather than maintain our own copy. ) // 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)) + return goroutine.ID() } - -//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 From a9bec0267fbe869989abac74db5ee23e8101ef65 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Tue, 16 Jul 2024 16:12:40 -0700 Subject: [PATCH 04/12] add alternative used to benchmark --- goroutine/gid.go | 4 ++++ goroutine/gid_test.go | 15 +++++++++++++-- goroutine/gid_tinygo.go | 34 ++++++++++++++++++++++++++++++++++ 3 files changed, 51 insertions(+), 2 deletions(-) create mode 100644 goroutine/gid_tinygo.go diff --git a/goroutine/gid.go b/goroutine/gid.go index 2704fa0..119937a 100644 --- a/goroutine/gid.go +++ b/goroutine/gid.go @@ -1,9 +1,13 @@ +//go:build !tinygo + package goroutine import ( "github.com/kortschak/goroutine" // Rely on and forward to the original rather than maintain our own copy. ) +const IsTinyGo = false + // ID returns the runtime ID of the calling goroutine. func ID() int64 { return goroutine.ID() diff --git a/goroutine/gid_test.go b/goroutine/gid_test.go index 801e564..519bab0 100644 --- a/goroutine/gid_test.go +++ b/goroutine/gid_test.go @@ -19,8 +19,12 @@ func TestID(t *testing.T) { if got != want { t.Fatalf("unexpected id for main goroutine: got:%d want:%d", got, want) } + n := 1000000 // for regular go + if IsTinyGo { + n = 1000 // for tinygo + } var wg sync.WaitGroup - for i := 0; i < 1000000; i++ { + for i := 0; i < n; i++ { i := i wg.Add(1) go func() { @@ -35,8 +39,14 @@ func TestID(t *testing.T) { wg.Wait() } +var testID int64 + // goid returns the goroutine ID extracted from a stack trace. func goid() int64 { + if IsTinyGo { + testID++ + return testID // pretty horrible test that aligns with the implementation, but at least it tests we get 1,2,3... different numbers. + } var buf [64]byte n := runtime.Stack(buf[:], false) idField := strings.Fields(strings.TrimPrefix(string(buf[:n]), "goroutine "))[0] @@ -47,8 +57,9 @@ func goid() int64 { return id } +var gotid int64 + func BenchmarkGID(b *testing.B) { - var gotid int64 for n := 0; n < b.N; n++ { gotid += ID() } diff --git a/goroutine/gid_tinygo.go b/goroutine/gid_tinygo.go new file mode 100644 index 0000000..045c43e --- /dev/null +++ b/goroutine/gid_tinygo.go @@ -0,0 +1,34 @@ +//go:build tinygo + +package goroutine + +import ( + "sync" + "unsafe" +) + +const IsTinyGo = true + +var ( + counter int64 + mapping = make(map[uintptr]int64) + lock sync.Mutex +) + +func ID() int64 { + task := uintptr(currentTask()) + lock.Lock() + if id, ok := mapping[task]; ok { + lock.Unlock() + return id + } + counter++ + mapping[task] = counter + lock.Unlock() + return counter + // or, super fast but ugly large numbers/pointers: + //return int64(uintptr(currentTask())) +} + +//go:linkname currentTask internal/task.Current +func currentTask() unsafe.Pointer From ddcb430d1dd7afa845e8327be436b8b1ca199c5b Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Tue, 16 Jul 2024 17:47:13 -0700 Subject: [PATCH 05/12] happy linters, happy life --- goroutine/gid_test.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/goroutine/gid_test.go b/goroutine/gid_test.go index 519bab0..96fc9dc 100644 --- a/goroutine/gid_test.go +++ b/goroutine/gid_test.go @@ -44,8 +44,9 @@ var testID int64 // goid returns the goroutine ID extracted from a stack trace. func goid() int64 { if IsTinyGo { + // pretty horrible test that aligns with the implementation, but at least it tests we get 1,2,3... different numbers. testID++ - return testID // pretty horrible test that aligns with the implementation, but at least it tests we get 1,2,3... different numbers. + return testID } var buf [64]byte n := runtime.Stack(buf[:], false) From 8c81506c6ee3244dd7993ad32645d3833629f392 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Tue, 16 Jul 2024 18:06:53 -0700 Subject: [PATCH 06/12] Add comment about the mutex --- goroutine/gid_tinygo.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/goroutine/gid_tinygo.go b/goroutine/gid_tinygo.go index 045c43e..93e1605 100644 --- a/goroutine/gid_tinygo.go +++ b/goroutine/gid_tinygo.go @@ -12,7 +12,10 @@ const IsTinyGo = true var ( counter int64 mapping = make(map[uintptr]int64) - lock sync.Mutex + // TinyGo at the moment is single threaded so this is not needed but it's good to have anyway + // in case that changes. It does had ~5ns (from 20ns vs 4ns big go) but it's better to be correct. + // In theory the mutex could be noop on platforms where everything is single threaded. + lock sync.Mutex ) func ID() int64 { From 376fcdf110dc9fbde309e8b2cf00c297a93f0a76 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 17 Jul 2024 09:36:16 -0700 Subject: [PATCH 07/12] review comments, thanks @ccoVeille for the thorough look --- console_logging.go | 4 +++- goroutine/gid_test.go | 8 ++++---- goroutine/gid_tinygo.go | 2 +- logger.go | 2 +- 4 files changed, 9 insertions(+), 7 deletions(-) diff --git a/console_logging.go b/console_logging.go index 7dc3017..121401d 100644 --- a/console_logging.go +++ b/console_logging.go @@ -88,7 +88,9 @@ var ( Color = false ) -func IsValid(file *os.File) bool { +// Is the file (e.g os.StdErr) Stat()able so we can detect if it's a tty or not. +// If not we switch in init() to Stdout. +func isValid(file *os.File) bool { if file == nil { return false } diff --git a/goroutine/gid_test.go b/goroutine/gid_test.go index 96fc9dc..4693451 100644 --- a/goroutine/gid_test.go +++ b/goroutine/gid_test.go @@ -10,6 +10,7 @@ import ( "strconv" "strings" "sync" + "sync/atomic" "testing" ) @@ -21,7 +22,7 @@ func TestID(t *testing.T) { } n := 1000000 // for regular go if IsTinyGo { - n = 1000 // for tinygo + n = 1000 // for tinygo, it OOMs with 1000000 and we're only self testing that we get different increasing ids. } var wg sync.WaitGroup for i := 0; i < n; i++ { @@ -45,8 +46,7 @@ var testID int64 func goid() int64 { if IsTinyGo { // pretty horrible test that aligns with the implementation, but at least it tests we get 1,2,3... different numbers. - testID++ - return testID + return atomic.AddInt64(&testID, 1) } var buf [64]byte n := runtime.Stack(buf[:], false) @@ -58,7 +58,7 @@ func goid() int64 { return id } -var gotid int64 +var gotid int64 // outside of the function to help avoiding compiler optimizations func BenchmarkGID(b *testing.B) { for n := 0; n < b.N; n++ { diff --git a/goroutine/gid_tinygo.go b/goroutine/gid_tinygo.go index 93e1605..f4ee02e 100644 --- a/goroutine/gid_tinygo.go +++ b/goroutine/gid_tinygo.go @@ -20,7 +20,7 @@ var ( func ID() int64 { task := uintptr(currentTask()) - lock.Lock() + lock.Lock() // explicit minimal critical section without using defer, on purpose. if id, ok := mapping[task]; ok { lock.Unlock() return id diff --git a/logger.go b/logger.go index 01851c3..8915c5d 100644 --- a/logger.go +++ b/logger.go @@ -174,7 +174,7 @@ func (l *JSONEntry) Time() time.Time { //nolint:gochecknoinits // needed func init() { - if !IsValid(os.Stderr) { // wasm in browser case for instance + if !isValid(os.Stderr) { // wasm in browser case for instance SetOutput(os.Stdout) // this could also be invalid too but... we tried. } setLevel(Info) // starting value From 2097233028568bc4e71808096a0afb2072d28261 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 17 Jul 2024 14:54:25 -0700 Subject: [PATCH 08/12] Update logger_test.go --- logger_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logger_test.go b/logger_test.go index 38bb785..985d095 100644 --- a/logger_test.go +++ b/logger_test.go @@ -941,7 +941,7 @@ func TestInvalidFile(t *testing.T) { } } -// io.Discard but specially known to by logger optimizations for instance. +// like io.Discard except io.Discard is checked for by logger optimizations and we want to avoid that. type discard struct{} func (discard) Write(p []byte) (int, error) { From 086f2e4ab9bb54faeec0249fa9835ea7b274988d Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 17 Jul 2024 15:43:14 -0700 Subject: [PATCH 09/12] Update logger_test.go indicate why we don't just use io.Discard, some more cc @ccoVeille --- logger_test.go | 1 + 1 file changed, 1 insertion(+) diff --git a/logger_test.go b/logger_test.go index 985d095..24b696a 100644 --- a/logger_test.go +++ b/logger_test.go @@ -942,6 +942,7 @@ func TestInvalidFile(t *testing.T) { } // like io.Discard except io.Discard is checked for by logger optimizations and we want to avoid that. +// e.g. https://cs.opensource.google/go/go/+/refs/tags/go1.22.5:src/log/log.go;l=84 type discard struct{} func (discard) Write(p []byte) (int, error) { From 531e7095c06d3cc473cdd0de682b503f9988639a Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 17 Jul 2024 16:14:19 -0700 Subject: [PATCH 10/12] increase coverage where possible, ie not in init() --- logger_test.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/logger_test.go b/logger_test.go index 24b696a..dfc10ae 100644 --- a/logger_test.go +++ b/logger_test.go @@ -931,6 +931,9 @@ func TestConfigFromEnvOk(t *testing.T) { } func TestInvalidFile(t *testing.T) { + if isValid(nil) { + t.Errorf("expected nil to be invalid") + } prev := jWriter.w invalidFile := os.NewFile(^uintptr(0), "invalid-file") jWriter.w = invalidFile From 867aa5cae1c830b3a71f3254339231ca842fd078 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 17 Jul 2024 18:02:25 -0700 Subject: [PATCH 11/12] Apply suggestions from code review Co-authored-by: ccoVeille <3875889+ccoVeille@users.noreply.github.com> --- goroutine/gid_tinygo.go | 6 +++--- logger.go | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/goroutine/gid_tinygo.go b/goroutine/gid_tinygo.go index f4ee02e..8b053bb 100644 --- a/goroutine/gid_tinygo.go +++ b/goroutine/gid_tinygo.go @@ -12,9 +12,9 @@ const IsTinyGo = true var ( counter int64 mapping = make(map[uintptr]int64) - // TinyGo at the moment is single threaded so this is not needed but it's good to have anyway - // in case that changes. It does had ~5ns (from 20ns vs 4ns big go) but it's better to be correct. - // In theory the mutex could be noop on platforms where everything is single threaded. + // TinyGo at the moment is single threaded, so this is not needed, but it's good to have anyway + // in case that changes. It does add ~5ns (from 20ns vs 4ns big go) but it's better to be correct. + // In theory, the mutex could be noop on platforms where everything is single threaded. lock sync.Mutex ) diff --git a/logger.go b/logger.go index 8915c5d..651662f 100644 --- a/logger.go +++ b/logger.go @@ -175,7 +175,7 @@ func (l *JSONEntry) Time() time.Time { //nolint:gochecknoinits // needed func init() { if !isValid(os.Stderr) { // wasm in browser case for instance - SetOutput(os.Stdout) // this could also be invalid too but... we tried. + SetOutput(os.Stdout) // this could also be invalid too, but... we tried. } setLevel(Info) // starting value levelToStrM = make(map[string]Level, 2*len(LevelToStrA)) From 44cf64512306b88644cf8fb6fd6eef1c866e7778 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 17 Jul 2024 18:09:13 -0700 Subject: [PATCH 12/12] more explanations of --- goroutine/gid_tinygo.go | 2 ++ logger_test.go | 8 ++++++-- 2 files changed, 8 insertions(+), 2 deletions(-) diff --git a/goroutine/gid_tinygo.go b/goroutine/gid_tinygo.go index 8b053bb..883c111 100644 --- a/goroutine/gid_tinygo.go +++ b/goroutine/gid_tinygo.go @@ -33,5 +33,7 @@ func ID() int64 { //return int64(uintptr(currentTask())) } +// Call https://github.com/tinygo-org/tinygo/blob/v0.32.0/src/internal/task/task_stack.go#L39 +// //go:linkname currentTask internal/task.Current func currentTask() unsafe.Pointer diff --git a/logger_test.go b/logger_test.go index dfc10ae..7941410 100644 --- a/logger_test.go +++ b/logger_test.go @@ -944,8 +944,12 @@ func TestInvalidFile(t *testing.T) { } } -// like io.Discard except io.Discard is checked for by logger optimizations and we want to avoid that. -// e.g. https://cs.opensource.google/go/go/+/refs/tags/go1.22.5:src/log/log.go;l=84 +// --- Benchmarks + +// This `discard` is like io.Discard, except that io.Discard is checked explicitly +// (e.g. https://cs.opensource.google/go/go/+/refs/tags/go1.22.5:src/log/log.go;l=84) +// in logger optimizations and we want to measure the actual production +// of messages. type discard struct{} func (discard) Write(p []byte) (int, error) {