|
| 1 | +package harness |
| 2 | + |
| 3 | +import ( |
| 4 | + "fmt" |
| 5 | + "path/filepath" |
| 6 | + "runtime" |
| 7 | + "sort" |
| 8 | + "strings" |
| 9 | + "sync" |
| 10 | + "testing" |
| 11 | + "time" |
| 12 | +) |
| 13 | + |
| 14 | +type event struct { |
| 15 | + timestamp time.Time |
| 16 | + msg string |
| 17 | +} |
| 18 | + |
| 19 | +type events []*event |
| 20 | + |
| 21 | +func (e events) Len() int { return len(e) } |
| 22 | +func (e events) Less(i, j int) bool { return e[i].timestamp.Before(e[j].timestamp) } |
| 23 | +func (e events) Swap(i, j int) { e[i], e[j] = e[j], e[i] } |
| 24 | + |
| 25 | +// TestLogger is a logger for tests. |
| 26 | +// It buffers output and only writes the output if the test fails or output is explicitly turned on. |
| 27 | +// The purpose of this logger is to allow Go test to run with the verbose flag without printing logs. |
| 28 | +// The verbose flag is useful since it streams test progress, but also printing logs makes the output too verbose. |
| 29 | +// |
| 30 | +// You can also add prefixes that are prepended to each log message, for extra logging context. |
| 31 | +// |
| 32 | +// This is implemented as a hierarchy of loggers, with children flushing log entries back to parents. |
| 33 | +// This works because t.Cleanup() processes entries in LIFO order, so children always flush first. |
| 34 | +// |
| 35 | +// Obviously this logger should never be used in production systems. |
| 36 | +type TestLogger struct { |
| 37 | + parent *TestLogger |
| 38 | + children []*TestLogger |
| 39 | + prefixes []string |
| 40 | + prefixesIface []any |
| 41 | + t *testing.T |
| 42 | + buf events |
| 43 | + m sync.Mutex |
| 44 | + logsEnabled bool |
| 45 | +} |
| 46 | + |
| 47 | +func NewTestLogger(t *testing.T) *TestLogger { |
| 48 | + l := &TestLogger{t: t, buf: make(events, 0)} |
| 49 | + t.Cleanup(l.flush) |
| 50 | + return l |
| 51 | +} |
| 52 | + |
| 53 | +func (t *TestLogger) buildPrefix(timestamp time.Time) string { |
| 54 | + d := timestamp.Format("2006-01-02T15:04:05.999999") |
| 55 | + _, file, lineno, _ := runtime.Caller(2) |
| 56 | + file = filepath.Base(file) |
| 57 | + caller := fmt.Sprintf("%s:%d", file, lineno) |
| 58 | + |
| 59 | + if len(t.prefixes) == 0 { |
| 60 | + return fmt.Sprintf("%s\t%s\t", d, caller) |
| 61 | + } |
| 62 | + |
| 63 | + prefixes := strings.Join(t.prefixes, ":") |
| 64 | + return fmt.Sprintf("%s\t%s\t%s: ", d, caller, prefixes) |
| 65 | +} |
| 66 | + |
| 67 | +func (t *TestLogger) Log(args ...any) { |
| 68 | + timestamp := time.Now() |
| 69 | + e := t.buildPrefix(timestamp) + fmt.Sprint(args...) |
| 70 | + t.add(&event{timestamp: timestamp, msg: e}) |
| 71 | +} |
| 72 | + |
| 73 | +func (t *TestLogger) Logf(format string, args ...any) { |
| 74 | + timestamp := time.Now() |
| 75 | + e := t.buildPrefix(timestamp) + fmt.Sprintf(format, args...) |
| 76 | + t.add(&event{timestamp: timestamp, msg: e}) |
| 77 | +} |
| 78 | + |
| 79 | +func (t *TestLogger) Fatal(args ...any) { |
| 80 | + timestamp := time.Now() |
| 81 | + e := t.buildPrefix(timestamp) + fmt.Sprint(append([]any{"fatal: "}, args...)...) |
| 82 | + t.add(&event{timestamp: timestamp, msg: e}) |
| 83 | + t.t.FailNow() |
| 84 | +} |
| 85 | + |
| 86 | +func (t *TestLogger) Fatalf(format string, args ...any) { |
| 87 | + timestamp := time.Now() |
| 88 | + e := t.buildPrefix(timestamp) + fmt.Sprintf(fmt.Sprintf("fatal: %s", format), args...) |
| 89 | + t.add(&event{timestamp: timestamp, msg: e}) |
| 90 | + t.t.FailNow() |
| 91 | +} |
| 92 | + |
| 93 | +func (t *TestLogger) add(e *event) { |
| 94 | + t.m.Lock() |
| 95 | + defer t.m.Unlock() |
| 96 | + t.buf = append(t.buf, e) |
| 97 | +} |
| 98 | + |
| 99 | +func (t *TestLogger) AddPrefix(prefix string) *TestLogger { |
| 100 | + l := &TestLogger{ |
| 101 | + prefixes: append(t.prefixes, prefix), |
| 102 | + prefixesIface: append(t.prefixesIface, prefix), |
| 103 | + t: t.t, |
| 104 | + parent: t, |
| 105 | + logsEnabled: t.logsEnabled, |
| 106 | + } |
| 107 | + t.m.Lock() |
| 108 | + defer t.m.Unlock() |
| 109 | + |
| 110 | + t.children = append(t.children, l) |
| 111 | + t.t.Cleanup(l.flush) |
| 112 | + |
| 113 | + return l |
| 114 | +} |
| 115 | + |
| 116 | +func (t *TestLogger) EnableLogs() { |
| 117 | + t.m.Lock() |
| 118 | + defer t.m.Unlock() |
| 119 | + t.logsEnabled = true |
| 120 | + if t.parent != nil { |
| 121 | + if t.parent.logsEnabled { |
| 122 | + t.parent.EnableLogs() |
| 123 | + } |
| 124 | + } |
| 125 | + fmt.Printf("enabling %d children\n", len(t.children)) |
| 126 | + for _, c := range t.children { |
| 127 | + if !c.logsEnabled { |
| 128 | + c.EnableLogs() |
| 129 | + } |
| 130 | + } |
| 131 | +} |
| 132 | + |
| 133 | +func (t *TestLogger) flush() { |
| 134 | + if t.t.Failed() || t.logsEnabled { |
| 135 | + t.m.Lock() |
| 136 | + defer t.m.Unlock() |
| 137 | + // if this is a child, send the events to the parent |
| 138 | + // the root parent will print all the events in sorted order |
| 139 | + if t.parent != nil { |
| 140 | + for _, e := range t.buf { |
| 141 | + t.parent.add(e) |
| 142 | + } |
| 143 | + } else { |
| 144 | + // we're the root, sort all the events and then print them |
| 145 | + sort.Sort(t.buf) |
| 146 | + fmt.Println() |
| 147 | + fmt.Printf("Logs for test %q:\n\n", t.t.Name()) |
| 148 | + for _, e := range t.buf { |
| 149 | + fmt.Println(e.msg) |
| 150 | + } |
| 151 | + fmt.Println() |
| 152 | + } |
| 153 | + t.buf = nil |
| 154 | + } |
| 155 | +} |
0 commit comments