diff --git a/cmd/cli/dns_intercept_darwin.go b/cmd/cli/dns_intercept_darwin.go index 798c886..08d0813 100644 --- a/cmd/cli/dns_intercept_darwin.go +++ b/cmd/cli/dns_intercept_darwin.go @@ -152,6 +152,8 @@ func writePFAnchorFile(rules string) error { type pfState struct { anchorFile string anchorName string + // Serialized by prog.interceptDNSTargetMu; bounded to one failed decision. + targetDiagnostic dnsTargetDecisionDiagnostic } // ensureCtrldGroup creates the _ctrld system group if it doesn't exist and returns its GID. diff --git a/cmd/cli/dns_proxy.go b/cmd/cli/dns_proxy.go index f63bb4b..f76e87f 100644 --- a/cmd/cli/dns_proxy.go +++ b/cmd/cli/dns_proxy.go @@ -999,7 +999,7 @@ func (p *prog) handleAllUpstreamsFailure(ctx context.Context, req *proxyRequest, } else if p.leakOnUpstreamFailure() { ctrld.Log(ctx, p.Debug(), "Leak on upstream failure enabled") if p.um.countHealthy(upstreams) == 0 { - ctrld.Log(ctx, p.Debug(), "No healthy upstreams, triggering recovery") + ctrld.Log(ctx, p.Debug(), "Selected upstreams unavailable; requesting recovery") p.triggerRecovery(upstreams[0] == upstreamOS) } else { ctrld.Log(ctx, p.Debug(), "One upstream is down but at least one is healthy; skipping recovery trigger") @@ -1256,8 +1256,8 @@ func (p *prog) triggerRecovery(isOSFailure bool) { } else { reason = RecoveryReasonRegularFailure } - p.Debug().Msgf("No healthy upstreams, triggering recovery with reason: %v", reason) - go p.handleRecovery(reason) + p.Debug().Msgf("Selected upstreams unavailable; requesting recovery with reason: %v", reason) + go queryRecoveryFn(p, reason) } else { p.Debug().Msg("Recovery already in progress; skipping duplicate trigger from down detection") } @@ -2560,6 +2560,26 @@ func (p *prog) handleRecoveryForTransition(reason RecoveryReason, transitionID u p.logger.Load().Debug().Uint64("transition_id", transitionID).Msg("Recovery skipped: transition superseded") return } + // Admission and completion use the same pool. A failed OS-only policy + // is not evidence that configured general DNS is unavailable. Check here, + // rather than only at the query, because a queued trigger can arrive late. + upstreams := p.buildRecoveryUpstreams(reason) + upstreamNames := make([]string, 0, len(upstreams)) + for name := range upstreams { + upstreamNames = append(upstreamNames, name) + } + slices.Sort(upstreamNames) + if reason == RecoveryReasonOSFailure { + if _, osOnly := upstreams[upstreamOS]; !osOnly { + for _, name := range upstreamNames { + if !p.um.isDown(name) { + p.networkSourceMu.Unlock() + p.refreshOSResolverAfterRecoverySkip(name) + return + } + } + } + } recoveryCtx, gen, interceptRecovery, ok := p.beginRecovery(reason) p.networkSourceMu.Unlock() if !ok { @@ -2569,7 +2589,8 @@ func (p *prog) handleRecoveryForTransition(reason RecoveryReason, transitionID u return } diagnostic := recoveryDiagnostic{logger: p.logger.Load(), transitionID: transitionID, generation: gen, reason: reason, started: time.Now()} - journal(diagnostic.event(p.logger.Load().Info())).Bool("intercept", interceptRecovery).Msg("Recovery begin") + journal(diagnostic.event(p.logger.Load().Info())).Bool("intercept", interceptRecovery). + Strs("probe_upstreams", journalUpstreamNames(upstreamNames)).Msg("Recovery begin") p.logNetworkSnapshot("recovery_begin") targetBefore := p.interceptTargetSnapshot() outcome := recoveryOutcomeSuperseded @@ -2610,7 +2631,7 @@ func (p *prog) handleRecoveryForTransition(reason RecoveryReason, transitionID u return } - upstreams := p.buildRecoveryUpstreams(reason) + // Wait for the same upstream pool used to admit this recovery. recovered, err := waitForUpstreamRecoveryFn(p, recoveryCtx, upstreams, &diagnostic) if err != nil { if p.recoveryGen.Load() == gen { @@ -2761,10 +2782,38 @@ func (p *prog) completeRecoveryWork(reason RecoveryReason, recovered string, int return nil } +// refreshOSResolverAfterRecoverySkip repairs stale OS resolver discovery without +// enabling bypass, changing host DNS, or clearing the monitor's failure state. +// Only a successful query establishes that the OS resolver recovered. +func (p *prog) refreshOSResolverAfterRecoverySkip(healthy string) { + if !p.osRecoveryRefreshMu.TryLock() { + return + } + defer p.osRecoveryRefreshMu.Unlock() + + now := networkEventsNowFn() + if p.osRecoverySkipLogAt.IsZero() || healthy != p.osRecoverySkipUpstream || now.Sub(p.osRecoverySkipLogAt) >= 5*time.Minute { + journal(p.Info()).Str("recovery_reason", recoveryReasonName(RecoveryReasonOSFailure)). + Str("healthy_upstream", journalUpstreamName(healthy)). + Msg("Recovery skipped: configured upstream is not marked down") + p.osRecoverySkipLogAt = now + p.osRecoverySkipUpstream = healthy + } + // Failed policy queries can arrive concurrently and at high volume. Retry + // discovery on later traffic, but never run overlapping or per-query reads. + if !p.osRecoveryRefreshAt.IsZero() && now.Sub(p.osRecoveryRefreshAt) < upstreamDownDelay { + return + } + p.osRecoveryRefreshAt = now + initializeOsResolverWithSystemNameserversFn(ctrld.LoggerCtx(context.Background(), p.logger.Load()), true, recoveryResolverReason) +} + // waitForUpstreamRecoveryFn is the seam of the upstream probe. A test drives // the whole recovery flow without a query to a real upstream. var waitForUpstreamRecoveryFn = (*prog).waitForUpstreamRecovery +var queryRecoveryFn = (*prog).handleRecovery + // waitForUpstreamRecovery checks the provided upstreams concurrently until one recovers. // It returns the name of the recovered upstream or an error if the check times out. func (p *prog) waitForUpstreamRecovery(ctx context.Context, upstreams map[string]*ctrld.UpstreamConfig, diagnostic *recoveryDiagnostic) (string, error) { @@ -2792,7 +2841,7 @@ func (p *prog) waitForUpstreamRecovery(ctx context.Context, upstreams map[string return default: attempts++ - // checkUpstreamOnce will reset any failure counters on success. + // The owning recovery resets the monitor after this probe succeeds. err := p.checkUpstreamOnce(name, uc, &failures) if err == nil || errors.Is(err, errOsHealthcheckSuppressed) { p.Debug().Msgf("Upstream %s recovered successfully", name) @@ -2870,17 +2919,26 @@ func sleepWithContext(ctx context.Context, d time.Duration) bool { } // buildRecoveryUpstreams constructs the map of upstream configurations to test. -// For OS failures we supply the manual OS resolver upstream configuration. -// For network change or regular failure we use the upstreams defined in p.cfg (ignoring OS). +// OS failures use configured non-OS upstreams for both admission and recovery, +// excluding generated Internal Domain resolvers. OS-only configurations retain +// the OS recovery path. Other recovery reasons retain their configured pool. func (p *prog) buildRecoveryUpstreams(reason RecoveryReason) map[string]*ctrld.UpstreamConfig { upstreams := make(map[string]*ctrld.UpstreamConfig) switch reason { case RecoveryReasonOSFailure: - upstreams[upstreamOS] = osUpstreamConfig + for k, uc := range p.cfg.Upstream { + name := upstreamPrefix + k + if uc != nil && uc.Type != ctrld.ResolverTypeOS && !isInternalDomainUpstream(name) { + upstreams[name] = uc + } + } + if len(upstreams) == 0 { + upstreams[upstreamOS] = osUpstreamConfig + } case RecoveryReasonNetworkChange, RecoveryReasonRegularFailure: // Use all configured upstreams except any OS type. for k, uc := range p.cfg.Upstream { - if uc.Type != ctrld.ResolverTypeOS { + if uc != nil && uc.Type != ctrld.ResolverTypeOS { upstreams[upstreamPrefix+k] = uc } } diff --git a/cmd/cli/dns_target_darwin.go b/cmd/cli/dns_target_darwin.go index b4f7938..b47c282 100644 --- a/cmd/cli/dns_target_darwin.go +++ b/cmd/cli/dns_target_darwin.go @@ -110,29 +110,52 @@ func (p *prog) ensureInterceptDNSTarget(systemDiscovery []string) { if !dnsIntercept || p.dnsInterceptState == nil { return } - if systemDiscovery == nil { - mainLog.Load().Debug().Msg("intercept DNS target: system DNS discovery was not performed; not changing DNS") - return - } p.interceptDNSTargetMu.Lock() defer p.interceptDNSTargetMu.Unlock() p.loadInterceptDNSTargetStateLocked() + var diagnostic *dnsTargetDecisionDiagnostic + if state, ok := p.dnsInterceptState.(*pfState); ok { + diagnostic = &state.targetDiagnostic + } + decision := dnsTargetDecisionContext{ + ownership: p.interceptDNSTargetOwnershipLocked(), + generation: p.recoveryGen.Load(), + transitionID: p.networkAcceptedGen.Load(), + } + // Only completed discovery resolves an outstanding diagnostic. A resolution + // describes the decision and observed ownership, not successful DNS repair. + resolvedReason := "" + defer func() { + if resolvedReason != "" { + diagnostic.resolved(decision, p.interceptDNSTargetOwnershipLocked(), resolvedReason) + } + }() + if systemDiscovery == nil { + diagnostic.failed(decision, "system_discovery", nil) + mainLog.Load().Debug().Msg("intercept DNS target: system DNS discovery was not performed; not changing DNS") + return + } drIfaceName, err := interceptDefaultRouteInterfaceFn() + decision.iface = drIfaceName if err != nil || drIfaceName == "" { // Mid-transition with no default route; the next recovery decides. + diagnostic.failed(decision, "default_route", err) return } iface, err := interceptInterfaceByNameFn(drIfaceName) if err != nil || iface == nil { + diagnostic.failed(decision, "interface_lookup", err) return } // Resolve the network service name (e.g. en5 -> "iPhone USB") so // networksetup operates on the right service. if _, err := interceptPatchNetIfaceNameFn(iface); err != nil { + diagnostic.failed(decision, "service_lookup", err) mainLog.Load().Debug().Err(err).Msgf("intercept DNS target: could not resolve network service for %s", drIfaceName) return } + decision.service = iface.Name staticDNS, err := interceptCurrentStaticDNSFn(iface) if err != nil { @@ -140,6 +163,7 @@ func (p *prog) ensureInterceptDNSTarget(systemDiscovery []string) { // networksetup cannot address them, ctrld never writes to them, and // any target set on the underlying physical service stays in place — // still correct while ctrld runs. + diagnostic.failed(decision, "static_dns", err) mainLog.Load().Debug().Err(err).Msgf("intercept DNS target: could not read static DNS for %q", iface.Name) return } @@ -150,22 +174,26 @@ func (p *prog) ensureInterceptDNSTarget(systemDiscovery []string) { staticDNS = filterOwnTarget(staticDNS, p.interceptDNSTargetSetValue) } if hasIPv4DNS(staticDNS) { + resolvedReason = "static_ipv4_dns" p.removeInterceptDNSTargetLocked("network has usable static IPv4 DNS") return } routeDHCPDNS, err := interceptDHCPNameserversForInterfaceFn(drIfaceName) if err != nil { + diagnostic.failed(decision, "dhcp_dns", err) mainLog.Load().Debug().Err(err).Msgf("intercept DNS target: could not read DHCP DNS for default-route service %q", iface.Name) return } if hasIPv4DNS(routeDHCPDNS) { + resolvedReason = "dhcp_ipv4_dns" // The default-route service regained DHCP option 6. Remove a target // previously set on this or another service. p.removeInterceptDNSTargetLocked("network has usable DHCP IPv4 DNS") return } + resolvedReason = "dns_less_network" target := p.interceptDNSTargetValue() if p.interceptDNSTargetService == iface.Name && p.interceptDNSTargetSetValue == target { return // already set on this service @@ -241,6 +269,10 @@ func (p *prog) removeInterceptDNSTargetLocked(reason string) { Msgf("intercept DNS target: removed %s from %q (%s)", val, svc, reason) } +func (p *prog) interceptDNSTargetOwnershipLocked() dnsTargetOwnership { + return dnsTargetOwnership{p.interceptDNSTargetService, p.interceptDNSTargetSetValue} +} + func (p *prog) clearInterceptDNSTargetStateLocked() { p.setInterceptDNSTargetLocked("", "") p.persistInterceptDNSTargetStateLocked() diff --git a/cmd/cli/dns_target_darwin_test.go b/cmd/cli/dns_target_darwin_test.go index a04f785..0bdb181 100644 --- a/cmd/cli/dns_target_darwin_test.go +++ b/cmd/cli/dns_target_darwin_test.go @@ -117,7 +117,7 @@ func newInterceptTargetProg() *prog { cfg: &ctrld.Config{Listener: map[string]*ctrld.ListenerConfig{ "0": {IP: "127.0.0.1", Port: 5354}, }}, - dnsInterceptState: &interceptStateStub{}, + dnsInterceptState: &pfState{}, } } diff --git a/cmd/cli/dns_target_diagnostic.go b/cmd/cli/dns_target_diagnostic.go new file mode 100644 index 0000000..8841171 --- /dev/null +++ b/cmd/cli/dns_target_diagnostic.go @@ -0,0 +1,126 @@ +package cli + +import ( + "context" + "errors" + "net" + "os" + "os/exec" + + "github.com/Control-D-Inc/ctrld" +) + +// dnsTargetDecisionDiagnostic keeps one outstanding discovery failure, not a +// history keyed by interface or recovery generation. The target mutex serializes +// access. Correlation IDs are sampled before discovery, never after a slow read. +// A successful read (including empty DNS) closes the failure; it does not claim +// that a subsequent DNS write succeeded. repeat_count counts suppressed reads +// across the whole failure episode, including condition changes; first retains +// its original correlation IDs until discovery succeeds. ID changes alone do +// not reopen the condition or turn periodic reconciliation into a log flood. +type dnsTargetDecisionDiagnostic struct { + pending bool + condition dnsTargetFailureCondition + first dnsTargetDecisionContext + repeats uint64 +} + +type dnsTargetOwnership struct { + service string + value string +} + +type dnsTargetDecisionContext struct { + iface string + service string + ownership dnsTargetOwnership + generation uint64 + transitionID uint64 +} + +type dnsTargetFailureCondition struct { + iface string + service string + ownership dnsTargetOwnership + stage string + class string +} + +// dnsTargetReadErrorClass deliberately never serializes command output or error +// text. Classify wrapped causes by type; unknown errors remain read_failed and +// must never be guessed to mean "no DNS". +func dnsTargetReadErrorClass(err error) string { + var networkError net.Error + var exitError *exec.ExitError + switch { + case err == nil: + return "unavailable" + case errors.Is(err, context.DeadlineExceeded), errors.As(err, &networkError) && networkError.Timeout(): + return "timeout" + case errors.Is(err, context.Canceled): + return "canceled" + case errors.Is(err, os.ErrPermission): + return "permission_denied" + case errors.As(err, &exitError): + return "command_failed" + default: + return "read_failed" + } +} + +func dnsTargetDecisionEvent(e *ctrld.LogEvent, c dnsTargetDecisionContext, after dnsTargetOwnership) *ctrld.LogEvent { + action := "unchanged" + if c.ownership != after { + switch { + case after.service == "": + action = "removed" + case c.ownership.service == "": + action = "set" + default: + action = "changed" + } + } + return journal(e).Str("interface", c.iface).Str("service", c.service). + Uint64("recovery_generation", c.generation).Uint64("transition_id", c.transitionID). + Str("action", action). + Bool("ownership_before", c.ownership.service != "").Bool("ownership_after", after.service != ""). + Str("owned_service_before", c.ownership.service).Str("owned_service_after", after.service). + Str("target_before", c.ownership.value).Str("target_after", after.value) +} + +func (d *dnsTargetDecisionDiagnostic) failed(c dnsTargetDecisionContext, stage string, err error) { + if d == nil { + return + } + condition := dnsTargetFailureCondition{c.iface, c.service, c.ownership, stage, dnsTargetReadErrorClass(err)} + if d.pending && d.condition == condition { + // Saturate rather than wrap during an arbitrarily long failure. + if d.repeats != ^uint64(0) { + d.repeats++ + } + return + } + if !d.pending { + d.first = c + } + d.pending = true + d.condition = condition + dnsTargetDecisionEvent(mainLog.Load().Warn(), c, c.ownership). + Str("outcome", "discovery_failed").Str("stage", stage).Str("error_class", condition.class). + Uint64("repeat_count", d.repeats). + Uint64("failure_recovery_generation", d.first.generation).Uint64("failure_transition_id", d.first.transitionID). + Msg("intercept DNS target: decision unavailable; DNS unchanged") +} + +func (d *dnsTargetDecisionDiagnostic) resolved(c dnsTargetDecisionContext, after dnsTargetOwnership, reason string) { + if d == nil || !d.pending { + return + } + dnsTargetDecisionEvent(mainLog.Load().Info(), c, after). + Str("outcome", "decision_available").Str("reason", reason). + Str("stage", d.condition.stage).Str("error_class", d.condition.class). + Uint64("repeat_count", d.repeats). + Uint64("failure_recovery_generation", d.first.generation).Uint64("failure_transition_id", d.first.transitionID). + Msg("intercept DNS target: decision available again") + *d = dnsTargetDecisionDiagnostic{} +} diff --git a/cmd/cli/dns_target_diagnostic_darwin_test.go b/cmd/cli/dns_target_diagnostic_darwin_test.go new file mode 100644 index 0000000..c83f298 --- /dev/null +++ b/cmd/cli/dns_target_diagnostic_darwin_test.go @@ -0,0 +1,272 @@ +//go:build darwin + +package cli + +import ( + "encoding/json" + "errors" + "net" + "os" + "os/exec" + "path/filepath" + "slices" + "strings" + "testing" + + "github.com/Control-D-Inc/ctrld" +) + +func TestEnsureInterceptDNSTargetFailedDecision(t *testing.T) { + for _, owned := range []bool{false, true} { + name := "without target" + if owned { + name = "existing target" + } + t.Run(name, func(t *testing.T) { + logs := captureDebugMainLog(t) + h := newInterceptTargetHarness(t) + p := newInterceptTargetProg() + p.recoveryGen.Store(3) + p.networkAcceptedGen.Store(7) + if owned { + persistInterceptTargetForTest(t, p, "Wi-Fi", "127.0.0.53") + h.dns["Wi-Fi"] = []string{"127.0.0.53"} + } + before := p.interceptDNSTargetOwnershipLocked() + fileBefore, _ := os.ReadFile(h.statePath) + // This is the first mutating call in the no-target path. Replacing it + // with a fatal stub makes any failure-to-absence regression safe/red. + save := interceptSaveCurrentStaticDNSFn + interceptSaveCurrentStaticDNSFn = func(*net.Interface) error { t.Fatal("discovery failure attempted a DNS backup"); return nil } + // Exercise the production getoption/getpacket wrapper, not a synthetic + // error. PATH contains only our fixture so no host ipconfig can run. + binDir := t.TempDir() + const script = `#!/bin/sh +case "$*" in + 'getoption en1 domain_name_server') code=17 ;; + 'getpacket en1') code=19 ;; + *) exit 99 ;; +esac +printf 'private.example command output\n' +printf 'private.example command stderr\n' >&2 +exit "$code" +` + if err := os.WriteFile(filepath.Join(binDir, "ipconfig"), []byte(script), 0700); err != nil { + t.Fatal(err) + } + t.Setenv("PATH", binDir) + dhcpStub := interceptDHCPNameserversForInterfaceFn + interceptDHCPNameserversForInterfaceFn = func(iface string) ([]string, error) { + servers, err := ctrld.DHCPNameserversForInterface(iface) + h.dhcpErr = err + return servers, err + } + for range 4 { + p.ensureInterceptDNSTarget([]string{}) + } + wrapped, ok := h.dhcpErr.(interface{ Unwrap() []error }) + if !ok || len(wrapped.Unwrap()) != 2 { + t.Fatalf("DHCP error did not preserve both command causes: %v", h.dhcpErr) + } + for i, cause := range wrapped.Unwrap() { + var exitErr *exec.ExitError + if !errors.As(cause, &exitErr) || exitErr.ExitCode() != []int{17, 19}[i] { + t.Fatalf("command cause %d = %v, want original exit error", i, cause) + } + if !strings.Contains(string(exitErr.Stderr), "private.example") { + t.Fatal("command fixture did not exercise private stderr") + } + } + if got := dnsTargetReadErrorClass(h.dhcpErr); got != "command_failed" { + t.Fatalf("production DHCP error class = %q", got) + } + if len(h.setCalls) != 0 || len(h.resetCalls) != 0 { + t.Fatal("failed discovery mutated DNS") + } + if p.interceptDNSTargetOwnershipLocked() != before { + t.Fatal("failed discovery changed ownership") + } + fileAfter, _ := os.ReadFile(h.statePath) + if !slices.Equal(fileBefore, fileAfter) { + t.Fatal("failed discovery changed persisted ownership") + } + failed := oneRecoveryEvent(t, logs, dnsTargetFailedMessage) + wantField(t, failed, "stage", "dhcp_dns") + wantField(t, failed, "error_class", "command_failed") + wantField(t, failed, "ownership_before", owned) + wantField(t, failed, "ownership_after", owned) + wantField(t, failed, "action", "unchanged") + wantField(t, failed, "service", "Wi-Fi") + wantField(t, failed, "interface", "en1") + wantField(t, failed, "journal", true) + detail := jsonLogEvents(t, logs, `intercept DNS target: could not read DHCP DNS for default-route service "Wi-Fi"`) + if len(detail) != 4 { + t.Fatal("detailed discovery errors disappeared from the debug stream") + } + wantField(t, detail[0], "level", "debug") + wantField(t, detail[0], "error", h.dhcpErr.Error()) + + // Successful empty discovery is different from failure: only now may + // ctrld install the loopback target (or keep an existing one). + interceptSaveCurrentStaticDNSFn = save + interceptDHCPNameserversForInterfaceFn = dhcpStub + h.dhcpErr = nil + p.recoveryGen.Store(4) + p.networkAcceptedGen.Store(8) + p.ensureInterceptDNSTarget([]string{}) + p.ensureInterceptDNSTarget([]string{}) + resolved := oneRecoveryEvent(t, logs, dnsTargetResolvedMessage) + wantField(t, resolved, "error_class", "command_failed") + for _, event := range []map[string]any{failed, resolved} { + encoded, err := json.Marshal(event) + if err != nil { + t.Fatal(err) + } + for _, raw := range []string{"error reading DHCP", "getoption", "getpacket", "exit status", "private.example"} { + if strings.Contains(string(encoded), raw) { + t.Fatalf("raw command error/output leaked into decision diagnostic: %s", encoded) + } + } + if _, ok := event["error"]; ok { + t.Fatal("decision diagnostic included a raw error field") + } + } + wantField(t, resolved, "reason", "dns_less_network") + wantField(t, resolved, "repeat_count", float64(3)) + wantField(t, resolved, "failure_recovery_generation", float64(3)) + wantField(t, resolved, "failure_transition_id", float64(7)) + wantField(t, resolved, "recovery_generation", float64(4)) + wantField(t, resolved, "transition_id", float64(8)) + wantField(t, resolved, "ownership_before", owned) + wantField(t, resolved, "ownership_after", true) + action := "set" + if owned { + action = "unchanged" + } + wantField(t, resolved, "action", action) + wantSets := 1 + if owned { + wantSets = 0 + } + if len(h.setCalls) != wantSets || len(h.resetCalls) != 0 { + t.Fatalf("set/reset = %v/%v", h.setCalls, h.resetCalls) + } + if !slices.Equal(h.dns["Wi-Fi"], []string{"127.0.0.53"}) { + t.Fatal("empty discovery did not preserve a target") + } + + // DHCP IPv4 arriving later must still remove it exactly once. + h.dhcp = []string{"192.0.2.1"} + p.ensureInterceptDNSTarget([]string{}) + p.ensureInterceptDNSTarget([]string{}) + if len(h.resetCalls) != 1 || p.interceptDNSTargetService != "" { + t.Fatal("later IPv4 DNS did not remove target once") + } + }) + } +} + +func TestEnsureInterceptDNSTargetFailureThenIPv4(t *testing.T) { + for _, static := range []bool{false, true} { + name := "dhcp" + if static { + name = "static" + } + t.Run(name, func(t *testing.T) { + logs := captureDebugMainLog(t) + h := newInterceptTargetHarness(t) + p := newInterceptTargetProg() + persistInterceptTargetForTest(t, p, "Wi-Fi", "127.0.0.53") + h.dns["Wi-Fi"] = []string{"127.0.0.53"} + h.dhcpErr = errors.New("failed read") + p.ensureInterceptDNSTarget([]string{}) + h.dhcpErr = nil + h.dhcp = []string{"192.0.2.1"} + reason := "dhcp_ipv4_dns" + if static { + h.dns["Wi-Fi"] = []string{"192.0.2.1"} + reason = "static_ipv4_dns" + } + p.ensureInterceptDNSTarget([]string{}) + resolved := oneRecoveryEvent(t, logs, dnsTargetResolvedMessage) + wantField(t, resolved, "reason", reason) + wantField(t, resolved, "action", "removed") + wantField(t, resolved, "ownership_before", true) + wantField(t, resolved, "ownership_after", false) + if static && !slices.Equal(h.dns["Wi-Fi"], []string{"192.0.2.1"}) { + t.Fatal("external static DNS was changed") + } + }) + } +} + +func TestEnsureInterceptDNSTargetDiscoveryFailureStages(t *testing.T) { + for _, stage := range []string{"system_discovery", "default_route", "interface_lookup", "service_lookup", "static_dns"} { + t.Run(stage, func(t *testing.T) { + logs := captureDebugMainLog(t) + h := newInterceptTargetHarness(t) + p := newInterceptTargetProg() + input := []string{} + err := errors.New("synthetic read error") + switch stage { + case "system_discovery": + input = nil + case "default_route": + interceptDefaultRouteInterfaceFn = func() (string, error) { return "", err } + case "interface_lookup": + interceptInterfaceByNameFn = func(string) (*net.Interface, error) { return nil, err } + case "service_lookup": + interceptPatchNetIfaceNameFn = func(*net.Interface) (bool, error) { return false, err } + case "static_dns": + h.readErr = err + } + interceptSaveCurrentStaticDNSFn = func(*net.Interface) error { t.Fatal("failed discovery attempted backup"); return nil } + p.ensureInterceptDNSTarget(input) + p.ensureInterceptDNSTarget(input) + if len(h.setCalls) != 0 || len(h.resetCalls) != 0 { + t.Fatal("failed discovery mutated DNS") + } + wantField(t, oneRecoveryEvent(t, logs, dnsTargetFailedMessage), "stage", stage) + }) + } +} + +func TestEnsureInterceptDNSTargetResolutionDoesNotClaimWriteSuccess(t *testing.T) { + logs := captureDebugMainLog(t) + h := newInterceptTargetHarness(t) + p := newInterceptTargetProg() + h.dhcpErr = errors.New("read failed") + p.ensureInterceptDNSTarget([]string{}) + h.dhcpErr = nil + h.setErr = errors.New("synthetic set failure") + p.ensureInterceptDNSTarget([]string{}) + event := oneRecoveryEvent(t, logs, dnsTargetResolvedMessage) + wantField(t, event, "outcome", "decision_available") + wantField(t, event, "reason", "dns_less_network") + wantField(t, event, "action", "unchanged") + wantField(t, event, "ownership_before", false) + wantField(t, event, "ownership_after", false) + if len(h.setCalls) != 1 || p.interceptDNSTargetService != "" { + t.Fatal("failed target write was not exercised or acquired ownership") + } +} + +func TestEnsureInterceptDNSTargetSamplesCorrelationBeforeRead(t *testing.T) { + logs := captureDebugMainLog(t) + h := newInterceptTargetHarness(t) + p := newInterceptTargetProg() + p.recoveryGen.Store(2) + p.networkAcceptedGen.Store(5) + interceptDHCPNameserversForInterfaceFn = func(string) ([]string, error) { + p.recoveryGen.Store(3) + p.networkAcceptedGen.Store(6) + return nil, errors.New("read failed") + } + p.ensureInterceptDNSTarget([]string{}) + event := oneRecoveryEvent(t, logs, dnsTargetFailedMessage) + wantField(t, event, "recovery_generation", float64(2)) + wantField(t, event, "transition_id", float64(5)) + if len(h.setCalls) != 0 || len(h.resetCalls) != 0 { + t.Fatal("failed discovery mutated DNS") + } +} diff --git a/cmd/cli/dns_target_diagnostic_test.go b/cmd/cli/dns_target_diagnostic_test.go new file mode 100644 index 0000000..9a323dc --- /dev/null +++ b/cmd/cli/dns_target_diagnostic_test.go @@ -0,0 +1,200 @@ +package cli + +import ( + "context" + "errors" + "fmt" + "os" + "os/exec" + "strings" + "testing" + "time" +) + +const ( + dnsTargetFailedMessage = "intercept DNS target: decision unavailable; DNS unchanged" + dnsTargetResolvedMessage = "intercept DNS target: decision available again" +) + +func TestDNSTargetReadErrorClass(t *testing.T) { + for _, tc := range []struct { + name string + err error + want string + }{ + {"missing", nil, "unavailable"}, + {"deadline", fmt.Errorf("wrapped: %w", context.DeadlineExceeded), "timeout"}, + {"canceled", context.Canceled, "canceled"}, + {"permission", &os.PathError{Op: "read", Path: "private", Err: os.ErrPermission}, "permission_denied"}, + {"command", &exec.ExitError{}, "command_failed"}, + {"wrapped command", fmt.Errorf("wrapped: %w", &exec.ExitError{}), "command_failed"}, + {"untyped error", errors.New("exit status 1"), "read_failed"}, + } { + t.Run(tc.name, func(t *testing.T) { + if got := dnsTargetReadErrorClass(tc.err); got != tc.want { + t.Fatalf("class = %q, want %q", got, tc.want) + } + }) + } +} + +func TestDNSTargetDiagnosticFailureAndResolution(t *testing.T) { + for _, owned := range []bool{false, true} { + t.Run(fmt.Sprintf("owned=%t", owned), func(t *testing.T) { + logs := captureDebugMainLog(t) + d := dnsTargetDecisionDiagnostic{} + c := dnsTargetDecisionContext{iface: "en1", service: "Wi-Fi", generation: 3, transitionID: 7} + if owned { + c.ownership = dnsTargetOwnership{"Wi-Fi", "127.0.0.53"} + } + // A healthy pass must not turn the watchdog into a journal heartbeat. + d.resolved(c, c.ownership, "dns_less_network") + failure := errors.New("private.example must not be retained") + d.failed(c, "dhcp_dns", failure) + for range 100 { + c.generation++ + c.transitionID++ + d.failed(c, "dhcp_dns", failure) + } + failed := oneRecoveryEvent(t, logs, dnsTargetFailedMessage) + wantField(t, failed, "journal", true) + wantField(t, failed, "level", "warn") + wantField(t, failed, "interface", "en1") + wantField(t, failed, "service", "Wi-Fi") + wantField(t, failed, "stage", "dhcp_dns") + wantField(t, failed, "error_class", "read_failed") + wantField(t, failed, "action", "unchanged") + wantField(t, failed, "ownership_before", owned) + wantField(t, failed, "ownership_after", owned) + wantField(t, failed, "recovery_generation", float64(3)) + wantField(t, failed, "transition_id", float64(7)) + d.resolved(c, c.ownership, "dns_less_network") + d.resolved(c, c.ownership, "dns_less_network") + resolved := oneRecoveryEvent(t, logs, dnsTargetResolvedMessage) + wantField(t, resolved, "journal", true) + wantField(t, resolved, "level", "info") + wantField(t, resolved, "repeat_count", float64(100)) + wantField(t, resolved, "failure_recovery_generation", float64(3)) + wantField(t, resolved, "failure_transition_id", float64(7)) + wantField(t, resolved, "recovery_generation", float64(103)) + wantField(t, resolved, "transition_id", float64(107)) + if strings.Contains(logs.String(), "private.example") { + t.Fatal("raw read error leaked into diagnostics") + } + if d != (dnsTargetDecisionDiagnostic{}) { + t.Fatal("resolved diagnostic retained failure state") + } + if len(jsonLogEvents(t, logs, "")) != 2 { + t.Fatal("repeated failures or healthy decisions were logged") + } + }) + } +} + +func TestDNSTargetDiagnosticConditionChanges(t *testing.T) { + for _, change := range []string{"interface", "service", "ownership", "stage", "class"} { + t.Run(change, func(t *testing.T) { + logs := captureDebugMainLog(t) + d := dnsTargetDecisionDiagnostic{} + c := dnsTargetDecisionContext{iface: "en1", service: "Wi-Fi"} + err := errors.New("read failed") + stage := "dhcp_dns" + d.failed(c, stage, err) + d.failed(c, stage, err) + switch change { + case "interface": + c.iface = "en2" + case "service": + c.service = "USB" + case "ownership": + c.ownership = dnsTargetOwnership{"USB", "127.0.0.53"} + case "stage": + stage = "static_dns" + case "class": + err = context.DeadlineExceeded + } + d.failed(c, stage, err) + d.failed(c, stage, err) + if got := len(jsonLogEvents(t, logs, dnsTargetFailedMessage)); got != 2 { + t.Fatalf("condition-change failures = %d, want 2", got) + } + d.resolved(c, dnsTargetOwnership{}, "dhcp_ipv4_dns") + wantField(t, oneRecoveryEvent(t, logs, dnsTargetResolvedMessage), "repeat_count", float64(2)) + // A new episode must log again and reset the suppressed count. + d.failed(c, stage, err) + if d.repeats != 0 { + t.Fatal("new episode retained old repeat count") + } + }) + } +} + +func TestDNSTargetDiagnosticRepeatCountSaturates(t *testing.T) { + captureDebugMainLog(t) + d := dnsTargetDecisionDiagnostic{} + c := dnsTargetDecisionContext{} + d.failed(c, "dhcp_dns", nil) + d.repeats = ^uint64(0) + d.failed(c, "dhcp_dns", nil) + if d.repeats != ^uint64(0) { + t.Fatal("repeat count wrapped") + } +} + +func TestDNSTargetDiagnosticOwnershipActions(t *testing.T) { + owned := dnsTargetOwnership{"Wi-Fi", "127.0.0.53"} + for _, tc := range []struct { + action string + before, after dnsTargetOwnership + }{ + {"set", dnsTargetOwnership{}, owned}, + {"removed", owned, dnsTargetOwnership{}}, + {"changed", owned, dnsTargetOwnership{"USB", "127.0.0.53"}}, + {"unchanged", owned, owned}, + } { + t.Run(tc.action, func(t *testing.T) { + logs := captureDebugMainLog(t) + d := dnsTargetDecisionDiagnostic{} + c := dnsTargetDecisionContext{ownership: tc.before} + d.failed(c, "dhcp_dns", os.ErrPermission) + d.resolved(c, tc.after, "dns_less_network") + event := oneRecoveryEvent(t, logs, dnsTargetResolvedMessage) + wantField(t, event, "action", tc.action) + wantField(t, event, "owned_service_before", tc.before.service) + wantField(t, event, "owned_service_after", tc.after.service) + wantField(t, event, "target_before", tc.before.value) + wantField(t, event, "target_after", tc.after.value) + }) + } +} + +func TestDNSTargetDiagnosticSurvivesDebugTruncation(t *testing.T) { + p, _ := startInternalLogging(t) + useTestSendBudget(t, 1024) + d := dnsTargetDecisionDiagnostic{} + c := dnsTargetDecisionContext{iface: "en1", service: "Wi-Fi"} + d.failed(c, "dhcp_dns", errors.New("private.example")) + for range 5 { + d.failed(c, "dhcp_dns", errors.New("private.example")) + } + d.resolved(c, dnsTargetOwnership{"Wi-Fi", "127.0.0.53"}, "dns_less_network") + for range 40 { + mainLog.Load().Debug().Msg(strings.Repeat("debug filler", 20)) + } + start := time.Now() + debugPart, journalPart := splitUpload(t, readLogReader(t, p, false), start) + for _, message := range []string{dnsTargetFailedMessage, dnsTargetResolvedMessage} { + if strings.Contains(string(debugPart), message) { + t.Fatalf("fixture did not truncate %q from debug", message) + } + if strings.Count(string(journalPart), message) != 1 { + t.Fatalf("journal did not retain exactly one %q", message) + } + } + if !strings.Contains(string(journalPart), `"repeat_count":5`) { + t.Fatal("journal lost repeat count") + } + if strings.Contains(string(journalPart), "private.example") { + t.Fatal("raw error leaked into journal") + } +} diff --git a/cmd/cli/prog.go b/cmd/cli/prog.go index 0079278..f546d16 100644 --- a/cmd/cli/prog.go +++ b/cmd/cli/prog.go @@ -177,6 +177,12 @@ type prog struct { recoveryRunning atomic.Bool recoveryGen atomic.Uint64 + // OS-only failures can refresh the resolver without owning global recovery. + osRecoveryRefreshMu sync.Mutex + osRecoveryRefreshAt time.Time + osRecoverySkipLogAt time.Time + osRecoverySkipUpstream string + // All deltas get an ID. Only accepted deltas replace recovery ownership. networkTransitionGen atomic.Uint64 networkAcceptedGen atomic.Uint64 diff --git a/cmd/cli/recovery_scope_test.go b/cmd/cli/recovery_scope_test.go new file mode 100644 index 0000000..79f21ef --- /dev/null +++ b/cmd/cli/recovery_scope_test.go @@ -0,0 +1,346 @@ +package cli + +import ( + "context" + "net" + "reflect" + "sync/atomic" + "testing" + "time" + + "github.com/miekg/dns" + ctrld "github.com/Control-D-Inc/ctrld" +) + +// Loopback transports exercise the real proxy and recovery loop without host +// DNS changes. The event harness intercepts the first platform mutation. +func scopeTestResolver(t *testing.T, answering *atomic.Bool, calls *atomic.Int64) *ctrld.UpstreamConfig { + t.Helper() + pc, err := net.ListenPacket("udp", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + started := make(chan struct{}) + srv := &dns.Server{PacketConn: pc, Net: "udp", NotifyStartedFunc: func() { close(started) }, Handler: dns.HandlerFunc(func(w dns.ResponseWriter, m *dns.Msg) { + calls.Add(1) + if answering.Load() { + a := new(dns.Msg) + a.SetReply(m) + _ = w.WriteMsg(a) + } + })} + go func() { _ = srv.ActivateAndServe() }() + <-started + t.Cleanup(func() { _ = srv.Shutdown() }) + return &ctrld.UpstreamConfig{Type: ctrld.ResolverTypeLegacy, Endpoint: pc.LocalAddr().String(), Timeout: 40} +} + +type scopeTestHarness struct { + *recoveryEventHarness + osAnswers, defaultAnswers atomic.Bool + osCalls, defaultCalls atomic.Int64 + finished chan struct{} +} + +func newScopeTestHarness(t *testing.T) *scopeTestHarness { + t.Helper() + h := &scopeTestHarness{recoveryEventHarness: newRecoveryEventHarness(t), finished: make(chan struct{}, 8)} + // These flows keep interception active (or reject recovery before host work). + // Fence the first platform calls if that contract regresses, not merely a + // later DNS write: startDNSIntercept can install PF/NRPT/WFP policy. + oldStart, oldReset := startDNSInterceptFn, recoveryResetDNSFn + var hostCalls atomic.Int64 + startDNSInterceptFn = func(*prog) error { + hostCalls.Add(1) + t.Fatal("scope recovery attempted to start host interception") + return nil + } + recoveryResetDNSFn = func(*prog, bool, bool) { + hostCalls.Add(1) + t.Fatal("scope recovery attempted to reset host DNS") + } + t.Cleanup(func() { + startDNSInterceptFn, recoveryResetDNSFn = oldStart, oldReset + if got := hostCalls.Load(); got != 0 { + t.Errorf("unexpected first host calls: %d", got) + } + }) + h.dhcpServers = nil + initializeOsResolverWithSystemNameserversFn = func(context.Context, bool, string) ([]string, []string) { return nil, nil } + oldOS, oldQueryRecovery := osUpstreamConfig, queryRecoveryFn + t.Cleanup(func() { osUpstreamConfig, queryRecoveryFn = oldOS, oldQueryRecovery }) + osUpstreamConfig = scopeTestResolver(t, &h.osAnswers, &h.osCalls) + h.defaultAnswers.Store(true) + h.prog.cfg.Upstream = map[string]*ctrld.UpstreamConfig{"0": scopeTestResolver(t, &h.defaultAnswers, &h.defaultCalls)} + leak := true + h.prog.cfg.Service.LeakOnUpstreamFailure = &leak + h.prog.um = newUpstreamMonitor(h.prog.cfg, mainLog.Load()) + h.prog.um.after = func(time.Duration, func()) {} + h.prog.um.clearRecovered(upstreamOS) + h.prog.um.clearRecovered("upstream.0") + queryRecoveryFn = func(p *prog, reason RecoveryReason) { + p.handleRecovery(reason) + h.finished <- struct{}{} + } + return h +} + +func (h *scopeTestHarness) query(t *testing.T, policy bool) *proxyResponse { + t.Helper() + name := "ordinary.example." + ufr := &upstreamForResult{upstreams: []string{"upstream.0"}, matched: true} + if policy { + name = "os-only.example." + lc := listenerWithRules(ctrld.Rule{"os-only.example": []string{}}) + ufr = h.prog.upstreamFor(context.Background(), "0", lc, &net.UDPAddr{IP: net.IPv4(127, 0, 0, 1), Port: 53000}, "", "os-only.example") + if !ufr.matched || len(ufr.upstreams) != 0 { + t.Fatalf("wrong policy fixture: %+v", ufr) + } + } + m := new(dns.Msg) + m.SetQuestion(name, dns.TypeTXT) + return h.prog.proxy(context.Background(), &proxyRequest{msg: m, ufr: ufr}) +} + +func (h *scopeTestHarness) markOSDown(t *testing.T) { + t.Helper() + if got := h.query(t, true).answer.Rcode; got != dns.RcodeServerFailure { + t.Fatalf("OS fixture rcode=%d", got) + } + // Fire the real delayed-down callback without waiting ten seconds. + h.prog.um.markDownAfterDelay(upstreamOS) + if !h.prog.um.isDown(upstreamOS) { + t.Fatal("OS down precondition failed") + } +} + +func scopeWait(t *testing.T, ch <-chan struct{}) { + t.Helper() + select { + case <-ch: + case <-time.After(5 * time.Second): + t.Fatal("recovery handler did not return") + } +} + +func TestOSPolicyFailureDoesNotBypassHealthyDefault(t *testing.T) { + h := newScopeTestHarness(t) + if h.query(t, false).answer.Rcode != dns.RcodeSuccess { + t.Fatal("default fixture failed") + } + h.markOSDown(t) + for range 3 { + if h.query(t, true).answer.Rcode != dns.RcodeServerFailure { + t.Fatal("policy changed resolver") + } + scopeWait(t, h.finished) + if h.prog.recoveryBypass.Load() || h.prog.recoveryRunning.Load() { + t.Fatal("policy failure started global recovery") + } + } + before := h.osCalls.Load() + if h.query(t, false).answer.Rcode != dns.RcodeSuccess { + t.Fatal("default request failed") + } + if h.osCalls.Load() != before { + t.Fatal("unrelated request detoured through OS DNS") + } + if len(jsonLogEvents(t, h.logs, recoveryBeginMessage)) != 0 { + t.Fatal("rejected recovery touched host state") + } +} + +func TestQueuedOSFailureRechecksHealthyDefault(t *testing.T) { + h := newScopeTestHarness(t) + h.markOSDown(t) + h.prog.um.mu.Lock() + h.prog.um.markDown("upstream.0", 1, "test") + h.prog.um.mu.Unlock() + entered, proceed := make(chan struct{}), make(chan struct{}) + queryRecoveryFn = func(p *prog, reason RecoveryReason) { + close(entered) + <-proceed + p.handleRecovery(reason) + h.finished <- struct{}{} + } + h.query(t, true) + scopeWait(t, entered) + if h.query(t, false).answer.Rcode != dns.RcodeSuccess { + t.Fatal("default did not recover") + } + close(proceed) + scopeWait(t, h.finished) + if len(jsonLogEvents(t, h.logs, recoveryBeginMessage)) != 0 { + t.Fatal("late OS trigger ignored newer default success") + } +} + +func TestOSFailureRecoversThroughConfiguredPool(t *testing.T) { + h := newScopeTestHarness(t) + h.markOSDown(t) + h.prog.um.mu.Lock() + h.prog.um.markDown("upstream.0", 1, "test") + h.prog.um.mu.Unlock() + candidates := make(chan map[string]*ctrld.UpstreamConfig, 1) + proceed := make(chan struct{}) + waitForUpstreamRecoveryFn = func(p *prog, ctx context.Context, ups map[string]*ctrld.UpstreamConfig, diagnostic *recoveryDiagnostic) (string, error) { + candidates <- ups + <-proceed + return p.waitForUpstreamRecovery(ctx, ups, diagnostic) + } + h.query(t, true) + select { + case ups := <-candidates: + if len(ups) != 1 || ups["upstream.0"] != h.prog.cfg.Upstream["0"] { + t.Fatalf("wrong recovery pool: %v", ups) + } + case <-time.After(time.Second): + t.Fatal("general outage did not enter recovery") + } + if !h.prog.recoveryBypass.Load() { + t.Fatal("general outage did not enable bypass") + } + close(proceed) + scopeWait(t, h.finished) + if h.prog.recoveryBypass.Load() || h.prog.recoveryRunning.Load() { + t.Fatal("healthy default did not end recovery") + } + if !h.prog.um.isDown(upstreamOS) { + t.Fatal("fixture OS resolver unexpectedly recovered") + } +} + +func TestOSOnlyConfigurationRetainsOSRecovery(t *testing.T) { + h := newScopeTestHarness(t) + h.prog.cfg.Upstream = nil + h.markOSDown(t) + waitForUpstreamRecoveryFn = func(p *prog, ctx context.Context, ups map[string]*ctrld.UpstreamConfig, diagnostic *recoveryDiagnostic) (string, error) { + if len(ups) != 1 || ups[upstreamOS] != osUpstreamConfig { + return "", context.Canceled + } + h.osAnswers.Store(true) + return p.waitForUpstreamRecovery(ctx, ups, diagnostic) + } + h.query(t, true) + scopeWait(t, h.finished) + end := oneRecoveryEvent(t, h.logs, recoveryEndMessage) + wantField(t, end, "outcome", "completed") + wantField(t, end, "recovered_upstream", upstreamOS) + if h.prog.recoveryBypass.Load() || h.prog.um.isDown(upstreamOS) { + t.Fatal("OS-only recovery did not finish") + } +} + +func TestOSRecoveryRejectedBeforeHostWork(t *testing.T) { + for _, intercept := range []bool{false, true} { + t.Run(map[bool]string{false: "traditional", true: "intercept"}[intercept], func(t *testing.T) { + h := newScopeTestHarness(t) + dnsIntercept = intercept + oldReset := recoveryResetDNSFn + t.Cleanup(func() { recoveryResetDNSFn = oldReset }) + calls := 0 + recoveryResetDNSFn = func(*prog, bool, bool) { calls++ } + refreshes := 0 + initializeOsResolverWithSystemNameserversFn = func(context.Context, bool, string) ([]string, []string) { refreshes++; return nil, nil } + ensureInterceptDNSTargetFn = func(*prog, []string) { calls++ } + waitForUpstreamRecoveryFn = func(*prog, context.Context, map[string]*ctrld.UpstreamConfig, *recoveryDiagnostic) (string, error) { + calls++ + return "", context.Canceled + } + before := h.prog.recoveryGen.Load() + h.prog.handleRecovery(RecoveryReasonOSFailure) + if refreshes != 1 || calls != 0 || h.prog.recoveryGen.Load() != before || h.prog.recoveryRunning.Load() || h.prog.recoveryBypass.Load() { + t.Fatal("rejected recovery failed to refresh only OS resolver discovery") + } + }) + } +} + +func TestOSRecoveryKeepsExistingOwner(t *testing.T) { + h := newScopeTestHarness(t) + ctx, gen, _, ok := h.prog.beginRecovery(RecoveryReasonRegularFailure) + if !ok { + t.Fatal("could not establish prior owner") + } + t.Cleanup(func() { h.prog.completeRecoveryState(gen) }) + h.prog.handleRecovery(RecoveryReasonOSFailure) + if ctx.Err() != nil || h.prog.recoveryGen.Load() != gen || !h.prog.recoveryOwnsState(gen) || !h.prog.recoveryBypass.Load() { + t.Fatal("rejected OS recovery displaced the active owner") + } +} + +func TestOSRecoveryConfiguredPoolDoesNotBlockRegularFailure(t *testing.T) { + h := newScopeTestHarness(t) + h.markOSDown(t) + h.prog.cfg.Upstream["unused"] = &ctrld.UpstreamConfig{Type: ctrld.ResolverTypeLegacy, Endpoint: "127.0.0.1:1"} + h.prog.um.mu.Lock() + h.prog.um.markDown("upstream.0", 1, "test") + h.prog.um.mu.Unlock() + h.query(t, true) + scopeWait(t, h.finished) + if len(jsonLogEvents(t, h.logs, recoveryBeginMessage)) != 0 { + t.Fatal("OS admission ignored an unmarked configured candidate") + } + // Ordinary default failure still follows its original admission path. + h.defaultAnswers.Store(false) + h.query(t, false) + scopeWait(t, h.finished) + begin := oneRecoveryEvent(t, h.logs, recoveryBeginMessage) + wantField(t, begin, "recovery_reason", "upstream_failure") +} + +func TestOtherRecoveryPoolsRemainUnchanged(t *testing.T) { + remote := &ctrld.UpstreamConfig{Type: ctrld.ResolverTypeDOH} + internal := &ctrld.UpstreamConfig{Type: ctrld.ResolverTypeLegacy} + p := &prog{cfg: &ctrld.Config{Upstream: map[string]*ctrld.UpstreamConfig{ + "0": remote, "internal_0": internal, "1": {Type: ctrld.ResolverTypeOS}, "2": nil, + }}} + want := map[string]*ctrld.UpstreamConfig{"upstream.0": remote, "upstream.internal_0": internal} + for _, reason := range []RecoveryReason{RecoveryReasonRegularFailure, RecoveryReasonNetworkChange} { + if got := p.buildRecoveryUpstreams(reason); !reflect.DeepEqual(got, want) { + t.Fatalf("reason=%v got=%v want=%v", reason, got, want) + } + } +} + +func TestScopeHarnessRestoresRecoveryWait(t *testing.T) { + original := waitForUpstreamRecoveryFn + t.Cleanup(func() { waitForUpstreamRecoveryFn = original }) + waitForUpstreamRecoveryFn = func(*prog, context.Context, map[string]*ctrld.UpstreamConfig, *recoveryDiagnostic) (string, error) { + return "outer", nil + } + t.Run("overridden wait", func(t *testing.T) { + newScopeTestHarness(t) + waitForUpstreamRecoveryFn = func(*prog, context.Context, map[string]*ctrld.UpstreamConfig, *recoveryDiagnostic) (string, error) { + return "inner", nil + } + }) + got, err := waitForUpstreamRecoveryFn(nil, context.Background(), nil, nil) + if err != nil || got != "outer" { + t.Fatalf("composed harness leaked its wait function: got %q, %v", got, err) + } +} + +func TestOSRecoveryCandidates(t *testing.T) { + remote := &ctrld.UpstreamConfig{Type: ctrld.ResolverTypeDOH} + internal := &ctrld.UpstreamConfig{Type: ctrld.ResolverTypeLegacy} + osConfig := &ctrld.UpstreamConfig{Type: ctrld.ResolverTypeOS} + for _, tc := range []struct { + name string + configured map[string]*ctrld.UpstreamConfig + want map[string]*ctrld.UpstreamConfig + }{ + {"configured", map[string]*ctrld.UpstreamConfig{"0": remote, "internal_0": internal, "1": osConfig, "2": nil}, map[string]*ctrld.UpstreamConfig{"upstream.0": remote}}, + {"custom_policy_or_unused", map[string]*ctrld.UpstreamConfig{"0": remote, "unused": internal}, map[string]*ctrld.UpstreamConfig{"upstream.0": remote, "upstream.unused": internal}}, + {"only_os", map[string]*ctrld.UpstreamConfig{"0": osConfig}, map[string]*ctrld.UpstreamConfig{upstreamOS: osUpstreamConfig}}, + {"only_internal", map[string]*ctrld.UpstreamConfig{"internal_0": internal}, map[string]*ctrld.UpstreamConfig{upstreamOS: osUpstreamConfig}}, + {"empty", nil, map[string]*ctrld.UpstreamConfig{upstreamOS: osUpstreamConfig}}, + } { + t.Run(tc.name, func(t *testing.T) { + p := &prog{cfg: &ctrld.Config{Upstream: tc.configured}} + if got := p.buildRecoveryUpstreams(RecoveryReasonOSFailure); !reflect.DeepEqual(got, tc.want) { + t.Fatalf("got %v want %v", got, tc.want) + } + }) + } +} diff --git a/cmd/cli/recovery_skip_test.go b/cmd/cli/recovery_skip_test.go new file mode 100644 index 0000000..6806fe4 --- /dev/null +++ b/cmd/cli/recovery_skip_test.go @@ -0,0 +1,149 @@ +package cli + +import ( + "context" + "strings" + "sync/atomic" + "testing" + "time" + + "github.com/miekg/dns" + ctrld "github.com/Control-D-Inc/ctrld" +) + +const recoverySkipMessage = "Recovery skipped: configured upstream is not marked down" + +func TestOSRecoverySkipRefreshesWithoutNetworkChange(t *testing.T) { + h := newScopeTestHarness(t) + h.markOSDown(t) + var refreshes atomic.Int64 + initializeOsResolverWithSystemNameserversFn = func(_ context.Context, guard bool, reason string) ([]string, []string) { + if !guard || reason != recoveryResolverReason { + t.Error("refresh lost empty-discovery guard or reason") + } + refreshes.Add(1) + h.osAnswers.Store(true) + return nil, nil + } + // This query still fails; the asynchronously triggered refresh repairs + // discovery for the next policy query, without a network-change callback. + h.query(t, true) + scopeWait(t, h.finished) + if refreshes.Load() != 1 || !h.prog.um.isDown(upstreamOS) { + t.Fatal("refresh must run without claiming a successful OS response") + } + if h.query(t, true).answer.Rcode != dns.RcodeSuccess || h.prog.um.isDown(upstreamOS) { + t.Fatal("OS policy did not recover on its own resolver") + } + if h.prog.recoveryBypass.Load() || h.prog.recoveryRunning.Load() || h.prog.recoveryGen.Load() != 0 { + t.Fatal("local refresh acquired global recovery state") + } +} + +func TestOSRecoverySkipRefreshIsBounded(t *testing.T) { + h := newScopeTestHarness(t) + now := time.Unix(1000, 0) + oldNow := networkEventsNowFn + networkEventsNowFn = func() time.Time { return now } + t.Cleanup(func() { networkEventsNowFn = oldNow }) + calls := 0 + initializeOsResolverWithSystemNameserversFn = func(context.Context, bool, string) ([]string, []string) { + calls++ + return nil, nil + } + for range 100 { + h.prog.handleRecovery(RecoveryReasonOSFailure) + } + if calls != 1 { + t.Fatalf("burst discovery calls=%d, want 1", calls) + } + now = now.Add(upstreamDownDelay - time.Nanosecond) + h.prog.handleRecovery(RecoveryReasonOSFailure) + if calls != 1 { + t.Fatal("discovery retried before the cooldown") + } + now = now.Add(time.Nanosecond) + h.prog.handleRecovery(RecoveryReasonOSFailure) + if calls != 2 { + t.Fatal("later OS failures cannot retry discovery") + } + event := oneRecoveryEvent(t, h.logs, recoverySkipMessage) + wantField(t, event, "journal", true) + wantField(t, event, "healthy_upstream", "upstream.0") + wantField(t, event, "recovery_reason", "os_resolver_failure") + now = now.Add(5 * time.Minute) + h.prog.handleRecovery(RecoveryReasonOSFailure) + if len(jsonLogEvents(t, h.logs, recoverySkipMessage)) != 2 { + t.Fatal("persistent skips lost the bounded journal heartbeat") + } +} + +func TestOSRecoverySkipCoalescesConcurrentRefresh(t *testing.T) { + h := newScopeTestHarness(t) + entered, release, done := make(chan struct{}), make(chan struct{}), make(chan struct{}) + var calls atomic.Int64 + initializeOsResolverWithSystemNameserversFn = func(context.Context, bool, string) ([]string, []string) { + if calls.Add(1) == 1 { + close(entered) + } + <-release + return nil, nil + } + go func() { h.prog.handleRecovery(RecoveryReasonOSFailure); close(done) }() + scopeWait(t, entered) + other := make(chan struct{}) + go func() { h.prog.handleRecovery(RecoveryReasonOSFailure); close(other) }() + // Release the first worker even if coalescing regresses, to keep cleanup safe. + select { + case <-other: + case <-time.After(time.Second): + close(release) + scopeWait(t, done) + scopeWait(t, other) + t.Fatal("concurrent failure waited on discovery") + } + close(release) + scopeWait(t, done) + if calls.Load() != 1 { + t.Fatalf("overlapping discovery calls=%d", calls.Load()) + } +} + +func TestOSRecoverySkipJournalsChangedCandidatePrivately(t *testing.T) { + h := newScopeTestHarness(t) + h.prog.cfg.Upstream["private-token.example"] = &ctrld.UpstreamConfig{Type: ctrld.ResolverTypeLegacy} + h.prog.handleRecovery(RecoveryReasonOSFailure) + h.prog.um.mu.Lock() + h.prog.um.markDown("upstream.0", 1, "test") + h.prog.um.mu.Unlock() + h.prog.handleRecovery(RecoveryReasonOSFailure) + events := jsonLogEvents(t, h.logs, recoverySkipMessage) + if len(events) != 2 { + t.Fatalf("candidate change events=%d", len(events)) + } + wantField(t, events[0], "healthy_upstream", "upstream.0") + wantField(t, events[1], "healthy_upstream", "upstream.custom") + if strings.Contains(h.logs.String(), "private-token.example") { + t.Fatal("operator-provided upstream key leaked") + } +} + +func TestOSRecoverySkipSurvivesDebugTruncation(t *testing.T) { + h := newScopeTestHarness(t) + p, _ := startInternalLogging(t) + h.prog.logger.Store(mainLog.Load()) + useTestSendBudget(t, 1024) + for range 100 { + h.prog.handleRecovery(RecoveryReasonOSFailure) + } + for range 40 { + mainLog.Load().Debug().Msg(strings.Repeat("debug filler", 20)) + } + debugPart, journalPart := splitUpload(t, readLogReader(t, p, false), time.Now()) + if strings.Contains(string(debugPart), recoverySkipMessage) { + t.Fatal("fixture did not truncate the skip from debug") + } + if strings.Count(string(journalPart), recoverySkipMessage) != 1 || !strings.Contains(string(journalPart), `"healthy_upstream":"upstream.0"`) { + t.Fatal("journal did not retain the bounded skip and admission candidate") + } +} diff --git a/docs/network-recovery-diagnostics.md b/docs/network-recovery-diagnostics.md index 240668e..14f8221 100644 --- a/docs/network-recovery-diagnostics.md +++ b/docs/network-recovery-diagnostics.md @@ -24,7 +24,8 @@ The table gives the trigger, the level, and the fields of each event. | `OS resolver set changed` | A nameserver read that differs from the read before | info | `source` (`scutil`, `dhcp`, `resolv.conf`, `unknown`), `before`, `after`, `default_route`, `reason` (`start`, `recovery`, `delayed_recheck`, `wake_probe`, `vpn_settle`, `unspecified`) | | `Reinitialized OS resolver with nameservers: …` | ctrld read the nameservers of the system again and built the OS resolver again | info | none, the nameservers are part of the message | | `DNS configuration changed` | A `scutil --dns` poll that finds a changed resolver, one event per resolver (macOS) | info | `nameservers`, `if_index`, `interface`, `scoped`, `action` (`added`, `changed`, `removed`), `flags`, `search_domain_count`, `order`, `reachable` | -| `Recovery begin` | The start of every recovery | info | `transition_id`, `recovery_generation`, `recovery_reason`, `intercept` | +| `Recovery begin` | The start of every recovery | info | `transition_id`, `recovery_generation`, `recovery_reason`, `intercept`, `probe_upstreams` | +| `Recovery skipped: configured upstream is not marked down` | An OS-only failure does not start global recovery because a configured candidate is not marked down. First/changed candidate, then at most once per 5 minutes for an unchanged candidate | info | `recovery_reason`, `healthy_upstream` | | `Recovery end` | The end of every recovery | info, warn for a canceled recovery and for a recovery with a failure | `transition_id`, `recovery_generation`, `recovery_reason`, `outcome`, `had_failure`, `duration_ms`, `recovered_upstream`, `dhcp_servers`, `dhcp_server_count`, `intercept_target_action`, `bypass_active` | | `Upstream … recovered …` | An upstream that was down answers again | info | `down_for_ms` | | `Recovery canceled with no successor …` | A recovery stops and no other recovery follows it | info | none | @@ -169,6 +170,45 @@ The cancellation event alone does not prove that interface DNS remains removed. Note: On the 1.x (`v1.0`) line, the previous message was `Recovery canceled; DNS settings remain removed`. +### OS-triggered recovery scope + +An OS-only policy failure does not establish that configured DNS is unavailable. +Before starting OS-triggered recovery, ctrld checks its configured non-OS upstreams, excluding generated Internal Domain resolvers. +If any candidate is not marked down, it leaves shared recovery state and DNS settings unchanged. +The skipped trigger still refreshes in-memory OS-resolver discovery, at most once per 10 seconds while OS failures continue. Concurrent triggers do not queue duplicate discovery work. +This read preserves the existing resolver when discovery yields no nameservers. It does not clear the OS failure state; a successful OS query does that. +It does not remove interface DNS, reload interception rules, or enable bypass. A network change is not required for this refresh. +`Recovery skipped: configured upstream is not marked down` enters the journal with `healthy_upstream`, the candidate that admitted the skip. Generated IDs are retained; operator-defined keys are redacted to `upstream.custom`. +An unchanged candidate is journaled at most once per 5 minutes, rather than once per failed query. A changed candidate is journaled immediately when no refresh is in progress. +If all candidates are down, it uses that same pool for recovery probes instead of waiting only for OS DNS. The recovery still refreshes OS discovery initially, but only configured candidates can end it; the OS-only periodic probe/reinitialization loop is not part of that pool. +With no such configured candidates, it retains OS-only recovery. +`Recovery begin` includes `probe_upstreams` so the exit condition is visible in the journal. + +This is a configured pool, not a reconstruction of every listener's effective default route. +Custom configurations can include policy-only or unused upstreams, and an untested upstream is not marked down. +Ordinary upstream-failure and network-change admission and candidate selection are unchanged. +A success racing with admission can still cause brief bypass; probing the configured pool prevents the old OS-only wait from persisting. +The original OS policy remains OS-routed. + +### DNS-target decision failures (macOS) + +`intercept DNS target: decision unavailable; DNS unchanged` retains the first discovery failure and changes to that condition. +Identical consecutive failures are suppressed, even if recovery IDs change. +A later `decision available again` event closes the episode and reports the cumulative `repeat_count`. +Do not add repeat counts from separate events in the same episode. + +These events include the interface/service, discovery stage, bounded error class, target ownership before/after, and correlation IDs captured before discovery. +`failure_recovery_generation` and `failure_transition_id` identify the episode's first failed decision. +Raw error detail remains in the debug stream, not the journal fields. +A stage can be `system_discovery`, `default_route`, `interface_lookup`, `service_lookup`, `static_dns`, or `dhcp_dns`. +An error class can be `unavailable`, `timeout`, `canceled`, `permission_denied`, `command_failed`, or `read_failed`. + +A DHCP error is not an empty DNS result and never authorizes a DNS write. +Resolution means discovery can make a decision again, not that a DNS write or client lookup succeeded. +`action` describes the change in tracked target ownership; it is not independent proof of an OS write. +The target's existing set/remove events still report those operations. +The journal retains these decisions separately from the bounded debug upload. + ## PF probes (macOS) `DNS intercept probe result` includes these fields: diff --git a/nameservers_darwin.go b/nameservers_darwin.go index 92540c1..bb7e337 100644 --- a/nameservers_darwin.go +++ b/nameservers_darwin.go @@ -100,10 +100,7 @@ func getDHCPNameservers(iface string) ([]string, error) { // domain_name_server (ip_mult): {192.168.1.1, 8.8.8.8} output, packetErr := exec.Command("ipconfig", "getpacket", iface).Output() if packetErr != nil { - if err != nil { - return nil, fmt.Errorf("error reading DHCP DNS option: getoption: %v; getpacket: %v", err, packetErr) - } - return nil, fmt.Errorf("error reading DHCP packet: %v", packetErr) + return nil, fmt.Errorf("error reading DHCP DNS option: getoption: %w; getpacket: %w", err, packetErr) } return parseDHCPPacketNameservers(output), nil }