1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
|
// Copyright (c) Tailscale Inc & contributors
// SPDX-License-Identifier: BSD-3-Clause
package tstest
import (
"bytes"
"fmt"
"log"
"os"
"sync"
"testing"
"go4.org/mem"
"tailscale.com/types/logger"
"tailscale.com/util/testenv"
)
type testLogWriter struct {
t *testing.T
}
func (w *testLogWriter) Write(b []byte) (int, error) {
w.t.Helper()
w.t.Logf("%s", b)
return len(b), nil
}
func FixLogs(t *testing.T) {
log.SetFlags(log.Ltime | log.Lshortfile)
log.SetOutput(&testLogWriter{t})
}
func UnfixLogs(t *testing.T) {
defer log.SetOutput(os.Stderr)
}
type panicLogWriter struct{}
func (panicLogWriter) Write(b []byte) (int, error) {
// Allow certain phrases for now, in the interest of getting
// CI working on Windows and not having to refactor all the
// interfaces.GetState & tshttpproxy code to allow pushing
// down a Logger yet. TODO(bradfitz): do that refactoring once
// 1.2.0 is out.
if bytes.Contains(b, []byte("tshttpproxy: ")) ||
bytes.Contains(b, []byte("runtime/panic.go:")) ||
bytes.Contains(b, []byte("XXX")) {
os.Stderr.Write(b)
return len(b), nil
}
panic(fmt.Sprintf("please use tailscale.com/logger.Logf instead of the log package (tried to log: %q)", b))
}
// PanicOnLog modifies the standard library log package's default output to
// an io.Writer that panics, to root out code that's not plumbing their logging
// through explicit tailscale.com/logger.Logf paths.
func PanicOnLog() {
log.SetOutput(panicLogWriter{})
}
// NewLogLineTracker produces a LogLineTracker wrapping a given logf that tracks whether expectedFormatStrings were seen.
func NewLogLineTracker(logf logger.Logf, expectedFormatStrings []string) *LogLineTracker {
ret := &LogLineTracker{
logf: logf,
listenFor: expectedFormatStrings,
seen: make(map[string]bool),
}
for _, line := range expectedFormatStrings {
ret.seen[line] = false
}
return ret
}
// LogLineTracker is a logger that tracks which log format patterns it's
// seen and can report which expected ones were not seen later.
type LogLineTracker struct {
logf logger.Logf
listenFor []string
mu sync.Mutex
closed bool
seen map[string]bool // format string => false (if not yet seen but wanted) or true (once seen)
}
// Logf logs to its underlying logger and also tracks that the given format pattern has been seen.
func (lt *LogLineTracker) Logf(format string, args ...any) {
lt.mu.Lock()
if lt.closed {
lt.mu.Unlock()
return
}
if v, ok := lt.seen[format]; ok && !v {
lt.seen[format] = true
}
lt.mu.Unlock()
lt.logf(format, args...)
}
// Check returns which format strings haven't been logged yet.
func (lt *LogLineTracker) Check() []string {
lt.mu.Lock()
defer lt.mu.Unlock()
var notSeen []string
for _, format := range lt.listenFor {
if !lt.seen[format] {
notSeen = append(notSeen, format)
}
}
return notSeen
}
// Reset forgets everything that it's seen.
func (lt *LogLineTracker) Reset() {
lt.mu.Lock()
defer lt.mu.Unlock()
for _, line := range lt.listenFor {
lt.seen[line] = false
}
}
// Close closes lt. After calling Close, calls to Logf become no-ops.
func (lt *LogLineTracker) Close() {
lt.mu.Lock()
defer lt.mu.Unlock()
lt.closed = true
}
// MemLogger is a bytes.Buffer with a Logf method for tests that want
// to log to a buffer.
type MemLogger struct {
sync.Mutex
bytes.Buffer
}
func (ml *MemLogger) Logf(format string, args ...any) {
ml.Lock()
defer ml.Unlock()
fmt.Fprintf(&ml.Buffer, format, args...)
if !mem.HasSuffix(mem.B(ml.Buffer.Bytes()), mem.S("\n")) {
ml.Buffer.WriteByte('\n')
}
}
func (ml *MemLogger) String() string {
ml.Lock()
defer ml.Unlock()
return ml.Buffer.String()
}
// WhileTestRunningLogger returns a logger.Logf that logs to t.Logf until the
// test finishes, at which point it no longer logs anything.
func WhileTestRunningLogger(t testenv.TB) logger.Logf {
var (
mu sync.RWMutex
done bool
)
tlogf := logger.TestLogger(t)
logger := func(format string, args ...any) {
t.Helper()
mu.RLock()
defer mu.RUnlock()
if done {
return
}
tlogf(format, args...)
}
// t.Cleanup is run before the test is marked as done, so by acquiring
// the mutex and then disabling logs, we know that all existing log
// functions have completed, and that no future calls to the logger
// will log something.
//
// We can't do this with an atomic bool, since it's possible to
// observe the following race:
//
// test goroutine goroutine 1
// -------------- -----------
// check atomic, testFinished = no
// test finishes
// run t.Cleanups
// set testFinished = true
// call t.Logf
// panic
//
// Using a mutex ensures that all actions in goroutine 1 in the
// sequence above occur atomically, and thus should not panic.
t.Cleanup(func() {
mu.Lock()
defer mu.Unlock()
done = true
})
return logger
}
|
