mirror of
https://github.com/Control-D-Inc/ctrld.git
synced 2026-10-12 01:58:46 +02:00
fix(cli): fix three log journal defects and test Windows with the race detector
This commit is contained in:
1 parent
462f912495
commit
db228a86ae
13 files changed
+505
-31
No files matched your search
@@ -170,3 +170,59 @@ func Test_allEndpointsFailedBoundsTheUpstreamName(t *testing.T) {
|
||||
t.Fatalf("the all-endpoints line holds the operator key: %q", reported)
|
||||
}
|
||||
}
|
||||
|
||||
// Test_upstreamOutageOnTheQueryPathLogsOneStatePair drives 633 failed queries
|
||||
// through the real query path, the count of the customer upload that sized the
|
||||
// journal. The outage must give one down event, and the recovery one up event
|
||||
// with the length of the outage.
|
||||
func Test_upstreamOutageOnTheQueryPathLogsOneStatePair(t *testing.T) {
|
||||
const failedQueries = 633
|
||||
logs := captureDebugMainLog(t)
|
||||
cfg := &ctrld.Config{}
|
||||
cfg.Service.LeakOnUpstreamFailure = func(v bool) *bool { return &v }(false)
|
||||
p := &prog{cfg: cfg, um: newUpstreamMonitor(cfg)}
|
||||
// A new monitor holds back the failure counts for one second. The test
|
||||
// clears the flag instead of waiting for that timer.
|
||||
p.um.clearRecovered(upstreamOS)
|
||||
p.um.after = func(time.Duration, func()) {}
|
||||
t.Cleanup(func() { p.querySampler.closeExpired(time.Now().Add(querySampleWindow)) })
|
||||
|
||||
origOSUpstream := osUpstreamConfig
|
||||
t.Cleanup(func() { osUpstreamConfig = origOSUpstream })
|
||||
// Windows reports no port-unreachable error on a UDP socket, so each query
|
||||
// waits for the full timeout there. A short timeout keeps 633 queries fast.
|
||||
osUpstreamConfig = &ctrld.UpstreamConfig{
|
||||
Name: "dead resolver",
|
||||
Type: ctrld.ResolverTypeLegacy,
|
||||
Endpoint: deadUpstreamEndpoint,
|
||||
Timeout: 20,
|
||||
}
|
||||
|
||||
ctx := context.Background()
|
||||
for i := 0; i < failedQueries; i++ {
|
||||
if rcode := askThroughProxy(t, p, ctx).Rcode; rcode != dns.RcodeServerFailure {
|
||||
t.Fatalf("query %d: rcode %s, want SERVFAIL", i+1, dns.RcodeToString[rcode])
|
||||
}
|
||||
}
|
||||
events := jsonLogEvents(t, logs, upstreamStateMessage)
|
||||
if len(events) != 1 {
|
||||
t.Fatalf("state events after %d failed queries: got %d, want 1", failedQueries, len(events))
|
||||
}
|
||||
wantField(t, events[0], "upstream", upstreamOS)
|
||||
wantField(t, events[0], "state", "down")
|
||||
|
||||
startOSResolverStub(t)
|
||||
if rcode := askThroughProxy(t, p, ctx).Rcode; rcode != dns.RcodeSuccess {
|
||||
t.Fatalf("the answered query returned %s, want NOERROR", dns.RcodeToString[rcode])
|
||||
}
|
||||
|
||||
events = jsonLogEvents(t, logs, upstreamStateMessage)
|
||||
if len(events) != 2 {
|
||||
t.Fatalf("state events after the recovery: got %d, want 2", len(events))
|
||||
}
|
||||
wantField(t, events[1], "upstream", upstreamOS)
|
||||
wantField(t, events[1], "state", "up")
|
||||
if _, carried := events[1]["down_for_ms"].(float64); !carried {
|
||||
t.Fatalf("the up event carries no down_for_ms: %v", events[1])
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,142 @@
|
||||
package cli
|
||||
|
||||
import (
|
||||
"os"
|
||||
"path/filepath"
|
||||
"strconv"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/Control-D-Inc/ctrld"
|
||||
)
|
||||
|
||||
// setupDebugBudgetTest seeds a debug file with four backups, which is the
|
||||
// default count, and puts back the two limit keys after the test.
|
||||
func setupDebugBudgetTest(t *testing.T) string {
|
||||
t.Helper()
|
||||
dir := setupLogSetupTest(t)
|
||||
origSize, origBackups := cfg.Service.LogMaxSizeMB, cfg.Service.LogMaxBackups
|
||||
t.Cleanup(func() {
|
||||
cfg.Service.LogMaxSizeMB, cfg.Service.LogMaxBackups = origSize, origBackups
|
||||
})
|
||||
cfg.Service.LogMaxSizeMB, cfg.Service.LogMaxBackups = 0, nil
|
||||
debugPath := filepath.Join(dir, logFileName)
|
||||
for i := 1; i <= 4; i++ {
|
||||
if err := os.WriteFile(debugPath+"."+strconv.Itoa(i), []byte("old run\n"), 0o600); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
}
|
||||
return debugPath
|
||||
}
|
||||
|
||||
// assertDebugBudget checks the limits of the open debug file and the backups
|
||||
// that stay on disk.
|
||||
func assertDebugBudget(t *testing.T, p *prog, debugPath string, want logBudget) {
|
||||
t.Helper()
|
||||
debugWriter, _ := p.internalWriters()
|
||||
rf := debugWriter.rotating()
|
||||
if rf == nil {
|
||||
t.Fatal("the debug file is not open")
|
||||
}
|
||||
rf.mu.Lock()
|
||||
got := rf.budget
|
||||
rf.mu.Unlock()
|
||||
if got != want {
|
||||
t.Fatalf("debug budget = %+v, want %+v", got, want)
|
||||
}
|
||||
for i := 1; i <= 4; i++ {
|
||||
_, err := os.Stat(debugPath + "." + strconv.Itoa(i))
|
||||
if i <= want.backups && err != nil {
|
||||
t.Fatalf("backup %d is gone: %v", i, err)
|
||||
}
|
||||
if i > want.backups && !os.IsNotExist(err) {
|
||||
t.Fatalf("backup %d stays although the limit is %d backups (stat err = %v)", i, want.backups, err)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// Test_initLogging_appliesTheLimitsOfTheFetchedConfig drives a first start:
|
||||
// the debug file opens with the local config, and the API preflight then
|
||||
// writes the limit keys. The second logging setup must apply them at once, so
|
||||
// no second restart is necessary.
|
||||
func Test_initLogging_appliesTheLimitsOfTheFetchedConfig(t *testing.T) {
|
||||
debugPath := setupDebugBudgetTest(t)
|
||||
cdUID = "test-uid"
|
||||
p := &prog{cfg: &cfg}
|
||||
p.initLogging(true)
|
||||
t.Cleanup(p.closeInternalLogs)
|
||||
defaultBudget, _ := logBudgets(false)
|
||||
assertDebugBudget(t, p, debugPath, defaultBudget)
|
||||
|
||||
oneBackup := 1
|
||||
cfg.Service.LogMaxSizeMB, cfg.Service.LogMaxBackups = 20, &oneBackup
|
||||
p.initLogging(false)
|
||||
|
||||
assertDebugBudget(t, p, debugPath, logBudget{maxSize: 20 << 20, backups: 1})
|
||||
}
|
||||
|
||||
// Test_applyDebugLogBudget_takesTheLimitsOfARefreshedConfig drives a managed
|
||||
// config refresh, which applies a new config with no restart.
|
||||
func Test_applyDebugLogBudget_takesTheLimitsOfARefreshedConfig(t *testing.T) {
|
||||
debugPath := setupDebugBudgetTest(t)
|
||||
cdUID = "test-uid"
|
||||
p := &prog{cfg: &cfg}
|
||||
p.initLogging(true)
|
||||
t.Cleanup(p.closeInternalLogs)
|
||||
|
||||
noBackups := 0
|
||||
refreshed := ctrld.ServiceConfig{LogMaxSizeMB: 5, LogMaxBackups: &noBackups}
|
||||
p.applyDebugLogBudget(debugLogBudget(&refreshed, false))
|
||||
|
||||
assertDebugBudget(t, p, debugPath, logBudget{maxSize: 5 << 20, backups: 0})
|
||||
}
|
||||
|
||||
// Test_applyDebugLogBudget_takesTheLimitsForLogPath checks the log_path file,
|
||||
// which follows the same two keys. ctrld does not prune its backups, because
|
||||
// log_path can name a directory that holds the files of other programs.
|
||||
func Test_applyDebugLogBudget_takesTheLimitsForLogPath(t *testing.T) {
|
||||
setupDebugBudgetTest(t)
|
||||
logPath := filepath.Join(t.TempDir(), "operator.log")
|
||||
cfg.Service.LogPath = logPath
|
||||
p := &prog{cfg: &cfg}
|
||||
p.initLogging(true)
|
||||
|
||||
want := logBudget{maxSize: 3 << 20, backups: 2}
|
||||
p.applyDebugLogBudget(want)
|
||||
|
||||
rf := logPathFile.Load()
|
||||
rf.mu.Lock()
|
||||
got := rf.budget
|
||||
rf.mu.Unlock()
|
||||
if got != want {
|
||||
t.Fatalf("log_path budget = %+v, want %+v", got, want)
|
||||
}
|
||||
}
|
||||
|
||||
// Test_initLogging_reportsTheRotationOfTheStartHeader drives a restart that
|
||||
// finds the journal close to its limit. The header of the new run rotates the
|
||||
// file, and the rotation event must reach the files, because support reads it
|
||||
// to learn where the history of the last run went.
|
||||
func Test_initLogging_reportsTheRotationOfTheStartHeader(t *testing.T) {
|
||||
dir := setupLogSetupTest(t)
|
||||
cdUID = "test-uid"
|
||||
_, journalBudget := logBudgets(false)
|
||||
journalPath := filepath.Join(dir, journalLogFileName)
|
||||
oldRun := strings.Repeat("o", int(journalBudget.maxSize)-10) + "\n"
|
||||
if err := os.WriteFile(journalPath, []byte(oldRun), 0o600); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
p := &prog{cfg: &cfg}
|
||||
|
||||
p.initLogging(true)
|
||||
t.Cleanup(p.closeInternalLogs)
|
||||
|
||||
if backup := rotatingFileTestContent(t, journalPath+".1"); backup != oldRun {
|
||||
t.Fatalf("the journal backup holds %d bytes, want the %d bytes of the old run", len(backup), len(oldRun))
|
||||
}
|
||||
for _, path := range []string{journalPath, filepath.Join(dir, logFileName)} {
|
||||
if content := rotatingFileTestContent(t, path); !strings.Contains(content, "Log rotated") {
|
||||
t.Fatalf("%s holds no rotation event: %s", filepath.Base(path), content)
|
||||
}
|
||||
}
|
||||
}
|
||||
+30
-6
@@ -134,8 +134,14 @@ func (rf *rotatingFile) writeReporting(p []byte) (int, *logRotation, error) {
|
||||
// after the lock is free, so the rotation event can go back into this file.
|
||||
func (rf *rotatingFile) Write(p []byte) (int, error) {
|
||||
n, rotated, err := rf.writeReporting(p)
|
||||
rf.reportRotation(rotated)
|
||||
return n, err
|
||||
}
|
||||
|
||||
// reportRotation calls onRotate for a rotation. It must run with rf.mu free.
|
||||
func (rf *rotatingFile) reportRotation(rotated *logRotation) {
|
||||
if rotated == nil || !rf.rotatedInFlight.CompareAndSwap(false, true) {
|
||||
return n, err
|
||||
return
|
||||
}
|
||||
defer rf.rotatedInFlight.Store(false)
|
||||
rf.mu.Lock()
|
||||
@@ -144,7 +150,6 @@ func (rf *rotatingFile) Write(p []byte) (int, error) {
|
||||
if onRotate != nil {
|
||||
onRotate(*rotated)
|
||||
}
|
||||
return n, err
|
||||
}
|
||||
|
||||
// setHeader stores a copy of the header bytes for the next file.
|
||||
@@ -158,14 +163,33 @@ func (rf *rotatingFile) setHeader(b []byte) {
|
||||
|
||||
// writeHeader appends the stored header to the current file, once for each
|
||||
// file that the writer opens. A restart uses it to mark the point where the
|
||||
// new run continues an old file.
|
||||
// new run continues an old file. A header that makes the file cross its
|
||||
// budget goes to a new file, which the rotation starts with the header.
|
||||
func (rf *rotatingFile) writeHeader() error {
|
||||
rotated, err := rf.writeHeaderReporting()
|
||||
rf.reportRotation(rotated)
|
||||
return err
|
||||
}
|
||||
|
||||
// writeHeaderReporting writes the header and reports a rotation that the header
|
||||
// caused. It never calls onRotate, because the caller must log the rotation
|
||||
// outside of the lock, and at start the logger does not reach the files yet.
|
||||
func (rf *rotatingFile) writeHeaderReporting() (*logRotation, error) {
|
||||
rf.mu.Lock()
|
||||
defer rf.mu.Unlock()
|
||||
if rf.headerWritten {
|
||||
return nil
|
||||
if rf.headerWritten || len(rf.header) == 0 {
|
||||
return nil, nil
|
||||
}
|
||||
return rf.writeHeaderLocked()
|
||||
if !rf.needsRotation(len(rf.header)) {
|
||||
return nil, rf.writeHeaderLocked()
|
||||
}
|
||||
rotated, err := rf.rotateLocked()
|
||||
if err != nil || rf.headerWritten {
|
||||
return rotated, err
|
||||
}
|
||||
// The file could not move, so the run continues in the old file, and the
|
||||
// header must still mark the point where the run starts.
|
||||
return rotated, rf.writeHeaderLocked()
|
||||
}
|
||||
|
||||
// setBudget takes the disk space of a later config. The file stays open, so a
|
||||
|
||||
@@ -551,3 +551,72 @@ func Test_zeroBackupRotationKeepsTheOpenReader(t *testing.T) {
|
||||
t.Fatalf("the moved file is still on disk: %v", err)
|
||||
}
|
||||
}
|
||||
|
||||
// Test_rotatingFileHeaderStaysInTheBudget drives a restart that finds a file
|
||||
// close to its limit. The header of the new run must go to a new file, so no
|
||||
// file grows over its budget.
|
||||
func Test_rotatingFileHeaderStaysInTheBudget(t *testing.T) {
|
||||
budget := logBudget{maxSize: 4096, backups: 1}
|
||||
path := filepath.Join(t.TempDir(), "ctrld-journal.log")
|
||||
oldRun := strings.Repeat("o", int(budget.maxSize)-10) + "\n"
|
||||
if err := os.WriteFile(path, []byte(oldRun), 0o600); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
rf, err := newRotatingFile(path, budget, nil)
|
||||
if err != nil {
|
||||
t.Fatalf("newRotatingFile: %v", err)
|
||||
}
|
||||
t.Cleanup(func() { _ = rf.close() })
|
||||
var rotations []logRotation
|
||||
rf.onRotate = func(record logRotation) { rotations = append(rotations, record) }
|
||||
header := []byte(`{"level":"info","journal":true,"message":"Log header"}` + "\n")
|
||||
rf.setHeader(header)
|
||||
|
||||
if err := rf.writeHeader(); err != nil {
|
||||
t.Fatalf("writeHeader: %v", err)
|
||||
}
|
||||
|
||||
if backup := rotatingFileTestContent(t, path+".1"); backup != oldRun {
|
||||
t.Fatalf("the backup holds %d bytes, want the %d bytes of the old run only", len(backup), len(oldRun))
|
||||
}
|
||||
if current := rotatingFileTestContent(t, path); current != string(header) {
|
||||
t.Fatalf("the current file holds %q, want the header only", current)
|
||||
}
|
||||
if len(rotations) != 1 || rotations[0].bytesWritten != int64(len(oldRun)) {
|
||||
t.Fatalf("rotations = %+v, want one event for the old file", rotations)
|
||||
}
|
||||
}
|
||||
|
||||
// Test_rotatingFileHeaderAfterAFailedRotation covers a restart whose rotation
|
||||
// cannot move the old file. The run continues in that file, and the header
|
||||
// must still mark the point where the run starts.
|
||||
func Test_rotatingFileHeaderAfterAFailedRotation(t *testing.T) {
|
||||
renameErr := errors.New("rename refused")
|
||||
budget := logBudget{maxSize: 4096, backups: 1}
|
||||
path := filepath.Join(t.TempDir(), "ctrld-journal.log")
|
||||
oldRun := strings.Repeat("o", int(budget.maxSize)-10) + "\n"
|
||||
if err := os.WriteFile(path, []byte(oldRun), 0o600); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
rf, err := newRotatingFile(path, budget, nil)
|
||||
if err != nil {
|
||||
t.Fatalf("newRotatingFile: %v", err)
|
||||
}
|
||||
t.Cleanup(func() { _ = rf.close() })
|
||||
rf.rename = func(string, string) error { return renameErr }
|
||||
var rotations []logRotation
|
||||
rf.onRotate = func(record logRotation) { rotations = append(rotations, record) }
|
||||
header := []byte(`{"level":"info","journal":true,"message":"Log header"}` + "\n")
|
||||
rf.setHeader(header)
|
||||
|
||||
if err := rf.writeHeader(); err != nil {
|
||||
t.Fatalf("writeHeader: %v", err)
|
||||
}
|
||||
|
||||
if current := rotatingFileTestContent(t, path); current != oldRun+string(header) {
|
||||
t.Fatalf("the current file holds %d bytes, want the old run and one header", len(current))
|
||||
}
|
||||
if len(rotations) != 1 || !errors.Is(rotations[0].err, renameErr) {
|
||||
t.Fatalf("rotations = %+v, want one failed rotation", rotations)
|
||||
}
|
||||
}
|
||||
+10
-3
@@ -159,13 +159,20 @@ func (p *prog) refreshLogHeader() {
|
||||
|
||||
// writeLogHeaders puts the header at the append point of each open file. A
|
||||
// header that cannot land leaves the file usable, so the error only earns a
|
||||
// warning.
|
||||
func (p *prog) writeLogHeaders() {
|
||||
// warning. It returns the rotations that the headers caused, because the
|
||||
// logger does not reach the files yet and cannot report them.
|
||||
func (p *prog) writeLogHeaders() []logRotation {
|
||||
var rotations []logRotation
|
||||
for _, rf := range p.openLogFiles() {
|
||||
if err := rf.writeHeader(); err != nil {
|
||||
rotated, err := rf.writeHeaderReporting()
|
||||
if rotated != nil {
|
||||
rotations = append(rotations, *rotated)
|
||||
}
|
||||
if err != nil {
|
||||
mainLog.Load().Warn().Err(err).Msg("could not write log header")
|
||||
}
|
||||
}
|
||||
return rotations
|
||||
}
|
||||
|
||||
func prefixStrings(prefixes []netip.Prefix) []string {
|
||||
|
||||
@@ -570,3 +570,78 @@ func Test_boundedLogFilesFixTheSizeAtSelection(t *testing.T) {
|
||||
t.Fatalf("upload = %q (%d bytes), want %q within the budget of 4", got, upload.size, "one\n")
|
||||
}
|
||||
}
|
||||
|
||||
// seedFullLogChain writes a full chain of files at the desktop budget: the
|
||||
// current file and every backup, each file at its size limit. Every line names
|
||||
// its file, so a reader can tell which file a part comes from.
|
||||
func seedFullLogChain(t *testing.T, name string, budget logBudget) {
|
||||
t.Helper()
|
||||
path := absHomeDir(name)
|
||||
for index := budget.backups; index >= 0; index-- {
|
||||
filePath := path
|
||||
if index > 0 {
|
||||
filePath = fmt.Sprintf("%s.%d", path, index)
|
||||
}
|
||||
line := fmt.Sprintf("%s file=%d ", name, index)
|
||||
line += strings.Repeat("x", rotatingFileTestLineSize-len(line)-1) + "\n"
|
||||
content := bytes.Repeat([]byte(line), int(budget.maxSize)/len(line))
|
||||
if err := os.WriteFile(filePath, content, 0o600); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// Test_logReader_desktopBudgetUpload uses the desktop budgets, not the small
|
||||
// test budgets: 50 MB of debug files and a full journal chain. The normal
|
||||
// upload must stay under 17 MB, and the full upload must hold every file.
|
||||
func Test_logReader_desktopBudgetUpload(t *testing.T) {
|
||||
if testing.Short() {
|
||||
t.Skip("writes 56 MB of log files")
|
||||
}
|
||||
origSilent, origCdUID, origHomedir := silent, cdUID, homedir
|
||||
t.Cleanup(func() { silent, cdUID, homedir = origSilent, origCdUID, origHomedir })
|
||||
captureMainLog(t)
|
||||
setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel)
|
||||
stubLogHeaderNetworkRead(t, "en9")
|
||||
silent, cdUID, homedir = false, "test-uid", t.TempDir()
|
||||
debugBudget, journalBudget := logBudgets(false)
|
||||
seedFullLogChain(t, logFileName, debugBudget)
|
||||
seedFullLogChain(t, journalLogFileName, journalBudget)
|
||||
|
||||
p := &prog{cfg: &ctrld.Config{}}
|
||||
p.internalLogWriter = newLogWriterWithSize(logWriterSize)
|
||||
p.internalJournalWriter = newLogWriterWithSize(logWriterSmallSize)
|
||||
for _, stream := range []struct {
|
||||
lw *logWriter
|
||||
name string
|
||||
budget logBudget
|
||||
}{{p.internalLogWriter, logFileName, debugBudget}, {p.internalJournalWriter, journalLogFileName, journalBudget}} {
|
||||
if err := stream.lw.setLogFile(absHomeDir(stream.name), stream.budget); err != nil {
|
||||
t.Fatalf("setLogFile %s: %v", stream.name, err)
|
||||
}
|
||||
t.Cleanup(stream.lw.closeLogFile)
|
||||
}
|
||||
wholeDebug := logFilesContent(t, p.internalLogWriter.rotating().paths())
|
||||
wholeJournal := logFilesContent(t, p.internalJournalWriter.rotating().paths())
|
||||
if len(wholeDebug) < 50_000_000 {
|
||||
t.Fatalf("the debug files hold %d bytes, want at least 50 MB", len(wholeDebug))
|
||||
}
|
||||
|
||||
start := time.Now()
|
||||
upload := readLogReader(t, p, false)
|
||||
if len(upload) >= 17_000_000 {
|
||||
t.Fatalf("normal upload = %d bytes, want less than 17 MB", len(upload))
|
||||
}
|
||||
debugPart, journalPart := splitUpload(t, upload, start)
|
||||
if int64(len(debugPart)) > logSendDebugBudget || !bytes.HasSuffix(wholeDebug, debugPart) {
|
||||
t.Fatalf("debug part = %d bytes, want the newest bytes within %d", len(debugPart), logSendDebugBudget)
|
||||
}
|
||||
if !bytes.Equal(journalPart, wholeJournal) {
|
||||
t.Fatalf("journal part = %d bytes, want the %d bytes of the journal chain", len(journalPart), len(wholeJournal))
|
||||
}
|
||||
|
||||
fullDebug, fullJournal := splitUpload(t, readLogReader(t, p, true), start)
|
||||
if !bytes.Equal(fullDebug, wholeDebug) || !bytes.Equal(fullJournal, wholeJournal) {
|
||||
t.Fatalf("full upload = %d debug and %d journal bytes, want %d and %d", len(fullDebug), len(fullJournal), len(wholeDebug), len(wholeJournal))
|
||||
}
|
||||
}
|
||||
+25
-1
@@ -347,6 +347,7 @@ func (p *prog) initInternalLogging(writers []io.Writer) {
|
||||
return
|
||||
}
|
||||
headersWritten := false
|
||||
var headerRotations []logRotation
|
||||
p.initInternalLogWriterOnce.Do(func() {
|
||||
mainLog.Load().Notice().Msg("internal logging enabled")
|
||||
p.internalLogWriter = newLogWriter()
|
||||
@@ -356,7 +357,7 @@ func (p *prog) initInternalLogging(writers []io.Writer) {
|
||||
// A restart appends to the file it finds, so the header marks the
|
||||
// point where this run starts.
|
||||
p.refreshLogHeader()
|
||||
p.writeLogHeaders()
|
||||
headerRotations = p.writeLogHeaders()
|
||||
headersWritten = true
|
||||
})
|
||||
lw, jlw := p.internalWriters()
|
||||
@@ -372,14 +373,37 @@ func (p *prog) initInternalLogging(writers []io.Writer) {
|
||||
l := mainLog.Load().Output(multi).With().Logger()
|
||||
mainLog.Store(&l)
|
||||
ctrld.ProxyLogger.Store(&l)
|
||||
// A header that crossed the budget rotated its file before the logger
|
||||
// reached the files, so its event waits for this logger.
|
||||
for _, rotated := range headerRotations {
|
||||
emitLogRotated(rotated)
|
||||
}
|
||||
if headersWritten {
|
||||
return
|
||||
}
|
||||
// A later call reaches a changed config, so the stored bytes need the new
|
||||
// values. The files keep the header they already hold.
|
||||
p.applyDebugLogBudget(debugLogBudget(&p.cfg.Service, router.Name() != ""))
|
||||
p.refreshLogHeader()
|
||||
}
|
||||
|
||||
// applyDebugLogBudget gives the open debug files the limits of the config that
|
||||
// runs now. The files open before the API config arrives, and a managed config
|
||||
// refresh can change the limits with no restart. Only the internal file gets a
|
||||
// prune: ctrld owns its name, while log_path can name a file in a directory
|
||||
// that holds the files of other programs.
|
||||
func (p *prog) applyDebugLogBudget(budget logBudget) {
|
||||
if debugWriter, _ := p.internalWriters(); debugWriter != nil {
|
||||
if rf := debugWriter.rotating(); rf != nil {
|
||||
rf.setBudget(budget)
|
||||
pruneNumberedBackups(rf.currentPath(), budget.backups)
|
||||
}
|
||||
}
|
||||
if rf := logPathFile.Load(); rf != nil {
|
||||
rf.setBudget(budget)
|
||||
}
|
||||
}
|
||||
|
||||
// wrapConsoleWritersAtNotice holds the console at notice level while the files
|
||||
// take every level. A run without -v needs the detail for troubleshooting, and
|
||||
// the same detail on the console is noise.
|
||||
|
||||
@@ -5,6 +5,7 @@ import (
|
||||
"net"
|
||||
"net/netip"
|
||||
"slices"
|
||||
"strings"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
@@ -260,11 +261,21 @@ func wantNoField(t *testing.T, event map[string]any, field string) {
|
||||
// noiseDeltaStates returns a delta that moves the AirDrop link-local address.
|
||||
func noiseDeltaStates(t *testing.T, step int) (before, after *netmon.State) {
|
||||
t.Helper()
|
||||
airdrop := func(address int) deltaTestInterface {
|
||||
return deltaTestInterface{name: "awdl0", up: true, mtu: 1484, ips: []string{fmt.Sprintf("fe80::%d/64", address)}}
|
||||
return noiseDeltaStatesFor(t, step, "awdl0")
|
||||
}
|
||||
|
||||
// noiseDeltaStatesFor returns a delta that moves the link-local address of
|
||||
// each named noise interface.
|
||||
func noiseDeltaStatesFor(t *testing.T, step int, names ...string) (before, after *netmon.State) {
|
||||
t.Helper()
|
||||
noise := func(address int) []deltaTestInterface {
|
||||
interfaces := []deltaTestInterface{networkEventsHardwareIface}
|
||||
for _, name := range names {
|
||||
interfaces = append(interfaces, deltaTestInterface{name: name, up: true, mtu: 1484, ips: []string{fmt.Sprintf("fe80::%d/64", address)}})
|
||||
}
|
||||
return interfaces
|
||||
}
|
||||
return deltaTestState(t, "en0", networkEventsHardwareIface, airdrop(step)),
|
||||
deltaTestState(t, "en0", networkEventsHardwareIface, airdrop(step+1))
|
||||
return deltaTestState(t, "en0", noise(step)...), deltaTestState(t, "en0", noise(step+1)...)
|
||||
}
|
||||
|
||||
func wantStringsField(t *testing.T, event map[string]any, field string, want ...string) {
|
||||
@@ -286,22 +297,29 @@ func wantStringsField(t *testing.T, event map[string]any, field string, want ...
|
||||
}
|
||||
}
|
||||
|
||||
// Test_networkEventsNoiseDeltaSkipsTheHandler covers the AirDrop link, the
|
||||
// low-latency Wi-Fi link, and both in one callback, as an AirDrop transfer
|
||||
// gives them.
|
||||
func Test_networkEventsNoiseDeltaSkipsTheHandler(t *testing.T) {
|
||||
h := newNetworkEventsHarness(t, "en0")
|
||||
for _, names := range [][]string{{"awdl0"}, {"llw0"}, {"awdl0", "llw0"}} {
|
||||
t.Run(strings.Join(names, "+"), func(t *testing.T) {
|
||||
h := newNetworkEventsHarness(t, "en0")
|
||||
|
||||
before, after := noiseDeltaStates(t, 1)
|
||||
h.handle(before, after, false)
|
||||
before, after := noiseDeltaStatesFor(t, 1, names...)
|
||||
h.handle(before, after, false)
|
||||
|
||||
if h.reconciled != 0 || h.ignored != 0 {
|
||||
t.Fatalf("noise delta ran the handler: reconciled=%d ignored=%d, want 0/0", h.reconciled, h.ignored)
|
||||
}
|
||||
debugLines := h.eventsAtLevel(t, noiseDeltaMessage, "debug")
|
||||
if len(debugLines) != 1 {
|
||||
t.Fatalf("got %d debug %q lines, want 1", len(debugLines), noiseDeltaMessage)
|
||||
}
|
||||
wantStringsField(t, debugLines[0], "interfaces", "awdl0")
|
||||
if events := jsonLogEvents(t, h.logs, networkTransitionMessage); len(events) != 0 {
|
||||
t.Fatalf("got %d %q events for a noise delta, want 0", len(events), networkTransitionMessage)
|
||||
if h.reconciled != 0 || h.ignored != 0 {
|
||||
t.Fatalf("noise delta ran the handler: reconciled=%d ignored=%d, want 0/0", h.reconciled, h.ignored)
|
||||
}
|
||||
debugLines := h.eventsAtLevel(t, noiseDeltaMessage, "debug")
|
||||
if len(debugLines) != 1 {
|
||||
t.Fatalf("got %d debug %q lines, want 1", len(debugLines), noiseDeltaMessage)
|
||||
}
|
||||
wantStringsField(t, debugLines[0], "interfaces", names...)
|
||||
if events := jsonLogEvents(t, h.logs, networkTransitionMessage); len(events) != 0 {
|
||||
t.Fatalf("got %d %q events for a noise delta, want 0", len(events), networkTransitionMessage)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -116,19 +116,36 @@ func buildNetworkSnapshot(in snapshotInputs) networkSnapshot {
|
||||
var routeAddresses []netip.Prefix
|
||||
if in.State != nil {
|
||||
meta := interfaceMetaWithClass(in.Meta)
|
||||
routeMeta = meta(in.State.DefaultRouteInterface)
|
||||
routeAddresses = in.State.InterfaceIPs[in.State.DefaultRouteInterface]
|
||||
snapshot.HaveV4, snapshot.HaveV6 = in.State.HaveV4, in.State.HaveV6
|
||||
snapshot.Interfaces, snapshot.InterfacesOmitted = snapshotInterfaces(in.State, meta)
|
||||
if snapshot.DefaultRouteV4 == "" {
|
||||
// Only a platform that reads no route table takes the route of the
|
||||
// network monitor. On macOS an empty v4 route is a fact, and the
|
||||
// monitor can still hold the interface of the last network.
|
||||
if in.RouteV4.Interface == "" && in.RouteV6.Interface == "" {
|
||||
snapshot.DefaultRouteV4 = defaultRouteV4Interface(in.State)
|
||||
}
|
||||
linkInterface := snapshotLinkInterface(in)
|
||||
routeMeta = meta(linkInterface)
|
||||
routeAddresses = in.State.InterfaceIPs[linkInterface]
|
||||
}
|
||||
snapshot.LinkType = linkTypeFor(routeMeta.HardwarePort, routeMeta.Class)
|
||||
snapshot.Tethered = tetheredNetwork(in.RouteV4.Gateway, routeMeta.HardwarePort, routeAddresses)
|
||||
return snapshot
|
||||
}
|
||||
|
||||
// snapshotLinkInterface names the interface that the link fields describe.
|
||||
// The route table wins over the network monitor: during a switch the monitor
|
||||
// can still hold the old interface, and one record must not mix the routes of
|
||||
// one moment with the link type of another. It must run with a state.
|
||||
func snapshotLinkInterface(in snapshotInputs) string {
|
||||
for _, name := range []string{in.RouteV4.Interface, in.RouteV6.Interface} {
|
||||
if name != "" {
|
||||
return name
|
||||
}
|
||||
}
|
||||
return in.State.DefaultRouteInterface
|
||||
}
|
||||
|
||||
// interfaceMetaWithClass fills the class that the platform metadata leaves
|
||||
// empty. A host that names no port still tells a tunnel from a hardware port
|
||||
// by the interface name.
|
||||
|
||||
@@ -558,3 +558,40 @@ func sortedKeys(object map[string]any) []string {
|
||||
slices.Sort(keys)
|
||||
return keys
|
||||
}
|
||||
|
||||
// Test_buildNetworkSnapshot_linkFieldsFollowTheRouteTable covers a network
|
||||
// switch. The network monitor still holds the old Ethernet interface, while the
|
||||
// route table already selects Wi-Fi. The link fields must describe the
|
||||
// interface of the routes in the same record.
|
||||
func Test_buildNetworkSnapshot_linkFieldsFollowTheRouteTable(t *testing.T) {
|
||||
meta := snapshotTestMeta(map[string]interfaceMeta{
|
||||
"en0": {Class: "hardware", HardwarePort: "Ethernet"},
|
||||
"en1": {Class: "hardware", HardwarePort: "Wi-Fi"},
|
||||
})
|
||||
for _, tt := range []struct {
|
||||
name string
|
||||
routeV4 defaultRoute
|
||||
routeV6 defaultRoute
|
||||
}{
|
||||
{name: "dual_stack", routeV4: defaultRoute{Interface: "en1"}, routeV6: defaultRoute{Interface: "en1"}},
|
||||
{name: "v6_only", routeV6: defaultRoute{Interface: "en1"}},
|
||||
} {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
state := snapshotTestState("en0",
|
||||
snapshotTestInterface{"en0", true, []string{"192.0.2.10/24"}},
|
||||
snapshotTestInterface{"en1", true, []string{"172.20.10.2/28"}})
|
||||
|
||||
snapshot := buildNetworkSnapshot(snapshotInputs{State: state, RouteV4: tt.routeV4, RouteV6: tt.routeV6, Meta: meta})
|
||||
|
||||
if snapshot.LinkType != "wifi" {
|
||||
t.Errorf("link_type = %q, want %q for the interface of the route table", snapshot.LinkType, "wifi")
|
||||
}
|
||||
if !snapshot.Tethered {
|
||||
t.Error("tethered = false, want true for the hotspot address of the route interface")
|
||||
}
|
||||
if snapshot.DefaultRouteV4 != tt.routeV4.Interface {
|
||||
t.Errorf("default_route_v4 = %q, want %q from the route table", snapshot.DefaultRouteV4, tt.routeV4.Interface)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
@@ -573,6 +573,7 @@ func (p *prog) runWait() {
|
||||
p.mu.Unlock()
|
||||
|
||||
closeReplacedUpstreams(oldUpstreams, newCfg.Upstream)
|
||||
p.applyDebugLogBudget(debugLogBudget(&newCfg.Service, router.Name() != ""))
|
||||
// The header names the mode, the listeners, and the upstreams, so the
|
||||
// open files take the values of the config that now runs.
|
||||
p.refreshLogHeader()
|
||||
|
||||
Reference in new issue
Block a user