| 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 | } |