diff --git a/cmd/cli/dns_proxy_sampling_test.go b/cmd/cli/dns_proxy_sampling_test.go index e6d27bb..9b27b63 100644 --- a/cmd/cli/dns_proxy_sampling_test.go +++ b/cmd/cli/dns_proxy_sampling_test.go @@ -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]) + } +} diff --git a/cmd/cli/log_budget_apply_test.go b/cmd/cli/log_budget_apply_test.go new file mode 100644 index 0000000..abc2774 --- /dev/null +++ b/cmd/cli/log_budget_apply_test.go @@ -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) + } + } +} diff --git a/cmd/cli/log_file.go b/cmd/cli/log_file.go index dee26e7..3dda04e 100644 --- a/cmd/cli/log_file.go +++ b/cmd/cli/log_file.go @@ -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 diff --git a/cmd/cli/log_file_test.go b/cmd/cli/log_file_test.go index 428be98..c5133a4 100644 --- a/cmd/cli/log_file_test.go +++ b/cmd/cli/log_file_test.go @@ -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) + } +} diff --git a/cmd/cli/log_header.go b/cmd/cli/log_header.go index 317da3d..015e561 100644 --- a/cmd/cli/log_header.go +++ b/cmd/cli/log_header.go @@ -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 { diff --git a/cmd/cli/log_reader_test.go b/cmd/cli/log_reader_test.go index 369401a..db49e23 100644 --- a/cmd/cli/log_reader_test.go +++ b/cmd/cli/log_reader_test.go @@ -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)) + } +} diff --git a/cmd/cli/log_writer.go b/cmd/cli/log_writer.go index 0c66fda..68a9bdd 100644 --- a/cmd/cli/log_writer.go +++ b/cmd/cli/log_writer.go @@ -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. diff --git a/cmd/cli/network_events_test.go b/cmd/cli/network_events_test.go index c8f47c1..b490280 100644 --- a/cmd/cli/network_events_test.go +++ b/cmd/cli/network_events_test.go @@ -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) + } + }) } } diff --git a/cmd/cli/network_snapshot.go b/cmd/cli/network_snapshot.go index 9af1c02..e52d2ab 100644 --- a/cmd/cli/network_snapshot.go +++ b/cmd/cli/network_snapshot.go @@ -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. diff --git a/cmd/cli/network_snapshot_test.go b/cmd/cli/network_snapshot_test.go index f1276dd..ed2b7c5 100644 --- a/cmd/cli/network_snapshot_test.go +++ b/cmd/cli/network_snapshot_test.go @@ -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) + } + }) + } +} diff --git a/cmd/cli/prog.go b/cmd/cli/prog.go index 7957fa2..8bb1f77 100644 --- a/cmd/cli/prog.go +++ b/cmd/cli/prog.go @@ -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() diff --git a/docs/network-recovery-diagnostics.md b/docs/network-recovery-diagnostics.md index 224fa93..906f515 100644 --- a/docs/network-recovery-diagnostics.md +++ b/docs/network-recovery-diagnostics.md @@ -67,8 +67,10 @@ The `Network snapshot` event and the header line of every log file render the sa The field `default_route_interface` is gone. Read `default_route_v4` and `default_route_v6` in its place. The two routes and the two gateways come from the route table of macOS, one route per address family. A tunnel that owns the default route has no next hop, so its route names the tunnel and its gateway stays empty. Windows and Linux read no route table in this release. They fill `default_route_v4` from the network monitor and leave `default_route_v6`, `gateway_v4`, and `gateway_v6` empty. +On macOS, `default_route_v4` comes from the network monitor only when the route table gives no route for the two address families. When the route table gives an IPv6 route only, `default_route_v4` stays empty. `link_type` is one of `wifi`, `ethernet`, `usb_tether`, `tunnel`, and `unknown`. +`link_type` and `tethered` describe the interface of the IPv4 default route. When no IPv4 route is present, they describe the interface of the IPv6 default route. When the route table gives no route, they describe the default interface of the network monitor. Thus the link fields and the route fields of one record describe the same interface. macOS reads it from the name of the hardware port. Linux reads `wifi`, `ethernet`, `usb_tether`, and `tunnel` from the kernel. Windows reads the description of the adapter in place of a port name. The words Ethernet, LAN, and Thunderbolt win over the tunnel class on every platform, so a VPN adapter with a description such as `SSL VPN Virtual Ethernet Adapter` reads as `ethernet`. Windows gives `tunnel` to the other VPN adapters. The other links are `unknown`. diff --git a/docs/runtime-internal-logging.md b/docs/runtime-internal-logging.md index 26fad07..bf906b6 100644 --- a/docs/runtime-internal-logging.md +++ b/docs/runtime-internal-logging.md @@ -32,7 +32,7 @@ Rotation is by size. A write that crosses the size limit rotates the file first. Each stream also keeps a memory buffer: 5 MB for the debug stream and 1 MB for the journal. These buffers serve `ctrld log tail` and the fallback path when a file cannot open. The files hold the history. -A restart deletes the memory buffers and keeps the files. The new process appends a header line, which marks the restart point inside each file. +A restart deletes the memory buffers and keeps the files. The new process appends a header line, which marks the restart point inside each file. When the header would make a file larger than its size limit, ctrld rotates the file first, and the header starts the new file. If the file cannot move, the header goes to the end of the current file. After an open error, ctrld opens the file again and appends the header with no rotation, so that file can pass its limit by one header. ## Header and rotation events @@ -83,6 +83,8 @@ Two keys in the `[service]` section size the debug stream: Both keys also apply to the `log_path` file, which rotates the same way. The journal budget is fixed per platform. +A change to the keys takes effect with no restart. This includes the first start, when the keys come from the Control D API, and a managed configuration refresh. When the backup count decreases, ctrld deletes the extra backups of `ctrld.log`. ctrld does not delete backups of the `log_path` file, because that directory can hold files of other programs. + ## Uploads `ctrld log send` uploads the log to Control D. The body holds these parts, in this order: