diff --git a/cmd/cli/cli.go b/cmd/cli/cli.go index bb9988e..b6cf64f 100644 --- a/cmd/cli/cli.go +++ b/cmd/cli/cli.go @@ -355,6 +355,7 @@ func run(appCallback *AppCallback, stopCh chan struct{}) { oldLogPath := cfg.Service.LogPath if uid := cdUIDFromProvToken(); uid != "" { cdUID = uid + p.initLoggingAfterProvisioning() } if cdUID != "" { if !validateCdUpstreamProtocol(p.notifyExitToLogServer) { @@ -420,17 +421,7 @@ func run(appCallback *AppCallback, stopCh chan struct{}) { } if newLogPath := cfg.Service.LogPath; newLogPath != "" && oldLogPath != newLogPath { - // After processCDFlags, log config may change, so reset mainLog and re-init logging. - l := zerolog.New(io.Discard) - mainLog.Store(&l) - - // Copy logs written so far to new log file if possible. - if buf, err := os.ReadFile(oldLogPath); err == nil { - if err := os.WriteFile(newLogPath, buf, os.FileMode(0o600)); err != nil { - mainLog.Load().Warn().Err(err).Msg("could not copy old log file") - } - } - initLoggingWithBackup(false) + p.switchLogPath(oldLogPath, newLogPath) } if err := validateConfig(&cfg); err != nil { @@ -839,7 +830,9 @@ func apiRejectionSummary(statusCode int) string { // provisionSecrets lists every secret-bearing value to strip from provisioning // artifacts, including both parts of a composite "/" --cd -// value, which the API may echo back separately. +// value, which the API may echo back separately. redactSecrets drops the +// values that are too short to redact, so a client ID such as "os" leaves the +// words of the message alone. func provisionSecrets() []string { uid, clientID := controld.ParseRawUID(cdUID) return []string{cdUID, cdOrg, uid, clientID} @@ -1309,11 +1302,7 @@ func selfCheckResolveDomain(ctx context.Context, addr, scope string, domain stri } mainLog.Load().Debug().Msgf("self-check against %q failed", domain) // Ping all upstreams to provide better error message to users. - for name, uc := range cfg.Upstream { - if err := uc.ErrorPing(); err != nil { - mainLog.Load().Err(err).Msgf("failed to connect to upstream.%s, endpoint: %s", name, uc.Endpoint) - } - } + logUpstreamPingFailures(cfg.Upstream) marker := strings.Repeat("=", 32) mainLog.Load().Debug().Msg(marker) mainLog.Load().Debug().Msgf("listener address : %s", addr) @@ -1328,6 +1317,24 @@ func selfCheckResolveDomain(ctx context.Context, addr, scope string, domain stri return errSelfCheckNoAnswer } +// upstreamPingFn is a var so tests can drive the self-check report without a +// network probe. +var upstreamPingFn = (*ctrld.UpstreamConfig).ErrorPing + +// logUpstreamPingFailures names the upstreams that do not answer after a +// failed self-check, so the user learns which one is unreachable. The config +// key and the endpoint are operator text that can hold a token, so both stay +// at debug and the retained line names the upstream by its bounded name. +func logUpstreamPingFailures(upstreams map[string]*ctrld.UpstreamConfig) { + for name, uc := range upstreams { + err := upstreamPingFn(uc) + if err == nil { + continue + } + logUpstreamProbeFailure(upstreamPrefix+name, uc, err, mainLog.Load().Error, "failed to connect to the upstream") + } +} + // unixServiceHomeDir is where a ctrld service with root rights keeps its // files on macOS, Linux, and the BSDs. const unixServiceHomeDir = "/etc/controld" diff --git a/cmd/cli/dns_proxy.go b/cmd/cli/dns_proxy.go index 4d3ca6f..f16ae8a 100644 --- a/cmd/cli/dns_proxy.go +++ b/cmd/cli/dns_proxy.go @@ -989,7 +989,7 @@ func (p *prog) proxy(ctx context.Context, req *proxyRequest) *proxyResponse { res.upstream = upstreamConfig.Endpoint return res } - ctrld.Log(ctx, p.querySampler.event(sampleClassAllEndpointsFailed, ""), "all %v endpoints failed", upstreams) + ctrld.Log(ctx, p.querySampler.event(sampleClassAllEndpointsFailed, ""), "all %v endpoints failed", journalUpstreamNames(upstreams)) // An Internal Domain with explicit resolvers is served only by the // configured resolvers. When all of them are unreachable the query fails @@ -2193,8 +2193,7 @@ func (l *upstreamFailureLog) report(upstream string, uc *ctrld.UpstreamConfig, e level = mainLog.Load().Debug } l.reported = true - logUpstreamProbeFailure(isGeneratedInternalDomainUpstreamRef(upstream, uc), uc, err, level, - "Upstream %s check failed after %v", upstream, duration) + logUpstreamProbeFailure(upstream, uc, err, level, "Upstream check failed after %v", duration) } // checkUpstreamOnce sends a test query to the specified upstream. @@ -2204,8 +2203,7 @@ func (p *prog) checkUpstreamOnce(upstream string, uc *ctrld.UpstreamConfig, fail resolver, err := ctrld.NewResolver(uc) if err != nil { - logUpstreamProbeFailure(isGeneratedInternalDomainUpstreamRef(upstream, uc), uc, err, - mainLog.Load().Error, "Failed to create resolver for upstream %s", upstream) + logUpstreamProbeFailure(upstream, uc, err, mainLog.Load().Error, "Failed to create resolver") return err } diff --git a/cmd/cli/dns_proxy_sampling_test.go b/cmd/cli/dns_proxy_sampling_test.go index 0017446..e6d27bb 100644 --- a/cmd/cli/dns_proxy_sampling_test.go +++ b/cmd/cli/dns_proxy_sampling_test.go @@ -122,3 +122,51 @@ func Test_querySamplingOnTheQueryPath(t *testing.T) { wantField(t, events[1], "upstream", upstreamOS) wantField(t, events[1], "state", "up") } + +// Test_allEndpointsFailedBoundsTheUpstreamName drives the query path with an +// operator-chosen upstream key. The line that reports the loss of every +// endpoint reaches the journal, so it must name the upstream by its bounded +// name. +func Test_allEndpointsFailedBoundsTheUpstreamName(t *testing.T) { + logs := captureDebugMainLog(t) + uc := &ctrld.UpstreamConfig{ + Name: probeSecret, + Type: ctrld.ResolverTypeLegacy, + Endpoint: deadUpstreamEndpoint, + Timeout: 200, + } + uc.Init() + cfg := &ctrld.Config{Upstream: map[string]*ctrld.UpstreamConfig{probeSecret: uc}} + cfg.Service.LeakOnUpstreamFailure = func(v bool) *bool { return &v }(false) + p := &prog{cfg: cfg, um: newUpstreamMonitor(cfg)} + // The zero value sampler arms a real timer. Close its window after the + // assertions, so no late summary line reaches another test. + t.Cleanup(func() { p.querySampler.closeExpired(time.Now().Add(querySampleWindow)) }) + + msg := new(dns.Msg) + msg.SetQuestion("private.test.", dns.TypeA) + res := p.proxy(context.Background(), &proxyRequest{ + msg: msg, + ufr: &upstreamForResult{ + srcAddr: "192.168.0.1:1234", + upstreams: []string{upstreamPrefix + probeSecret}, + }, + }) + if res == nil || res.answer == nil || res.answer.Rcode != dns.RcodeServerFailure { + t.Fatal("the proxy answered although every endpoint failed") + } + + var reported string + for _, event := range jsonLogEvents(t, logs, "") { + text, _ := event["message"].(string) + if strings.Contains(text, "endpoints failed") { + reported = text + } + } + if !strings.Contains(reported, upstreamPrefix+"custom") { + t.Fatalf("the all-endpoints line does not name the bounded upstream: %q", reported) + } + if strings.Contains(reported, probeSecret) { + t.Fatalf("the all-endpoints line holds the operator key: %q", reported) + } +} diff --git a/cmd/cli/internal_domains.go b/cmd/cli/internal_domains.go index 3461c06..836a7dc 100644 --- a/cmd/cli/internal_domains.go +++ b/cmd/cli/internal_domains.go @@ -435,22 +435,25 @@ func isGeneratedInternalDomainUpstreamRef(upstream string, uc *ctrld.UpstreamCon return isGeneratedInternalDomainUpstream(strings.TrimPrefix(upstream, upstreamPrefix), uc) } -// logUpstreamProbeFailure reports a background probe failure against an -// upstream. +// logUpstreamProbeFailure reports a background probe failure against the +// upstream that the reference upstream names. // // Loop checking and recovery checking run on timers, so for a generated // Internal Domain resolver they would publish the organization's private -// address without any user ever querying the domain. They get the same -// treatment as a query failure: endpoint and the address-bearing error at -// debug, a classification above it, so the outcome stays visible while the -// address does not. -func logUpstreamProbeFailure(generated bool, uc *ctrld.UpstreamConfig, err error, level func() *zerolog.Event, format string, args ...any) { +// address without any user ever querying the domain. The name and the +// endpoint of any upstream are operator text that can hold a token, so both +// stay on the debug line. The leveled line names the upstream by its bounded +// name, so the outcome stays visible while the operator text does not. A +// generated Internal Domain resolver also trades the address-bearing error +// for a classification. +func logUpstreamProbeFailure(upstream string, uc *ctrld.UpstreamConfig, err error, level func() *zerolog.Event, format string, args ...any) { detail := append([]any{}, args...) - if !generated { - level().Err(err).Msgf(format+" for upstream: %q, endpoint: %q", append(detail, uc.Name, uc.Endpoint)...) + mainLog.Load().Debug().Err(err).Msgf(format+" for upstream: %q, endpoint: %q", append(detail, uc.Name, uc.Endpoint)...) + event := level().Str("upstream", journalUpstreamName(upstream)) + if !isGeneratedInternalDomainUpstreamRef(upstream, uc) { + event.Err(err).Msgf(format, detail...) return } - mainLog.Load().Debug().Err(err).Msgf(format+" for upstream: %q, endpoint: %q", append(detail, uc.Name, uc.Endpoint)...) - level().Str("failure", internalDomainFailureReason(err)). + event.Str("failure", internalDomainFailureReason(err)). Msgf(format+" for an Internal Domain resolver", detail...) } diff --git a/cmd/cli/log_journal.go b/cmd/cli/log_journal.go index 995de48..7701137 100644 --- a/cmd/cli/log_journal.go +++ b/cmd/cli/log_journal.go @@ -6,7 +6,9 @@ import ( "regexp" "github.com/rs/zerolog" + "github.com/Control-D-Inc/ctrld" + "github.com/Control-D-Inc/ctrld/internal/controld" ) // journalField marks an event for the retained journal stream. Both packages @@ -17,16 +19,31 @@ const journalField = ctrld.JournalField // writer keeps a line below warn level only when the line contains it. var journalMarker = []byte(`"` + journalField + `":true`) -// retainedURLPath matches the part of a URL that follows the host. The class -// stops the match at the characters that end a value inside a JSON line. -var retainedURLPath = regexp.MustCompile(`(https?://[^/?"\\\s]+)[/?][^"\\\s]*`) +// retainedURLPath matches the part of a URL that follows the host, for every +// scheme: a DoH, DoH3, or DoQ endpoint carries its token in the path. The +// class stops the match at the characters that end a value inside a JSON line. +var retainedURLPath = regexp.MustCompile(`([a-z][a-z0-9+.-]*://[^/?"\\\s]+)[/?][^"\\\s]*`) + +// retainedControlDHost matches a Control D resolver host. The first label of +// the host is the resolver ID, which a DoT or DoQ endpoint carries in place of +// a path. +var retainedControlDHost = regexp.MustCompile(`([A-Za-z0-9-]+)(\.dns\.controld\.(?:com|dev))`) // redactRetainedLine strips the secrets of one line that the journal keeps. // Support downloads the journal whole, and any error text can carry a DoH URL // with the resolver path and the packed query of the user. func redactRetainedLine(p []byte) []byte { stripped := retainedURLPath.ReplaceAll(p, []byte(`${1}/[redacted]`)) - return []byte(redactSecrets(string(stripped), provisionSecrets()...)) + stripped = retainedControlDHost.ReplaceAll(stripped, []byte(`[redacted]${2}`)) + return []byte(redactSecrets(string(stripped), journalSecrets()...)) +} + +// journalSecrets names the values that no retained line may hold. The client +// ID stays out: it is a device label, not a secret. redactSecrets drops the +// values that are too short to redact. +func journalSecrets() []string { + uid, _ := controld.ParseRawUID(cdUID) + return []string{cdUID, cdOrg, uid} } // journal marks an event for the retained journal stream. The event keeps diff --git a/cmd/cli/log_journal_test.go b/cmd/cli/log_journal_test.go index abd8f7e..58aa425 100644 --- a/cmd/cli/log_journal_test.go +++ b/cmd/cli/log_journal_test.go @@ -254,3 +254,52 @@ func Test_stopClosesTheInternalLogFiles(t *testing.T) { } } } + +// Test_redactRetainedLineKeepsAShortClientID puts a two-letter client ID in +// the resolver UID. The keys of a JSON line hold the same letters, and a +// redaction of the client ID would break the line. +func Test_redactRetainedLineKeepsAShortClientID(t *testing.T) { + origCdUID := cdUID + t.Cleanup(func() { cdUID = origCdUID }) + cdUID = "uid12345678/os" + + line := string(redactRetainedLine([]byte(`{"level":"info","os":"darwin","resolver":"uid12345678/os"}`))) + + if !strings.Contains(line, `"os":"darwin"`) { + t.Fatalf("the redaction changed the os key: %s", line) + } + if strings.Contains(line, "uid12345678") { + t.Fatalf("the redaction kept the resolver uid: %s", line) + } +} + +// Test_redactRetainedLineStripsEverySchemePath covers the endpoints that carry +// a token in their path with a scheme other than https. +func Test_redactRetainedLineStripsEverySchemePath(t *testing.T) { + for _, tc := range []struct{ in, want string }{ + {`Get "quic://dns.example/org-v1-SECRET0123?dns=pOgBAAAB": timeout`, `Get "quic://dns.example/[redacted]": timeout`}, + {`h3://dns.example/SECRET0123 failed`, `h3://dns.example/[redacted] failed`}, + {`tls://dns.example:853 failed`, `tls://dns.example:853 failed`}, + {`tls://abcdef12.dns.controld.com:853 failed`, `tls://[redacted].dns.controld.com:853 failed`}, + {`quic://abcdef12.dns.controld.dev failed`, `quic://[redacted].dns.controld.dev failed`}, + {`https://freedns.controld.com/p1 failed`, `https://freedns.controld.com/[redacted] failed`}, + } { + if got := string(redactRetainedLine([]byte(tc.in))); got != tc.want { + t.Errorf("redactRetainedLine(%q) = %q, want %q", tc.in, got, tc.want) + } + } +} + +// Test_redactRetainedLineKeepsAShortResolverUID puts a two-letter resolver UID +// in place. The keys of a JSON line hold the same letters, and a redaction of +// the UID would break every retained line and the header. +func Test_redactRetainedLineKeepsAShortResolverUID(t *testing.T) { + origCdUID := cdUID + t.Cleanup(func() { cdUID = origCdUID }) + cdUID = "os" + + const in = `{"level":"info","os":"darwin","message":"loss of service"}` + if got := string(redactRetainedLine([]byte(in))); got != in { + t.Fatalf("redactRetainedLine(%q) = %q, want the line unchanged", in, got) + } +} diff --git a/cmd/cli/log_setup_test.go b/cmd/cli/log_setup_test.go new file mode 100644 index 0000000..6f2b3ac --- /dev/null +++ b/cmd/cli/log_setup_test.go @@ -0,0 +1,176 @@ +package cli + +import ( + "io" + "os" + "path/filepath" + "slices" + "strings" + "testing" + + "github.com/rs/zerolog" + + "github.com/Control-D-Inc/ctrld" +) + +// setupLogSetupTest puts ctrld in cd mode with no log_path and a temporary +// home directory, and puts back every global that the logging setup touches. +// The globals are the reason why no test of this package calls t.Parallel. +func setupLogSetupTest(t *testing.T) string { + t.Helper() + dir := t.TempDir() + origLogPath, origLogLevel := cfg.Service.LogPath, cfg.Service.LogLevel + origSilent, origVerbose, origCdUID, origHomedir := silent, verbose, cdUID, homedir + origConsoleWriter := consoleWriter + origMainLog, origProxyLogger := mainLog.Load(), ctrld.ProxyLogger.Load() + origLevel, origTimeFormat := zerolog.GlobalLevel(), zerolog.TimeFieldFormat + origLogPathFile, origPendingRotation := logPathFile.Load(), pendingLogPathRotation.Load() + t.Cleanup(func() { + if rf := logPathFile.Load(); rf != nil && rf != origLogPathFile { + _ = rf.close() + } + logPathFile.Store(origLogPathFile) + pendingLogPathRotation.Store(origPendingRotation) + cfg.Service.LogPath, cfg.Service.LogLevel = origLogPath, origLogLevel + silent, verbose, cdUID, homedir = origSilent, origVerbose, origCdUID, origHomedir + consoleWriter = origConsoleWriter + mainLog.Store(origMainLog) + ctrld.ProxyLogger.Store(origProxyLogger) + zerolog.SetGlobalLevel(origLevel) + zerolog.TimeFieldFormat = origTimeFormat + }) + cfg.Service.LogPath, cfg.Service.LogLevel = "", "info" + silent, verbose, cdUID, homedir = false, 0, "", dir + consoleWriter = zerolog.NewConsoleWriter(func(w *zerolog.ConsoleWriter) { w.Out = io.Discard }) + discard := zerolog.New(io.Discard) + mainLog.Store(&discard) + logPathFile.Store(nil) + pendingLogPathRotation.Store(nil) + stubHeaderSnapshotSources(t) + stubLogHeaderNetworkRead(t, "en0") + return dir +} + +// Test_initLoggingAfterProvisioning_opensTheJournal drives a --cd-org start: +// the first logging setup runs before the resolver UID is known, and the +// provisioning step then opens the internal streams. +func Test_initLoggingAfterProvisioning_opensTheJournal(t *testing.T) { + dir := setupLogSetupTest(t) + p := &prog{cfg: &cfg} + p.initLogging(true) + t.Cleanup(p.closeInternalLogs) + + journalPath := filepath.Join(dir, journalLogFileName) + if _, err := os.Stat(journalPath); !os.IsNotExist(err) { + t.Fatalf("journal exists before the UID is known (stat err = %v)", err) + } + + cdUID = "provisioned-uid" + p.initLoggingAfterProvisioning() + + firstLine, headers := logHeaderFileLines(t, journalPath) + if firstLine.Message != logHeaderMessage || headers != 1 { + t.Fatalf("journal starts with %q and holds %d headers, want the header once", firstLine.Message, headers) + } + mainLog.Load().Warn().Msg("retained after provisioning") + if content := rotatingFileTestContent(t, journalPath); !strings.Contains(content, "retained after provisioning") { + t.Fatalf("journal misses the line after provisioning: %s", content) + } + + p.initLoggingAfterProvisioning() + if _, headers := logHeaderFileLines(t, journalPath); headers != 1 { + t.Fatalf("a second call added a header: %d headers", headers) + } +} + +// Test_switchLogPath_leadsTheNewFileAndClosesTheInternalFiles drives the +// log_path that the API config sets after the first logging setup. +func Test_switchLogPath_leadsTheNewFileAndClosesTheInternalFiles(t *testing.T) { + dir := setupLogSetupTest(t) + cdUID = "test-uid" + p := &prog{cfg: &cfg} + p.initLogging(true) + t.Cleanup(p.closeInternalLogs) + mainLog.Load().Info().Msg("line before the switch") + + newPath := filepath.Join(dir, "logs", "ctrld.log") + cfg.Service.LogPath = newPath + p.switchLogPath("", newPath) + + firstLine, headers := logHeaderFileLines(t, newPath) + if firstLine.Message != logHeaderMessage || headers != 1 { + t.Fatalf("log_path file starts with %q and holds %d headers, want the header once", firstLine.Message, headers) + } + lw, jlw := p.internalWriters() + if lw.rotating() != nil || jlw.rotating() != nil { + t.Fatal("the internal files stayed open after the switch") + } + if files := p.logHeaderFiles(); !slices.Equal(files, []string{newPath}) { + t.Fatalf("log_files = %v, want the log_path only", files) + } + // cd mode has no local log_path, so the lines of the run stay in the + // internal debug stream that this call closes. + if content := rotatingFileTestContent(t, newPath); strings.Contains(content, "line before the switch") { + t.Fatalf("a line moved although the run had no local log_path: %s", content) + } +} + +// Test_switchLogPath_carriesTheOldFileBelowOneHeader drives a run that already +// wrote a local log_path file. The new file must hold one header, and the +// header must lead the lines that the old file holds. +func Test_switchLogPath_carriesTheOldFileBelowOneHeader(t *testing.T) { + dir := setupLogSetupTest(t) + cdUID = "test-uid" + oldPath := filepath.Join(dir, "old", "ctrld.log") + cfg.Service.LogPath = oldPath + p := &prog{cfg: &cfg} + p.initLogging(true) + t.Cleanup(p.closeInternalLogs) + mainLog.Load().Info().Msg("line before the switch") + + newPath := filepath.Join(dir, "logs", "ctrld.log") + cfg.Service.LogPath = newPath + p.switchLogPath(oldPath, newPath) + + firstLine, headers := logHeaderFileLines(t, newPath) + if firstLine.Message != logHeaderMessage || headers != 1 { + t.Fatalf("log_path file starts with %q and holds %d headers, want the header once", firstLine.Message, headers) + } + if !slices.Equal(firstLine.LogFiles, []string{newPath}) { + t.Fatalf("header log_files = %v, want the new log_path", firstLine.LogFiles) + } + if content := rotatingFileTestContent(t, newPath); !strings.Contains(content, "line before the switch") { + t.Fatalf("the new file misses the lines of the old file: %s", content) + } +} + +// Test_initLoggingAfterProvisioning_skipsTheGuardedRuns covers the two runs +// that keep no internal files: a run with a local log_path, and a silent run. +// Neither may gain a journal when the provisioning step learns the UID. +func Test_initLoggingAfterProvisioning_skipsTheGuardedRuns(t *testing.T) { + for _, tc := range []struct { + name string + guard func(t *testing.T, dir string) + }{ + {"log_path set", func(t *testing.T, dir string) { + cfg.Service.LogPath = filepath.Join(dir, "operator.log") + }}, + {"silent set", func(t *testing.T, _ string) { silent = true }}, + } { + t.Run(tc.name, func(t *testing.T) { + dir := setupLogSetupTest(t) + tc.guard(t, dir) + p := &prog{cfg: &cfg} + p.initLogging(true) + t.Cleanup(p.closeInternalLogs) + + cdUID = "provisioned-uid" + p.initLoggingAfterProvisioning() + + journalPath := filepath.Join(dir, journalLogFileName) + if _, err := os.Stat(journalPath); !os.IsNotExist(err) { + t.Fatalf("the guarded run opened a journal (stat err = %v)", err) + } + }) + } +} diff --git a/cmd/cli/log_writer.go b/cmd/cli/log_writer.go index 73b7f30..0c66fda 100644 --- a/cmd/cli/log_writer.go +++ b/cmd/cli/log_writer.go @@ -2,7 +2,9 @@ package cli import ( "bytes" + "encoding/json" "io" + "os" "sync" "time" @@ -255,9 +257,93 @@ func (p *prog) initLogging(backup bool) { } } +// initLoggingAfterProvisioning opens the internal streams of a run whose +// resolver UID came from the provisioning token. The first logging setup ran +// before that UID was known, so it opened no debug file and no journal. +func (p *prog) initLoggingAfterProvisioning() { + if !p.needInternalLogging() { + return + } + if lw, _ := p.internalWriters(); lw != nil { + return + } + p.initLogging(false) +} + +// switchLogPath moves the logging of this run to the log_path that the API +// config set. The header of the new file leads it, the lines of an earlier +// local log_path file follow that header, and the internal streams close, +// because a run with a log_path keeps no internal files. A run without a local +// log_path carries no lines: its history stays in the internal debug stream, +// which this call closes. +func (p *prog) switchLogPath(oldLogPath, newLogPath string) { + // After processCDFlags, log config may change, so reset mainLog and re-init logging. + discard := zerolog.New(io.Discard) + mainLog.Store(&discard) + + carried := carriedLogLines(oldLogPath, newLogPath) + p.initLogging(false) + p.carryLogLines(carried) +} + +// carriedLogLines reads the lines of the old log_path file and empties the new +// file, so the header of the new file leads it. It drops the header lines of +// the old file, because each of them names the old file. +func carriedLogLines(oldLogPath, newLogPath string) []byte { + buf, err := os.ReadFile(oldLogPath) + if err != nil { + return nil + } + if err := os.Remove(newLogPath); err != nil && !os.IsNotExist(err) { + mainLog.Load().Warn().Err(err).Msg("could not clear the new log file") + return nil + } + return withoutLogHeaderLines(buf) +} + +// carryLogLines appends the lines of the old log_path file below the header of +// the new one. +func (p *prog) carryLogLines(lines []byte) { + if len(lines) == 0 { + return + } + rf := logPathFile.Load() + if rf == nil { + return + } + if _, err := rf.Write(lines); err != nil { + mainLog.Load().Warn().Err(err).Msg("could not copy old log file") + } +} + +// withoutLogHeaderLines removes every header line of a log file. +func withoutLogHeaderLines(buf []byte) []byte { + var kept bytes.Buffer + for _, line := range bytes.SplitAfter(buf, []byte("\n")) { + if isLogHeaderLine(line) { + continue + } + kept.Write(line) + } + return kept.Bytes() +} + +// isLogHeaderLine reports whether one line of a log file is a header line. +func isLogHeaderLine(line []byte) bool { + var parsed struct { + Message string `json:"message"` + } + if err := json.Unmarshal(bytes.TrimSpace(line), &parsed); err != nil { + return false + } + return parsed.Message == logHeaderMessage +} + // initInternalLogging performs internal logging if there's no log enabled. func (p *prog) initInternalLogging(writers []io.Writer) { if !p.needInternalLogging() { + // A log_path that the API set takes over from the internal files. + p.closeInternalLogs() return } headersWritten := false diff --git a/cmd/cli/loop.go b/cmd/cli/loop.go index e088001..b4adb8f 100644 --- a/cmd/cli/loop.go +++ b/cmd/cli/loop.go @@ -86,10 +86,9 @@ func (p *prog) detectLoop(msg *dns.Msg) { func (p *prog) checkDnsLoop() { mainLog.Load().Debug().Msg("start checking DNS loop") upstream := make(map[string]*ctrld.UpstreamConfig) - // Generated Internal Domain resolvers are local addresses, so they pass - // canBeLocalUpstream and are probed every minute. Record which ones they - // are while the config key is still in hand. - generated := make(map[string]bool) + // The probe loop below runs on the upstream UID, and the failure report + // needs the config key. Record the reference while the key is in hand. + reference := make(map[string]string) p.loopMu.Lock() for n, uc := range p.cfg.Upstream { if p.um.isDown("upstream." + n) { @@ -103,7 +102,7 @@ func (p *prog) checkDnsLoop() { uid := uc.UID() p.loop[uid] = false upstream[uid] = uc - generated[uid] = isGeneratedInternalDomainUpstream(n, uc) + reference[uid] = upstreamPrefix + n } p.loopMu.Unlock() @@ -116,11 +115,11 @@ func (p *prog) checkDnsLoop() { } resolver, err := ctrld.NewResolver(uc) if err != nil { - logUpstreamProbeFailure(generated[uid], uc, err, mainLog.Load().Warn, "could not perform loop check") + logUpstreamProbeFailure(reference[uid], uc, err, mainLog.Load().Warn, "could not perform loop check") continue } if _, err := resolver.Resolve(context.Background(), msg); err != nil { - logUpstreamProbeFailure(generated[uid], uc, err, mainLog.Load().Warn, "could not send DNS loop check query") + logUpstreamProbeFailure(reference[uid], uc, err, mainLog.Load().Warn, "could not send DNS loop check query") } } mainLog.Load().Debug().Msg("end checking DNS loop") diff --git a/cmd/cli/net_darwin.go b/cmd/cli/net_darwin.go index 8d9c4ab..4856150 100644 --- a/cmd/cli/net_darwin.go +++ b/cmd/cli/net_darwin.go @@ -74,7 +74,9 @@ func serviceNamesByDevice(r io.Reader) map[string]string { for scanner.Scan() { line := scanner.Text() if strings.Contains(line, "*") { - // Network services is disabled. + // A disabled service names no device. Without the reset, the device + // line that follows takes the name of the service before it. + prevLine = "" continue } device := serviceOrderDevice(line) diff --git a/cmd/cli/net_darwin_test.go b/cmd/cli/net_darwin_test.go index 280e4d5..1ac1326 100644 --- a/cmd/cli/net_darwin_test.go +++ b/cmd/cli/net_darwin_test.go @@ -313,3 +313,26 @@ func Test_platformInterfaceMeta(t *testing.T) { t.Error("platformVirtualInterfaces is not nil on darwin") } } + +// Test_serviceNamesByDevice_namesNoDisabledService drives output that holds no +// blank line between the blocks. The device of a disabled service must keep no +// name, and the name of the service before it is the wrong answer. +func Test_serviceNamesByDevice_namesNoDisabledService(t *testing.T) { + const fixture = `An asterisk (*) denotes that a network service is disabled. +(1) Wi-Fi +(Hardware Port: Wi-Fi, Device: en0) +(2) Thunderbolt Bridge +(Hardware Port: Thunderbolt Bridge, Device: bridge0) +(*) Ethernet Adapter (en6) +(Hardware Port: Ethernet Adapter (en6), Device: en6) +` + + names := serviceNamesByDevice(strings.NewReader(fixture)) + + if got := names["en6"]; got != "" { + t.Errorf("service of the disabled en6 = %q, want no name", got) + } + if got := names["bridge0"]; got != "Thunderbolt Bridge" { + t.Errorf("service of bridge0 = %q, want %q", got, "Thunderbolt Bridge") + } +} diff --git a/cmd/cli/network_snapshot_test.go b/cmd/cli/network_snapshot_test.go index e582e91..f1276dd 100644 --- a/cmd/cli/network_snapshot_test.go +++ b/cmd/cli/network_snapshot_test.go @@ -128,6 +128,9 @@ func Test_linkTypeFor(t *testing.T) { {"thunderbolt_bridge", "Thunderbolt Bridge", "hardware", "ethernet"}, {"iphone_usb_port", "iPhone USB", "hardware", "usb_tether"}, {"tunnel_class", "", "tunnel", "tunnel"}, + // The Windows adapter description reaches linkTypeFor as the port + // name, and a wired word in it wins over the tunnel class. + {"ethernet_word_wins_over_tunnel_class", "SSL VPN Virtual Ethernet Adapter", "tunnel", "ethernet"}, {"no_port_no_class", "", "", "unknown"}, {"unknown_port", "Bluetooth PAN", "hardware", "unknown"}, } { diff --git a/cmd/cli/network_source_state_test.go b/cmd/cli/network_source_state_test.go new file mode 100644 index 0000000..b1f7726 --- /dev/null +++ b/cmd/cli/network_source_state_test.go @@ -0,0 +1,147 @@ +package cli + +import ( + "errors" + "net" + "net/netip" + "slices" + "testing" + + "github.com/rs/zerolog" + "github.com/Control-D-Inc/ctrld" + "tailscale.com/net/netmon" +) + +func Test_interfaceAddressPrefix(t *testing.T) { + for _, tc := range []struct { + name string + address net.Addr + want string + }{ + {"IPv4 with a 4-byte mask", &net.IPNet{IP: net.IPv4(192, 0, 2, 10).To4(), Mask: net.CIDRMask(24, 32)}, "192.0.2.10/24"}, + {"IPv4 in the 16-byte form with a 4-byte mask", &net.IPNet{IP: net.IPv4(192, 0, 2, 10), Mask: net.CIDRMask(24, 32)}, "192.0.2.10/24"}, + {"IPv4 in the 16-byte form with a 16-byte mask", &net.IPNet{IP: net.IPv4(192, 0, 2, 10), Mask: net.CIDRMask(120, 128)}, "192.0.2.10/24"}, + {"IPv6 with a 64-bit mask", &net.IPNet{IP: net.ParseIP("2001:db8::1"), Mask: net.CIDRMask(64, 128)}, "2001:db8::1/64"}, + {"IPv4 without a mask", &net.IPAddr{IP: net.IPv4(192, 0, 2, 10)}, "192.0.2.10/32"}, + {"IPv6 without a mask", &net.IPAddr{IP: net.ParseIP("2001:db8::1")}, "2001:db8::1/128"}, + {"IPv4 with a nil mask", &net.IPNet{IP: net.IPv4(192, 0, 2, 10)}, "192.0.2.10/32"}, + {"IPv4 with an irregular mask", &net.IPNet{IP: net.IPv4(192, 0, 2, 10), Mask: net.IPMask{255, 0, 255, 0}}, "192.0.2.10/32"}, + } { + t.Run(tc.name, func(t *testing.T) { + prefix, err := interfaceAddressPrefix(tc.address) + if err != nil { + t.Fatalf("interfaceAddressPrefix: %v", err) + } + if prefix.String() != tc.want { + t.Fatalf("prefix = %s, want %s", prefix, tc.want) + } + }) + } + if _, err := interfaceAddressPrefix(&net.TCPAddr{IP: net.IPv4(192, 0, 2, 10), Port: 53}); err == nil { + t.Fatal("a TCP address gave a prefix, want an error") + } +} + +// sourceTestInterfaces returns one up interface with a /24 and a /64 address, +// through the reader seam of networkSourceState. +func sourceTestInterfaces() ([]net.Interface, func(*net.Interface) ([]net.Addr, error)) { + interfaces := []net.Interface{{Index: 1, Name: "en0", Flags: net.FlagUp}} + addresses := func(iface *net.Interface) ([]net.Addr, error) { + if iface.Name != "en0" { + return nil, errors.New("unknown interface") + } + return []net.Addr{ + &net.IPNet{IP: net.IPv4(192, 0, 2, 10), Mask: net.CIDRMask(24, 32)}, + &net.IPNet{IP: net.ParseIP("2001:db8::1"), Mask: net.CIDRMask(64, 128)}, + }, nil + } + return interfaces, addresses +} + +func Test_networkSourceState_keepsTheMasks(t *testing.T) { + state, err := networkSourceState(sourceTestInterfaces()) + if err != nil { + t.Fatalf("networkSourceState: %v", err) + } + if !state.Interface["en0"].IsUp() { + t.Fatal("en0 is not up") + } + if got := prefixStrings(state.InterfaceIPs["en0"]); !slices.Equal(got, []string{"192.0.2.10/24", "2001:db8::1/64"}) { + t.Fatalf("prefixes = %v, want the /24 and the /64 with the host address", got) + } +} + +// stubSourceStateRead makes the fresh network read return the test interfaces +// through the real state builder. +func stubSourceStateRead(t *testing.T) { + t.Helper() + origRead := readNetworkSourceStateFn + t.Cleanup(func() { readNetworkSourceStateFn = origRead }) + readNetworkSourceStateFn = func() (*netmon.State, error) { return networkSourceState(sourceTestInterfaces()) } +} + +// Test_freshSnapshotAndHeaderKeepTheMasks proves that the send-time header and +// the fresh snapshot show the /24 and the /64 of the host, as the network +// monitor does. +func Test_freshSnapshotAndHeaderKeepTheMasks(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + stubHeaderSnapshotSources(t) + stubSourceStateRead(t) + p := &prog{cfg: &ctrld.Config{}} + want := []string{"192.0.2.10/24", "2001:db8::1/64"} + + snapshot := buildNetworkSnapshot(p.freshSnapshotInputs()) + index := slices.IndexFunc(snapshot.Interfaces, func(i snapshotInterface) bool { return i.Name == "en0" }) + if index < 0 { + t.Fatalf("snapshot holds no en0: %+v", snapshot.Interfaces) + } + if got := snapshot.Interfaces[index].IPs; !slices.Equal(got, want) { + t.Fatalf("snapshot ips = %v, want %v", got, want) + } + + parsed, _ := parseLogHeader(t, p.sendLogHeader()) + var headerIPs []string + for _, iface := range parsed.Network.Interfaces { + if iface.Name == "en0" { + headerIPs = iface.IPs + } + } + if !slices.Equal(headerIPs, want) { + t.Fatalf("header ips = %v, want %v", headerIPs, want) + } +} + +// Test_sourceValidationKeepsTheHostAddress proves that a state with masked +// prefixes still names the host address, not the subnet address, as the +// source of the process. +func Test_sourceValidationKeepsTheHostAddress(t *testing.T) { + before4, before6 := ctrld.GetDefaultLocalIPv4(), ctrld.GetDefaultLocalIPv6() + t.Cleanup(func() { + ctrld.SetDefaultLocalIPv4(before4) + ctrld.SetDefaultLocalIPv6(before6) + }) + state, err := networkSourceState(sourceTestInterfaces()) + if err != nil { + t.Fatalf("networkSourceState: %v", err) + } + + ctrld.SetDefaultLocalIPv4(net.ParseIP("192.0.2.10")) + ctrld.SetDefaultLocalIPv6(net.ParseIP("2001:db8::1")) + validateDefaultLocalIPsFromDelta(state, 1) + if got := ctrld.GetDefaultLocalIPv4(); !got.Equal(net.ParseIP("192.0.2.10")) { + t.Fatalf("source IPv4 = %v, want the host address kept", got) + } + if got := ctrld.GetDefaultLocalIPv6(); !got.Equal(net.ParseIP("2001:db8::1")) { + t.Fatalf("source IPv6 = %v, want the host address kept", got) + } + + // The subnet address is not an address of the host. + ctrld.SetDefaultLocalIPv4(net.ParseIP("192.0.2.0")) + validateDefaultLocalIPsFromDelta(state, 2) + if got := ctrld.GetDefaultLocalIPv4(); got != nil { + t.Fatalf("source IPv4 = %v, want the subnet address cleared", got) + } + if reason := sourceInvalidReason(state, netip.MustParseAddr("192.0.2.10").AsSlice()); reason != "" { + t.Fatalf("host address reported %q, want a valid source", reason) + } +} diff --git a/cmd/cli/network_transition.go b/cmd/cli/network_transition.go index fb7825d..082516f 100644 --- a/cmd/cli/network_transition.go +++ b/cmd/cli/network_transition.go @@ -50,34 +50,71 @@ func readNetworkSourceState() (*netmon.State, error) { if err != nil { return nil, err } + return networkSourceState(interfaces, (*net.Interface).Addrs) +} + +// networkSourceState builds the state of the given interfaces. The address +// reader is a parameter, so a test feeds addresses without a host network. +func networkSourceState(interfaces []net.Interface, addressesOf func(*net.Interface) ([]net.Addr, error)) (*netmon.State, error) { state := &netmon.State{Interface: map[string]netmon.Interface{}, InterfaceIPs: map[string][]netip.Prefix{}} for _, iface := range interfaces { - addresses, err := iface.Addrs() + addresses, err := addressesOf(&iface) if err != nil { return nil, err } state.Interface[iface.Name] = netmon.Interface{Interface: &iface} for _, address := range addresses { - var ip net.IP - switch address := address.(type) { - case *net.IPNet: - ip = address.IP - case *net.IPAddr: - ip = address.IP - default: - return nil, errors.New("unsupported interface address type") + prefix, err := interfaceAddressPrefix(address) + if err != nil { + return nil, err } - addr, ok := netip.AddrFromSlice(ip) - if !ok { - return nil, errors.New("invalid interface address") - } - addr = addr.Unmap() - state.InterfaceIPs[iface.Name] = append(state.InterfaceIPs[iface.Name], netip.PrefixFrom(addr, addr.BitLen())) + state.InterfaceIPs[iface.Name] = append(state.InterfaceIPs[iface.Name], prefix) } } return state, nil } +// interfaceAddressPrefix turns one interface address into a prefix. An address +// with a subnet mask keeps the mask and its host bits, so a fresh state shows +// the same /24 or /64 as the network monitor. An address without a mask is a +// host prefix. +func interfaceAddressPrefix(address net.Addr) (netip.Prefix, error) { + var ip net.IP + var mask net.IPMask + switch address := address.(type) { + case *net.IPNet: + ip, mask = address.IP, address.Mask + case *net.IPAddr: + ip = address.IP + default: + return netip.Prefix{}, errors.New("unsupported interface address type") + } + addr, ok := netip.AddrFromSlice(ip) + if !ok { + return netip.Prefix{}, errors.New("invalid interface address") + } + addr = addr.Unmap() + return netip.PrefixFrom(addr, prefixBits(addr, mask)), nil +} + +// prefixBits reads the length of a mask for an unmapped address. The mask of +// an IPv4 address is 4 or 16 bytes long, and a 16-byte mask counts the 96 +// bits of the IPv6 mapping too. A missing or irregular mask means a host +// prefix. +func prefixBits(addr netip.Addr, mask net.IPMask) int { + bits, total := mask.Size() + if total == 0 { + return addr.BitLen() + } + if addr.Is4() && total == 128 { + bits -= 96 + } + if bits < 0 || bits > addr.BitLen() { + return addr.BitLen() + } + return bits +} + // netmon v1.74.0 caches only major snapshots. Minor and time-jump events // belong to their Old snapshot, not their distinct New snapshot. func networkSnapshotCurrent(delta *netmon.ChangeDelta, major bool, current *netmon.State) bool { diff --git a/cmd/cli/provision_result.go b/cmd/cli/provision_result.go index 606b8a4..c0b91f6 100644 --- a/cmd/cli/provision_result.go +++ b/cmd/cli/provision_result.go @@ -192,10 +192,17 @@ func newProvisionResult(code provisionFailureCode, message string, attempts []pr return r } -// redactSecrets removes every non-empty secret from s. +// redactSecretMinLen is the length below which a value is too short to +// redact. Two or three letters also match the keys of a JSON line and the +// words of a message, so a redaction of them corrupts the output. Corrupt +// output costs support more than a short value that the API rejects at the +// next step. It is the shortest token that the API parses. +const redactSecretMinLen = provisionTokenMinLen + +// redactSecrets removes every secret from s that is long enough to redact. func redactSecrets(s string, secrets ...string) string { for _, secret := range secrets { - if secret == "" { + if len(secret) < redactSecretMinLen { continue } s = strings.ReplaceAll(s, secret, "[redacted]") diff --git a/cmd/cli/provision_result_test.go b/cmd/cli/provision_result_test.go index f7f95d3..e4720ab 100644 --- a/cmd/cli/provision_result_test.go +++ b/cmd/cli/provision_result_test.go @@ -292,3 +292,22 @@ func TestFailProvisionWritesLogsNotifiesAndExits(t *testing.T) { t.Errorf("persisted code = %q", out.Code) } } + +// Test_redactSecretsKeepsAShortClientID puts a two-letter client ID in the +// resolver UID. The provisioning messages hold the same letters in ordinary +// words, and a redaction of the client ID would mangle them. +func Test_redactSecretsKeepsAShortClientID(t *testing.T) { + origCdUID, origCdOrg := cdUID, cdOrg + t.Cleanup(func() { cdUID, cdOrg = origCdUID, origCdOrg }) + cdUID, cdOrg = "uid12345678/os", "" + + const in = "failed to reach the host uid12345678/os" + got := redactSecrets(in, provisionSecrets()...) + + if !strings.Contains(got, "failed to reach the host ") { + t.Fatalf("the redaction mangled the words of the message: %s", got) + } + if strings.Contains(got, "uid12345678") { + t.Fatalf("the redaction kept the resolver uid: %s", got) + } +} diff --git a/cmd/cli/query_error_sampler.go b/cmd/cli/query_error_sampler.go index af382f7..c1c3ea5 100644 --- a/cmd/cli/query_error_sampler.go +++ b/cmd/cli/query_error_sampler.go @@ -145,7 +145,7 @@ func (s *errorSampler) logSummaries(summaries []sampleSummary) { for _, summary := range summaries { mainLog.Load().Error(). Str("class", summary.key.class). - Str("upstream", summary.key.upstream). + Str("upstream", journalUpstreamName(summary.key.upstream)). Int("count", summary.count). Int("suppressed", summary.suppressed). Int("window_s", int(querySampleWindow/time.Second)). diff --git a/cmd/cli/query_error_sampler_test.go b/cmd/cli/query_error_sampler_test.go index 57eaa32..17a77cb 100644 --- a/cmd/cli/query_error_sampler_test.go +++ b/cmd/cli/query_error_sampler_test.go @@ -155,6 +155,26 @@ func Test_errorSamplerLimitsWindowAndSummarizes(t *testing.T) { wantField(t, last, "level", "error") } +// Test_errorSamplerKeepsACustomNameOutOfTheSummary drives a window on an +// operator-chosen upstream key. The key can hold a token, so the summary names +// the upstream by a bounded name. +func Test_errorSamplerKeepsACustomNameOutOfTheSummary(t *testing.T) { + const upstream = upstreamPrefix + "dns.controld.com/org-v1-SECRET0123" + h := newSamplerHarness(t) + + for i := 0; i < querySampleLimit+1; i++ { + h.emit(sampleClassResolveFailed, upstream) + } + h.advance(querySampleWindow) + h.sampler.closeExpired(h.now) + + summaries := samplerSummaries(h.events(t)) + if len(summaries) != 1 { + t.Fatalf("summaries after the window closed: got %d, want 1", len(summaries)) + } + wantField(t, summaries[0], "upstream", upstreamPrefix+"custom") +} + func Test_errorSamplerKeepsBudgetPerUpstream(t *testing.T) { h := newSamplerHarness(t) @@ -258,3 +278,22 @@ func Test_errorSamplerZeroValueWorks(t *testing.T) { t.Fatalf("first line of a window is not at error level: %s", buf.String()) } } + +// Test_errorSamplerKeepsAnEmptyUpstreamEmpty drives a window of a class that +// names no upstream. The summary must not report the window as a custom +// upstream. +func Test_errorSamplerKeepsAnEmptyUpstreamEmpty(t *testing.T) { + h := newSamplerHarness(t) + + for i := 0; i < querySampleLimit+1; i++ { + h.emit(sampleClassAllEndpointsFailed, "") + } + h.advance(querySampleWindow) + h.sampler.closeExpired(h.now) + + summaries := samplerSummaries(h.events(t)) + if len(summaries) != 1 { + t.Fatalf("summaries after the window closed: got %d, want 1", len(summaries)) + } + wantField(t, summaries[0], "upstream", "") +} diff --git a/cmd/cli/upstream_monitor.go b/cmd/cli/upstream_monitor.go index 6d1e62f..029c9c5 100644 --- a/cmd/cli/upstream_monitor.go +++ b/cmd/cli/upstream_monitor.go @@ -182,14 +182,25 @@ func (um *upstreamMonitor) markUp(upstream, reason string) { // journalUpstreamName bounds the upstream name that a journal event carries. // ctrld generates upstream.os, upstream., and upstream.internal_; every // other key is operator text that can hold a token, so it reads as -// upstream.custom. +// upstream.custom. An empty name holds no operator text and stays empty, +// because a line that names no upstream must not read as a custom one. func journalUpstreamName(upstream string) string { - if upstream == upstreamOS || generatedUpstreamKey(strings.TrimPrefix(upstream, upstreamPrefix)) { + if upstream == "" || upstream == upstreamOS || generatedUpstreamKey(strings.TrimPrefix(upstream, upstreamPrefix)) { return upstream } return upstreamPrefix + "custom" } +// journalUpstreamNames bounds every name of a list, for a line that names +// several upstreams. +func journalUpstreamNames(upstreams []string) []string { + names := make([]string, 0, len(upstreams)) + for _, upstream := range upstreams { + names = append(names, journalUpstreamName(upstream)) + } + return names +} + // generatedUpstreamKey reports whether key is a number, or internal_ and a // number, the two shapes that ctrld writes itself. func generatedUpstreamKey(key string) bool { diff --git a/cmd/cli/upstream_monitor_test.go b/cmd/cli/upstream_monitor_test.go index 68780d8..20f6a9b 100644 --- a/cmd/cli/upstream_monitor_test.go +++ b/cmd/cli/upstream_monitor_test.go @@ -1,6 +1,7 @@ package cli import ( + "slices" "testing" "time" @@ -230,6 +231,21 @@ func Test_upstreamMonitorKeepsACustomNameOutOfTheJournal(t *testing.T) { } } +// Test_journalUpstreamNamesBoundsEveryName covers the line that names several +// upstreams at once. One operator key in the list must not reach the journal. +func Test_journalUpstreamNamesBoundsEveryName(t *testing.T) { + got := journalUpstreamNames([]string{ + upstreamPrefix + "0", + upstreamPrefix + "dns.controld.com/org-v1-SECRET0123", + upstreamOS, + }) + + want := []string{upstreamPrefix + "0", upstreamPrefix + "custom", upstreamOS} + if !slices.Equal(got, want) { + t.Fatalf("journalUpstreamNames = %v, want %v", got, want) + } +} + func Test_upstreamMonitorCountDown(t *testing.T) { captureDebugMainLog(t) um := newUpstreamMonitor(&ctrld.Config{}) diff --git a/cmd/cli/upstream_probe_journal_test.go b/cmd/cli/upstream_probe_journal_test.go new file mode 100644 index 0000000..b36208d --- /dev/null +++ b/cmd/cli/upstream_probe_journal_test.go @@ -0,0 +1,141 @@ +package cli + +import ( + "errors" + "strings" + "testing" + "time" + + "github.com/Control-D-Inc/ctrld" +) + +// probeSecret is the operator text that a custom upstream key, name, and +// endpoint hold in these tests. +const probeSecret = "org-v1-SECRET0123" + +// customProbeUpstream builds an upstream whose key, name, and endpoint all +// hold operator text. +func customProbeUpstream() (string, *ctrld.UpstreamConfig) { + return upstreamPrefix + probeSecret, &ctrld.UpstreamConfig{ + Name: probeSecret, + Endpoint: "https://dns.example.com/" + probeSecret, + } +} + +// retainedProbeLines returns the captured lines that the journal keeps. +func retainedProbeLines(t *testing.T, logs *syncBuffer) []map[string]any { + t.Helper() + var retained []map[string]any + for _, event := range jsonLogEvents(t, logs, "") { + switch event["level"] { + case "error", "warn": + retained = append(retained, event) + } + } + return retained +} + +// wantNoProbeSecret fails when a retained line carries the operator text. +func wantNoProbeSecret(t *testing.T, logs *syncBuffer) { + t.Helper() + for _, event := range retainedProbeLines(t, logs) { + for field, value := range event { + text, ok := value.(string) + if ok && strings.Contains(text, probeSecret) { + t.Fatalf("retained field %q holds the operator text: %s", field, text) + } + } + } +} + +// Test_upstreamFailureLogKeepsACustomKeyOutOfTheJournal drives one recovery +// check failure against an operator-chosen upstream key. The journal keeps +// error lines, so the key, the name, and the endpoint must stay off the line. +func Test_upstreamFailureLogKeepsACustomKeyOutOfTheJournal(t *testing.T) { + logs := captureDebugMainLog(t) + upstream, uc := customProbeUpstream() + + (&upstreamFailureLog{}).report(upstream, uc, errors.New("probe failed"), time.Second) + + retained := retainedProbeLines(t, logs) + if len(retained) != 1 { + t.Fatalf("retained lines: got %d, want 1", len(retained)) + } + wantField(t, retained[0], "upstream", upstreamPrefix+"custom") + wantNoProbeSecret(t, logs) + if !strings.Contains(logs.String(), probeSecret) { + t.Fatal("the operator text must stay at debug level for diagnosis") + } +} + +// Test_checkUpstreamOnceKeepsACustomKeyOutOfTheJournal drives the resolver +// creation failure of a recovery check. It logs at error level, so the journal +// keeps it. +func Test_checkUpstreamOnceKeepsACustomKeyOutOfTheJournal(t *testing.T) { + logs := captureDebugMainLog(t) + upstream, uc := customProbeUpstream() + // An empty type has no resolver, so the check fails before it sends. + uc.Type = "" + p := &prog{} + + if err := p.checkUpstreamOnce(upstream, uc, &upstreamFailureLog{}); err == nil { + t.Fatal("expected the resolver creation to fail") + } + + retained := retainedProbeLines(t, logs) + if len(retained) != 1 { + t.Fatalf("retained lines: got %d, want 1", len(retained)) + } + wantField(t, retained[0], "upstream", upstreamPrefix+"custom") + wantNoProbeSecret(t, logs) +} + +// Test_checkDnsLoopKeepsACustomKeyOutOfTheJournal drives the loop checker +// against an operator-chosen upstream key. The loop checker writes at warn +// level, so the journal keeps its line too. +func Test_checkDnsLoopKeepsACustomKeyOutOfTheJournal(t *testing.T) { + logs := captureDebugMainLog(t) + uc := &ctrld.UpstreamConfig{ + Name: probeSecret, + Type: ctrld.ResolverTypeLegacy, + Endpoint: deadUpstreamEndpoint, + Timeout: 200, + } + uc.Init() + cfg := &ctrld.Config{Upstream: map[string]*ctrld.UpstreamConfig{probeSecret: uc}} + p := &prog{cfg: cfg, um: newUpstreamMonitor(cfg), loop: make(map[string]bool)} + + p.checkDnsLoop() + + retained := retainedProbeLines(t, logs) + if len(retained) == 0 { + t.Fatal("the loop check failure must stay visible above debug") + } + for _, event := range retained { + wantField(t, event, "upstream", upstreamPrefix+"custom") + } + wantNoProbeSecret(t, logs) +} + +// Test_logUpstreamPingFailuresKeepsACustomKeyOutOfTheJournal drives the report +// that follows a failed self-check. It writes at error level, so the journal +// keeps it and the operator text must stay off the line. +func Test_logUpstreamPingFailuresKeepsACustomKeyOutOfTheJournal(t *testing.T) { + logs := captureDebugMainLog(t) + _, uc := customProbeUpstream() + origPing := upstreamPingFn + t.Cleanup(func() { upstreamPingFn = origPing }) + upstreamPingFn = func(*ctrld.UpstreamConfig) error { return errors.New("ping failed") } + + logUpstreamPingFailures(map[string]*ctrld.UpstreamConfig{probeSecret: uc}) + + retained := retainedProbeLines(t, logs) + if len(retained) != 1 { + t.Fatalf("retained lines: got %d, want 1", len(retained)) + } + wantField(t, retained[0], "upstream", upstreamPrefix+"custom") + wantNoProbeSecret(t, logs) + if !strings.Contains(logs.String(), probeSecret) { + t.Fatal("the operator text must stay at debug level for diagnosis") + } +} diff --git a/docs/network-recovery-diagnostics.md b/docs/network-recovery-diagnostics.md index d676ae1..1e01947 100644 --- a/docs/network-recovery-diagnostics.md +++ b/docs/network-recovery-diagnostics.md @@ -68,7 +68,9 @@ The two routes and the two gateways come from the route table of macOS, one rout 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. `link_type` is one of `wifi`, `ethernet`, `usb_tether`, `tunnel`, and `unknown`. -macOS reads it from the name of the hardware port. Linux reads `wifi`, `ethernet`, `usb_tether`, and `tunnel` from the kernel. Windows names a tunnel and leaves the other links unknown. +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`. The field `service` names a macOS network service. It stays empty on Windows and on Linux. `tethered` is true on every platform when the interface of the default route holds an address of the range 172.20.10.0/28. It is also true when the default gateway is in that range, and when the hardware port of the default route is `iPhone USB`. @@ -85,7 +87,7 @@ The trigger `start` always writes. A noise delta changes interfaces of the noise class only, and it does not move the default route. The noise class holds `awdl*` and `llw*` on macOS. -On Linux it holds the names `docker*`, `veth*`, `virbr*`, and `br-*`, plus the devices of the tun and tap types. +On Linux it holds the names `docker*`, `veth*`, `virbr*`, and `br-*`. A device of the tun or tap type is a tunnel, not a noise interface. On Windows it holds the virtual adapters without a connector. A Windows adapter whose description names TAP, Wintun, WireGuard, or VPN is a tunnel, not a noise interface. On Linux and on Windows, an interface that holds a global address on either side of the delta is never noise. A delta is also not noise when it flips `have_v4` or `have_v6`, or when it carries a time jump. diff --git a/internal/controld/config.go b/internal/controld/config.go index aad670a..adf83a7 100644 --- a/internal/controld/config.go +++ b/internal/controld/config.go @@ -10,6 +10,7 @@ import ( "io" "net" "net/http" + "os" "runtime" "strings" "time" @@ -289,10 +290,18 @@ func SendLogs(ctx context.Context, lr *LogsRequest, cdDev bool) error { if cdDev { apiUrl = logURLDev } - req, err := http.NewRequestWithContext(ctx, "POST", apiUrl, lr.Data) + body, size, getBody, cleanup, err := spoolLogBody(lr.Data) + if err != nil { + return err + } + defer cleanup() + + req, err := http.NewRequestWithContext(ctx, "POST", apiUrl, body) if err != nil { return fmt.Errorf("http.NewRequest: %w", err) } + req.ContentLength = size + req.GetBody = getBody q := req.URL.Query() q.Set("uid", lr.UID) req.URL.RawQuery = q.Encode() @@ -418,6 +427,15 @@ func doWithFallback(client *http.Client, req *http.Request, apiIp string) (*http ipReq := req.Clone(req.Context()) ipReq.Host = apiIp ipReq.URL.Host = apiIp + // The first attempt consumed the body. A request that can give its body + // again sends the whole body a second time. + if req.GetBody != nil { + body, bodyErr := req.GetBody() + if bodyErr != nil { + return nil, fmt.Errorf("request failed: %w; fallback to direct ip %s failed: %w", err, apiIp, bodyErr) + } + ipReq.Body = body + } resp, fallbackErr := client.Do(ipReq) if fallbackErr != nil { return nil, fmt.Errorf("request failed: %w; fallback to direct ip %s failed: %w", err, apiIp, fallbackErr) @@ -425,6 +443,34 @@ func doWithFallback(client *http.Client, req *http.Request, apiIp string) (*http return resp, nil } +// spoolLogBody copies an upload to a temporary file, so the request can go +// out a second time to the direct IP of the API. A log reader yields its +// bytes once, and the first attempt consumes them. The caller runs cleanup +// after the response arrived. +func spoolLogBody(data io.Reader) (body *os.File, size int64, getBody func() (io.ReadCloser, error), cleanup func(), err error) { + f, err := os.CreateTemp("", "ctrld-log-upload-*") + if err != nil { + return nil, 0, nil, nil, fmt.Errorf("creating the upload spool: %w", err) + } + cleanup = func() { + _ = f.Close() + _ = os.Remove(f.Name()) + } + size, err = io.Copy(f, data) + if err != nil { + cleanup() + return nil, 0, nil, nil, fmt.Errorf("writing the upload spool: %w", err) + } + if _, err := f.Seek(0, io.SeekStart); err != nil { + cleanup() + return nil, 0, nil, nil, fmt.Errorf("rewinding the upload spool: %w", err) + } + // The transport closes the body of a failed attempt, so the second body + // is a new handle on the same file. + getBody = func() (io.ReadCloser, error) { return os.Open(f.Name()) } + return f, size, getBody, cleanup, nil +} + // apiServerIP returns the direct IP to connect to API server. func apiServerIP(cdDev bool) string { if cdDev { diff --git a/internal/controld/log_upload_test.go b/internal/controld/log_upload_test.go new file mode 100644 index 0000000..5c9e5f7 --- /dev/null +++ b/internal/controld/log_upload_test.go @@ -0,0 +1,49 @@ +package controld + +import ( + "context" + "io" + "net/http" + "net/http/httptest" + "strings" + "testing" +) + +// TestDoWithFallbackResendsTheSpooledBody drives the two-attempt upload: the +// first attempt fails on a closed port and the fallback to the direct IP must +// carry the whole body, which the first attempt consumed. +func TestDoWithFallbackResendsTheSpooledBody(t *testing.T) { + payload := strings.Repeat("log line\n", 4096) + var got string + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + b, _ := io.ReadAll(r.Body) + got = string(b) + w.WriteHeader(http.StatusOK) + })) + defer srv.Close() + + body, size, getBody, cleanup, err := spoolLogBody(strings.NewReader(payload)) + if err != nil { + t.Fatalf("spoolLogBody: %v", err) + } + defer cleanup() + if size != int64(len(payload)) { + t.Fatalf("size = %d, want %d", size, len(payload)) + } + // Port 1 refuses the connection, so the first attempt fails at once. + req, err := http.NewRequestWithContext(context.Background(), http.MethodPost, "http://127.0.0.1:1/logs", body) + if err != nil { + t.Fatalf("NewRequest: %v", err) + } + req.ContentLength = size + req.GetBody = getBody + + resp, err := doWithFallback(srv.Client(), req, strings.TrimPrefix(srv.URL, "http://")) + if err != nil { + t.Fatalf("doWithFallback: %v", err) + } + resp.Body.Close() + if got != payload { + t.Fatalf("the fallback carried %d bytes, want %d", len(got), len(payload)) + } +}