tailscale/tstest/log.go

194 lines
4.8 KiB
Go
Raw Normal View History

// Copyright (c) Tailscale Inc & AUTHORS
// SPDX-License-Identifier: BSD-3-Clause
package tstest
import (
"bytes"
"fmt"
"log"
"os"
"sync"
"testing"
"go4.org/mem"
"tailscale.com/types/logger"
)
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)
}
2020-05-14 18:05:32 +01:00
type panicLogWriter struct{}
2020-05-14 18:05:32 +01:00
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:")) {
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))
}
2020-05-14 18:05:32 +01:00
// 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() {
2020-05-14 18:05:32 +01:00
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 testing.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
}