2020-02-05 22:16:58 +00:00
|
|
|
// Copyright (c) 2020 Tailscale Inc & AUTHORS All rights reserved.
|
|
|
|
// Use of this source code is governed by a BSD-style
|
|
|
|
// license that can be found in the LICENSE file.
|
|
|
|
|
2020-04-29 02:56:11 +00:00
|
|
|
package tstest
|
2020-02-05 22:16:58 +00:00
|
|
|
|
|
|
|
import (
|
2020-10-28 15:23:12 +00:00
|
|
|
"bytes"
|
|
|
|
"fmt"
|
2020-02-05 22:16:58 +00:00
|
|
|
"log"
|
|
|
|
"os"
|
2020-08-25 18:42:54 +00:00
|
|
|
"sync"
|
2020-02-05 22:16:58 +00:00
|
|
|
"testing"
|
2020-08-25 18:42:54 +00:00
|
|
|
|
|
|
|
"tailscale.com/types/logger"
|
2020-02-05 22:16:58 +00:00
|
|
|
)
|
|
|
|
|
|
|
|
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)
|
|
|
|
}
|
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 02:59:54 +00:00
|
|
|
|
2020-05-14 17:05:32 +00:00
|
|
|
type panicLogWriter struct{}
|
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 02:59:54 +00:00
|
|
|
|
2020-05-14 17:05:32 +00:00
|
|
|
func (panicLogWriter) Write(b []byte) (int, error) {
|
2020-10-28 15:23:12 +00:00
|
|
|
// 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: ")) {
|
|
|
|
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))
|
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 02:59:54 +00:00
|
|
|
}
|
|
|
|
|
2020-05-14 17:05:32 +00: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.
|
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 02:59:54 +00:00
|
|
|
func PanicOnLog() {
|
2020-05-14 17:05:32 +00:00
|
|
|
log.SetOutput(panicLogWriter{})
|
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 02:59:54 +00:00
|
|
|
}
|
2020-08-25 18:42:54 +00:00
|
|
|
|
2020-09-04 15:09:56 +00:00
|
|
|
// NewLogLineTracker produces a LogLineTracker wrapping a given logf that tracks whether expectedFormatStrings were seen.
|
|
|
|
func NewLogLineTracker(logf logger.Logf, expectedFormatStrings []string) *LogLineTracker {
|
|
|
|
ret := &LogLineTracker{
|
2020-08-25 18:42:54 +00:00
|
|
|
logf: logf,
|
2020-09-04 15:09:56 +00:00
|
|
|
listenFor: expectedFormatStrings,
|
2020-08-25 18:42:54 +00:00
|
|
|
seen: make(map[string]bool),
|
|
|
|
}
|
2020-09-04 15:09:56 +00:00
|
|
|
for _, line := range expectedFormatStrings {
|
2020-08-25 18:42:54 +00:00
|
|
|
ret.seen[line] = false
|
|
|
|
}
|
2020-09-04 15:09:56 +00:00
|
|
|
return ret
|
2020-08-25 18:42:54 +00:00
|
|
|
}
|
|
|
|
|
2020-09-04 15:09:56 +00:00
|
|
|
// 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 {
|
2020-08-25 18:42:54 +00:00
|
|
|
logf logger.Logf
|
|
|
|
listenFor []string
|
|
|
|
|
|
|
|
mu sync.Mutex
|
2020-09-04 15:09:56 +00:00
|
|
|
seen map[string]bool // format string => false (if not yet seen but wanted) or true (once seen)
|
2020-08-25 18:42:54 +00:00
|
|
|
}
|
|
|
|
|
2020-09-04 15:09:56 +00:00
|
|
|
// Logf logs to its underlying logger and also tracks that the given format pattern has been seen.
|
|
|
|
func (lt *LogLineTracker) Logf(format string, args ...interface{}) {
|
|
|
|
lt.mu.Lock()
|
|
|
|
if v, ok := lt.seen[format]; ok && !v {
|
|
|
|
lt.seen[format] = true
|
2020-08-25 18:42:54 +00:00
|
|
|
}
|
2020-09-04 15:09:56 +00:00
|
|
|
lt.mu.Unlock()
|
2020-09-04 15:31:43 +00:00
|
|
|
lt.logf(format, args...)
|
2020-08-25 18:42:54 +00:00
|
|
|
}
|
|
|
|
|
2020-09-04 15:09:56 +00:00
|
|
|
// Check returns which format strings haven't been logged yet.
|
|
|
|
func (lt *LogLineTracker) Check() []string {
|
|
|
|
lt.mu.Lock()
|
|
|
|
defer lt.mu.Unlock()
|
2020-08-25 18:42:54 +00:00
|
|
|
var notSeen []string
|
2020-09-04 15:09:56 +00:00
|
|
|
for _, format := range lt.listenFor {
|
|
|
|
if !lt.seen[format] {
|
|
|
|
notSeen = append(notSeen, format)
|
2020-08-25 18:42:54 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
return notSeen
|
|
|
|
}
|