package harness import ( "fmt" "path/filepath" "runtime" "sort" "strings" "sync" "testing" "time" ) type event struct { timestamp time.Time msg string } type events []*event func (e events) Len() int { return len(e) } func (e events) Less(i, j int) bool { return e[i].timestamp.Before(e[j].timestamp) } func (e events) Swap(i, j int) { e[i], e[j] = e[j], e[i] } // TestLogger is a logger for tests. // It buffers output and only writes the output if the test fails or output is explicitly turned on. // The purpose of this logger is to allow Go test to run with the verbose flag without printing logs. // The verbose flag is useful since it streams test progress, but also printing logs makes the output too verbose. // // You can also add prefixes that are prepended to each log message, for extra logging context. // // This is implemented as a hierarchy of loggers, with children flushing log entries back to parents. // This works because t.Cleanup() processes entries in LIFO order, so children always flush first. // // Obviously this logger should never be used in production systems. type TestLogger struct { parent *TestLogger children []*TestLogger prefixes []string prefixesIface []any t *testing.T buf events m sync.Mutex logsEnabled bool } func NewTestLogger(t *testing.T) *TestLogger { l := &TestLogger{t: t, buf: make(events, 0)} t.Cleanup(l.flush) return l } func (t *TestLogger) buildPrefix(timestamp time.Time) string { d := timestamp.Format("2006-01-02T15:04:05.999999") _, file, lineno, _ := runtime.Caller(2) file = filepath.Base(file) caller := fmt.Sprintf("%s:%d", file, lineno) if len(t.prefixes) == 0 { return fmt.Sprintf("%s\t%s\t", d, caller) } prefixes := strings.Join(t.prefixes, ":") return fmt.Sprintf("%s\t%s\t%s: ", d, caller, prefixes) } func (t *TestLogger) Log(args ...any) { timestamp := time.Now() e := t.buildPrefix(timestamp) + fmt.Sprint(args...) t.add(&event{timestamp: timestamp, msg: e}) } func (t *TestLogger) Logf(format string, args ...any) { timestamp := time.Now() e := t.buildPrefix(timestamp) + fmt.Sprintf(format, args...) t.add(&event{timestamp: timestamp, msg: e}) } func (t *TestLogger) Fatal(args ...any) { timestamp := time.Now() e := t.buildPrefix(timestamp) + fmt.Sprint(append([]any{"fatal: "}, args...)...) t.add(&event{timestamp: timestamp, msg: e}) t.t.FailNow() } func (t *TestLogger) Fatalf(format string, args ...any) { timestamp := time.Now() e := t.buildPrefix(timestamp) + fmt.Sprintf(fmt.Sprintf("fatal: %s", format), args...) t.add(&event{timestamp: timestamp, msg: e}) t.t.FailNow() } func (t *TestLogger) add(e *event) { t.m.Lock() defer t.m.Unlock() t.buf = append(t.buf, e) } func (t *TestLogger) AddPrefix(prefix string) *TestLogger { l := &TestLogger{ prefixes: append(t.prefixes, prefix), prefixesIface: append(t.prefixesIface, prefix), t: t.t, parent: t, logsEnabled: t.logsEnabled, } t.m.Lock() defer t.m.Unlock() t.children = append(t.children, l) t.t.Cleanup(l.flush) return l } func (t *TestLogger) EnableLogs() { t.m.Lock() defer t.m.Unlock() t.logsEnabled = true if t.parent != nil { if t.parent.logsEnabled { t.parent.EnableLogs() } } fmt.Printf("enabling %d children\n", len(t.children)) for _, c := range t.children { if !c.logsEnabled { c.EnableLogs() } } } func (t *TestLogger) flush() { if t.t.Failed() || t.logsEnabled { t.m.Lock() defer t.m.Unlock() // if this is a child, send the events to the parent // the root parent will print all the events in sorted order if t.parent != nil { for _, e := range t.buf { t.parent.add(e) } } else { // we're the root, sort all the events and then print them sort.Sort(t.buf) fmt.Println() fmt.Printf("Logs for test %q:\n\n", t.t.Name()) for _, e := range t.buf { fmt.Println(e.msg) } fmt.Println() } t.buf = nil } }