I was debugging some internals, and the test-logger was silently hiding important information from a sub-logger.
We can make the bufHandler not buffered, and surface the data synchronously. The test logger already flushes after every single log call, so there's no point in not doing that.
On a related note, the flush() after a crit never happens, because the inner crit logger is going to os.Exit(1), thus omitting critical info (originally found by @samlaf )
System information
Latest master branch.
Expected behaviour
testlog_test.go:13: INFO [03-31|13:28:01.130] Visible
testlog_test.go:14: INFO [03-31|13:28:01.130] Hide and seek foobar=123
testlog_test.go:15: INFO [03-31|13:28:01.130] Also visible
Actual behaviour
testlog_test.go:13: INFO [03-31|13:28:01.130] Visible
testlog_test.go:15: INFO [03-31|13:28:01.130] Also visible
Steps to reproduce the behaviour
Add a testlog_test.go with basic test:
package testlog
import (
"testing"
"github.com/ethereum/go-ethereum/log"
)
func TestLogging(t *testing.T) {
l := Logger(t, log.LevelInfo)
subLogger := l.New("foobar", 123)
l.Info("Visible")
subLogger.Info("Hide and seek") // not visible due to sub buffer never being flushed
l.Info("Also visible")
t.Log("flushed: ", l.Handler().(*bufHandler).buf)
t.Log("remaining: ", subLogger.Handler().(*bufHandler).buf)
// horrible hack to manually bring back the expected log data
l.Handler().(*bufHandler).buf = subLogger.Handler().(*bufHandler).buf
l.(*logger).flush()
}
=== RUN TestLogging
testlog_test.go:13: INFO [03-31|13:30:10.246] Visible
testlog_test.go:15: INFO [03-31|13:30:10.246] Also visible
testlog_test.go:17: flushed: []
testlog_test.go:18: remaining: [{2025-03-31 13:30:10.246453737 +0200 CEST m=+0.000212631 Hide and seek INFO 5598664 [{ {[] 0 <nil>}} { {[] 0 <nil>}} { {[] 0 <nil>}} { {[] 0 <nil>}} { {[] 0 <nil>}}] 0 []}]
testlog_test.go:21: INFO [03-31|13:30:10.246] Hide and seek
--- PASS: TestLogging (0.00s)
PASS
Note: the foobar=123 is still lost for some reason.
Backtrace
N/A
I was debugging some internals, and the test-logger was silently hiding important information from a sub-logger.
We can make the
bufHandlernot buffered, and surface the data synchronously. The test logger already flushes after every single log call, so there's no point in not doing that.On a related note, the
flush()after a crit never happens, because the inner crit logger is going toos.Exit(1), thus omitting critical info (originally found by @samlaf )System information
Latest
masterbranch.Expected behaviour
Actual behaviour
Steps to reproduce the behaviour
Add a
testlog_test.gowith basic test:Note: the
foobar=123is still lost for some reason.Backtrace
N/A