diff --git a/cmd/cli/cli.go b/cmd/cli/cli.go index 8275e5c..5d5e1db 100644 --- a/cmd/cli/cli.go +++ b/cmd/cli/cli.go @@ -348,30 +348,8 @@ func run(appCallback *AppCallback, stopCh chan struct{}) { return } - cdLogger := p.logger.Load().With().Str("mode", "cd") - // Performs self-uninstallation if the ControlD device does not exist. - var uer *controld.ErrorResponse - if errors.As(pf.err, &uer) && uer.ErrorField.Code == controld.InvalidConfigCode { - _ = uninstallInvalidCdUID(p, cdLogger, false) - } - if rejection, ok := permanentAPIRejection(pf.err); ok { - // The API answered and rejected this request permanently. Restarting - // cannot change that answer, so exit cleanly rather than through Fatal: - // an abnormal exit spends one of the service manager's restart actions, - // and on Windows those are what bring enforcement back after a real - // crash. Burning that budget on a config problem also buries the API's - // reason under repeated start failures. - cdLogger.Error().Err(pf.err).Int("status", rejection.StatusCode).Msg("Failed to fetch resolver config; the API rejected this configuration") - notifyExitToLogServer() - return - } - notifyExitToLogServer() - // Everything else - a denied socket, an unreachable API, a proxy in the way, - // an API that is having a bad day - is a condition a later start may not hit, - // so keep the abnormal exit and let the service manager's recovery policy - // retry. That policy backs off (see ConfigureWindowsServiceFailureActions), so - // a short-lived block does not exhaust it. - cdLogger.Fatal().Err(pf.err).Msg("Failed to fetch resolver config") + handleAPIPreflightFailure(p, pf.err, notifyExitToLogServer) + return default: p.mu.Lock() p.rc = pf.rc @@ -381,6 +359,10 @@ func run(appCallback *AppCallback, stopCh chan struct{}) { updated := updateListenerConfig(&cfg, notifyExitToLogServer) + // Bootstrap and listener binding both succeeded, so an earlier run's + // recorded failure no longer describes this install. + clearProvisionResult() + if cdUID != "" { processLogAndCacheFlags(v, &cfg) } @@ -782,6 +764,80 @@ func permanentAPIRejection(err error) (*controld.ErrorResponse, bool) { return uer, true } +// apiFailureCode maps a bootstrap preflight error to its provisioning code. +// A deleted device gets its own code because it triggers self-uninstall; +// other permanent rejections are generic; anything else counts as +// reachability trouble worth retrying. +func apiFailureCode(err error) (provisionFailureCode, bool) { + if err == nil { + return "", false + } + var uer *controld.ErrorResponse + if errors.As(err, &uer) && uer.ErrorField.Code == controld.InvalidConfigCode { + return provisionCodeAPIDeviceInvalid, true + } + if _, ok := permanentAPIRejection(err); ok { + return provisionCodeAPIRejected, true + } + return provisionCodeAPIUnreachable, true +} + +// apiRejectionSummary reports the HTTP status only. The API's raw error body +// can echo back the value the caller sent, so it stays out of the artifact. +func apiRejectionSummary(statusCode int) string { + return fmt.Sprintf("ControlD API rejected this configuration (HTTP status %d)", statusCode) +} + +// 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. +func provisionSecrets() []string { + uid, clientID := controld.ParseRawUID(cdUID) + return []string{cdUID, cdOrg, uid, clientID} +} + +// uninstallInvalidCdUIDFn is a var so tests can observe the self-uninstall +// without driving the OS service manager. +var uninstallInvalidCdUIDFn = uninstallInvalidCdUID + +// handleAPIPreflightFailure reports a failed resolver-config fetch. A deleted +// device self-uninstalls; it and any other permanent rejection return cleanly +// so a config problem cannot burn the service manager's restart budget (on +// Windows those restarts are what bring enforcement back after a real crash). +// Anything else exits nonzero through failProvision so the manager retries. +func handleAPIPreflightFailure(p *prog, err error, notify func()) { + logger := p.logger.Load() + if logger == nil { + logger = mainLog.Load() + } + cdLogger := logger.With().Str("mode", "cd") + code, _ := apiFailureCode(err) + var uer *controld.ErrorResponse + if errors.As(err, &uer) && uer.ErrorField.Code == controld.InvalidConfigCode { + r := newProvisionResult(code, apiRejectionSummary(uer.StatusCode), nil, provisionSecrets()...) + if werr := writeProvisionResult(r); werr != nil { + cdLogger.Warn().Err(werr).Msg("could not persist provision result") + } + _ = uninstallInvalidCdUIDFn(p, cdLogger, false) + cdLogger.Error().Err(err).Int("status", uer.StatusCode).Msg("Failed to fetch resolver config; the device no longer exists") + cdLogger.Error().Msg(r.failureLine()) + notify() + return + } + if rejection, ok := permanentAPIRejection(err); ok { + r := newProvisionResult(code, apiRejectionSummary(rejection.StatusCode), nil, provisionSecrets()...) + if werr := writeProvisionResult(r); werr != nil { + cdLogger.Warn().Err(werr).Msg("could not persist provision result") + } + cdLogger.Error().Err(err).Int("status", rejection.StatusCode).Msg("Failed to fetch resolver config; the API rejected this configuration") + cdLogger.Error().Msg(r.failureLine()) + notify() + return + } + cdLogger.Error().Err(err).Msg("Failed to fetch resolver config") + failProvision(newProvisionResult(code, fmt.Sprintf("failed to fetch resolver config: %v", err), nil, provisionSecrets()...), notify) +} + // processCDFlagsFn is the API fetch, indirected so the lifetime binding around it can be // tested without reaching the network. var processCDFlagsFn = processCDFlags @@ -1462,16 +1518,27 @@ func tryUpdateListenerConfigIntercept(cfg *ctrld.Config, notifyFunc func(), fata } } + // bindAttempts feeds the provisioning result detail. newProvisionResult + // caps it, so it grows freely here. + var bindAttempts []provisionBindAttempt + recordBindAttempt := func(addr, proto string, err error) { + if err != nil { + bindAttempts = append(bindAttempts, provisionBindAttempt{Addr: addr, Proto: proto, OSError: err.Error()}) + } + } + tryListen := func(ip string, port int) bool { addr := net.JoinHostPort(ip, strconv.Itoa(port)) udpLn, udpErr := net.ListenPacket("udp", addr) if udpLn != nil { udpLn.Close() } + recordBindAttempt(addr, "udp", udpErr) tcpLn, tcpErr := net.Listen("tcp", addr) if tcpLn != nil { tcpLn.Close() } + recordBindAttempt(addr, "tcp", tcpErr) return udpErr == nil && tcpErr == nil } @@ -1486,8 +1553,10 @@ func tryUpdateListenerConfigIntercept(cfg *ctrld.Config, notifyFunc func(), fata if hasExplicitConfig { // User specified explicit address — don't guess, just fail if fatal { - notifyFunc() - mainLog.Load().Fatal().Msgf("DNS intercept: cannot listen on configured address %s", addr) + msg := fmt.Sprintf("DNS intercept: cannot listen on configured address %s", addr) + mainLog.Load().Error().Msg(msg) + failProvision(newProvisionResult(provisionCodeListenerAddrUnavail, msg, bindAttempts, provisionSecrets()...), notifyFunc) + return updated, false } return updated, false } @@ -1501,8 +1570,10 @@ func tryUpdateListenerConfigIntercept(cfg *ctrld.Config, notifyFunc func(), fata } if fatal { - notifyFunc() - mainLog.Load().Fatal().Msg("DNS intercept: cannot bind 127.0.0.1:53 or 127.0.0.1:5354") + const msg = "DNS intercept: cannot bind 127.0.0.1:53 or 127.0.0.1:5354" + mainLog.Load().Error().Msg(msg) + failProvision(newProvisionResult(provisionCodeListenerBindFailed, msg, bindAttempts, provisionSecrets()...), notifyFunc) + return updated, false } return updated, false } @@ -1593,6 +1664,15 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, notifyFunc func(), fatal bool) ( _ = closer.Close() } }() + // bindAttempts feeds the provisioning result detail. newProvisionResult + // caps it, so it grows freely here. + var bindAttempts []provisionBindAttempt + recordBindAttempt := func(addr, proto string, err error) { + if err != nil { + bindAttempts = append(bindAttempts, provisionBindAttempt{Addr: addr, Proto: proto, OSError: err.Error()}) + } + } + // tryListen attempts to listen on given udp and tcp address. // Created listeners will be kept in listeners slice above, and close // before function finished. @@ -1601,16 +1681,21 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, notifyFunc func(), fatal bool) ( if udpLn != nil { closers = append(closers, udpLn) } + recordBindAttempt(addr, "udp", udpErr) tcpLn, tcpErr := net.Listen("tcp", addr) if tcpLn != nil { closers = append(closers, tcpLn) } + recordBindAttempt(addr, "tcp", tcpErr) return errors.Join(udpErr, tcpErr) } + listenerMsg := func(listenerNum int, format string, v ...any) string { + return fmt.Sprintf("listener.%d %s", listenerNum, fmt.Sprintf(format, v...)) + } logMsg := func(e *ctrld.LogEvent, listenerNum int, format string, v ...any) { e.MsgFunc(func() string { - return fmt.Sprintf("listener.%d %s", listenerNum, fmt.Sprintf(format, v...)) + return listenerMsg(listenerNum, format, v...) }) } @@ -1653,8 +1738,10 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, notifyFunc func(), fatal bool) ( maxAttempts := 10 for { if attempts == maxAttempts { - notifyFunc() - logMsg(mainLog.Load().Fatal(), n, "could not find available listen ip and port") + logMsg(mainLog.Load().Error(), n, "could not find available listen ip and port") + msg := listenerMsg(n, "could not find available listen ip and port") + failProvision(newProvisionResult(provisionCodeListenerBindFailed, msg, bindAttempts, provisionSecrets()...), notifyFunc) + return updated, false } addr := net.JoinHostPort(listener.IP, strconv.Itoa(listener.Port)) err := tryListen(addr) @@ -1666,8 +1753,10 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, notifyFunc func(), fatal bool) ( if !check.IP && !check.Port { if fatal { - notifyFunc() - logMsg(mainLog.Load().Fatal(), n, "failed to listen: %v", err) + logMsg(mainLog.Load().Error(), n, "failed to listen: %v", err) + msg := listenerMsg(n, "failed to listen: %v", err) + failProvision(newProvisionResult(provisionCodeListenerAddrUnavail, msg, bindAttempts, provisionSecrets()...), notifyFunc) + return updated, false } ok = false break @@ -1719,8 +1808,11 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, notifyFunc func(), fatal bool) ( } if listener.IP == oldIP && listener.Port == oldPort { if fatal { - notifyFunc() - logMsg(mainLog.Load().Fatal(), n, "could not listen on %s: %v", net.JoinHostPort(listener.IP, strconv.Itoa(listener.Port)), err) + triedAddr := net.JoinHostPort(listener.IP, strconv.Itoa(listener.Port)) + logMsg(mainLog.Load().Error(), n, "could not listen on %s: %v", triedAddr, err) + msg := listenerMsg(n, "could not listen on %s: %v", triedAddr, err) + failProvision(newProvisionResult(provisionCodeListenerBindFailed, msg, bindAttempts, provisionSecrets()...), notifyFunc) + return updated, false } ok = false break @@ -1759,8 +1851,10 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, notifyFunc func(), fatal bool) ( } } if !found { - notifyFunc() - logMsg(mainLog.Load().Fatal(), n, "could not use %q as DNS nameserver with systemd resolved", listener.IP) + logMsg(mainLog.Load().Error(), n, "could not use %q as DNS nameserver with systemd resolved", listener.IP) + msg := listenerMsg(n, "could not use %q as DNS nameserver with systemd resolved", listener.IP) + failProvision(newProvisionResult(provisionCodeListenerAddrUnavail, msg, bindAttempts, provisionSecrets()...), notifyFunc) + return updated, false } } } @@ -1810,13 +1904,23 @@ func cdUIDFromProvToken() string { Metadata: ctrld.SystemMetadata(loggerCtx), } // Process provision token if provided. - resolverConfig, err := controld.FetchResolverUID(loggerCtx, req, appVersion, cdDev) + resolverConfig, err := fetchResolverUIDFn(loggerCtx, req, appVersion, cdDev) if err != nil { - mainLog.Load().Fatal().Err(err).Msgf("Failed to fetch resolver uid with provision token: %s", redactToken(cdOrg)) + // The token exchange is the first API call of an org/MDM install, so + // its failure must carry a code like every other bootstrap failure. + code, _ := apiFailureCode(err) + mainLog.Load().Error().Msgf("Failed to fetch resolver uid with provision token: %s: %s", + redactToken(cdOrg), redactSecrets(err.Error(), provisionSecrets()...)) + failProvision(newProvisionResult(code, fmt.Sprintf("provision token exchange failed: %v", err), nil, provisionSecrets()...), nil) + return "" } return resolverConfig.UID } +// fetchResolverUIDFn is a var so tests can drive token-exchange failures +// without reaching the network. +var fetchResolverUIDFn = controld.FetchResolverUID + // removeOrgFlagsFromArgs removes organization flags from command line arguments. // The flags are: // diff --git a/cmd/cli/cli_provision_test.go b/cmd/cli/cli_provision_test.go new file mode 100644 index 0000000..44f90a1 --- /dev/null +++ b/cmd/cli/cli_provision_test.go @@ -0,0 +1,327 @@ +package cli + +import ( + "context" + "fmt" + "net" + "net/http" + "path/filepath" + "runtime" + "strconv" + "strings" + "testing" + + "github.com/Control-D-Inc/ctrld" + "github.com/Control-D-Inc/ctrld/internal/controld" +) + +// TestApiFailureCode covers the preflight-error mapping: a deleted device +// gets its own code (it drives self-uninstall), other permanent rejections +// are generic, anything else is retryable reachability trouble. +func TestApiFailureCode(t *testing.T) { + rejection := func(status, code int) error { + e := &controld.ErrorResponse{StatusCode: status} + e.ErrorField.Code = code + e.ErrorField.Message = "api said no" + return e + } + + tests := []struct { + name string + err error + wantCode provisionFailureCode + wantOk bool + }{ + {name: "nil error", err: nil, wantCode: "", wantOk: false}, + { + name: "deleted device maps to device invalid", + err: rejection(http.StatusNotFound, controld.InvalidConfigCode), + wantCode: provisionCodeAPIDeviceInvalid, + wantOk: true, + }, + { + name: "revoked credentials map to rejected", + err: rejection(http.StatusUnauthorized, 0), + wantCode: provisionCodeAPIRejected, + wantOk: true, + }, + { + name: "server error maps to unreachable", + err: rejection(http.StatusBadGateway, 0), + wantCode: provisionCodeAPIUnreachable, + wantOk: true, + }, + { + name: "network failure maps to unreachable", + err: retryableNetworkErr(), + wantCode: provisionCodeAPIUnreachable, + wantOk: true, + }, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + code, ok := apiFailureCode(tc.err) + if ok != tc.wantOk { + t.Fatalf("apiFailureCode() ok = %v, want %v", ok, tc.wantOk) + } + if code != tc.wantCode { + t.Errorf("apiFailureCode() code = %s, want %s", code, tc.wantCode) + } + }) + } +} + +func stubProvisionGlobals(t *testing.T) (exitCode *int, notified *bool) { + t.Helper() + oldCdUID, oldCdOrg := cdUID, cdOrg + oldExit, oldUninstall := provisionExit, uninstallInvalidCdUIDFn + t.Cleanup(func() { + cdUID, cdOrg = oldCdUID, oldCdOrg + provisionExit, uninstallInvalidCdUIDFn = oldExit, oldUninstall + }) + overrideProvisionResultPath(t) + code := -1 + provisionExit = func(c int) { code = c } + n := false + return &code, &n +} + +func TestHandleAPIPreflightFailure(t *testing.T) { + deviceInvalid := func() error { + e := &controld.ErrorResponse{StatusCode: http.StatusNotFound} + e.ErrorField.Code = controld.InvalidConfigCode + e.ErrorField.Message = "device does not exist" + return e + } + rejected := func() error { + e := &controld.ErrorResponse{StatusCode: http.StatusUnauthorized} + e.ErrorField.Message = "bad token" + return e + } + + t.Run("permanent rejection returns cleanly", func(t *testing.T) { + exitCode, notified := stubProvisionGlobals(t) + handleAPIPreflightFailure(&prog{}, rejected(), func() { *notified = true }) + if *exitCode != -1 { + t.Errorf("provisionExit called with %d, want a clean return", *exitCode) + } + if !*notified { + t.Error("notify not called") + } + r, err := readProvisionResult() + if err != nil { + t.Fatal(err) + } + if r.Code != string(provisionCodeAPIRejected) { + t.Errorf("code = %q, want API_REJECTED", r.Code) + } + }) + + t.Run("deleted device self-uninstalls and returns cleanly", func(t *testing.T) { + exitCode, notified := stubProvisionGlobals(t) + uninstalled := false + uninstallInvalidCdUIDFn = func(_ *prog, _ *ctrld.Logger, _ bool) bool { + uninstalled = true + return true + } + handleAPIPreflightFailure(&prog{}, deviceInvalid(), func() { *notified = true }) + if *exitCode != -1 { + t.Errorf("provisionExit called with %d, want a clean return", *exitCode) + } + if !uninstalled { + t.Error("self-uninstall not attempted") + } + if !*notified { + t.Error("notify not called") + } + r, err := readProvisionResult() + if err != nil { + t.Fatal(err) + } + if r.Code != string(provisionCodeAPIDeviceInvalid) { + t.Errorf("code = %q, want API_DEVICE_INVALID", r.Code) + } + }) + + t.Run("unreachable exits nonzero", func(t *testing.T) { + exitCode, notified := stubProvisionGlobals(t) + handleAPIPreflightFailure(&prog{}, retryableNetworkErr(), func() { *notified = true }) + if *exitCode != provisionExitCodeForCode[provisionCodeAPIUnreachable] { + t.Errorf("exit = %d, want %d", *exitCode, provisionExitCodeForCode[provisionCodeAPIUnreachable]) + } + if !*notified { + t.Error("notify not called") + } + r, err := readProvisionResult() + if err != nil { + t.Fatal(err) + } + if r.Code != string(provisionCodeAPIUnreachable) { + t.Errorf("code = %q, want API_UNREACHABLE", r.Code) + } + }) + + t.Run("bare uid from a composite --cd value is redacted", func(t *testing.T) { + _, _ = stubProvisionGlobals(t) + cdUID = "deviceabc/clientxyz" + cdOrg = "" + err := fmt.Errorf("failed: api says deviceabc is unknown") + handleAPIPreflightFailure(&prog{}, err, func() {}) + r, rerr := readProvisionResult() + if rerr != nil { + t.Fatal(rerr) + } + if strings.Contains(r.Message, "deviceabc") { + t.Errorf("bare uid leaked into message: %q", r.Message) + } + }) +} + +func TestCdUIDFromProvTokenFailureEmitsCode(t *testing.T) { + exitCode, _ := stubProvisionGlobals(t) + oldFetch, oldHostname := fetchResolverUIDFn, customHostname + t.Cleanup(func() { fetchResolverUIDFn, customHostname = oldFetch, oldHostname }) + cdUID = "" + cdOrg = "org-secret-token-123" + customHostname = "" + + rejected := &controld.ErrorResponse{StatusCode: http.StatusUnauthorized} + rejected.ErrorField.Message = "bad provision token org-secret-token-123" + fetchResolverUIDFn = func(context.Context, *controld.UtilityOrgRequest, string, bool) (*controld.ResolverConfig, error) { + return nil, rejected + } + + if got := cdUIDFromProvToken(); got != "" { + t.Errorf("cdUIDFromProvToken() = %q, want empty on failure", got) + } + if *exitCode != provisionExitCodeForCode[provisionCodeAPIRejected] { + t.Errorf("exit = %d, want API_REJECTED exit %d", *exitCode, provisionExitCodeForCode[provisionCodeAPIRejected]) + } + r, err := readProvisionResult() + if err != nil { + t.Fatalf("no provision result written: %v", err) + } + if r.Code != string(provisionCodeAPIRejected) { + t.Errorf("code = %q, want API_REJECTED", r.Code) + } + if strings.Contains(r.Message, cdOrg) { + t.Errorf("token leaked into result message: %q", r.Message) + } +} + +// Regression test: an explicit ip:port that fails to bind used to die with a +// bare fatal log automation could not tell apart from any other crash. It +// must report a stable code through the provisioning result instead. +func TestTryUpdateListenerConfigConfiguredAddrUnavailable(t *testing.T) { + // Occupy one localhost port on both udp and tcp, and hold both for the + // whole test so ctrld's own bind attempt is guaranteed to fail. + udpConn, err := net.ListenPacket("udp", "127.0.0.1:0") + if err != nil { + t.Fatalf("could not reserve a udp port: %v", err) + } + defer udpConn.Close() + + host, portStr, err := net.SplitHostPort(udpConn.LocalAddr().String()) + if err != nil { + t.Fatalf("could not parse reserved address: %v", err) + } + port, err := strconv.Atoi(portStr) + if err != nil { + t.Fatalf("could not parse reserved port: %v", err) + } + + tcpLn, err := net.Listen("tcp", net.JoinHostPort(host, portStr)) + if err != nil { + t.Fatalf("could not reserve the same port on tcp: %v", err) + } + defer tcpLn.Close() + + oldCdUID, oldCdOrg, oldNextdns, oldIntercept := cdUID, cdOrg, nextdns, interceptMode + oldPath, oldExit := provisionResultPath, provisionExit + t.Cleanup(func() { + cdUID, cdOrg, nextdns, interceptMode = oldCdUID, oldCdOrg, oldNextdns, oldIntercept + provisionResultPath, provisionExit = oldPath, oldExit + }) + // Non-cd, non-nextdns mode with an explicit ip:port: no fallback checks, + // the path that used to reach the fatal exit directly. + cdUID = "" + cdOrg = "" + nextdns = "" + interceptMode = "" + + tmpDir := t.TempDir() + provisionResultPath = func() string { return filepath.Join(tmpDir, "provision_result.json") } + + var exitCode int + var exited bool + provisionExit = func(code int) { exitCode = code; exited = true } + + cfg := &ctrld.Config{ + Listener: map[string]*ctrld.ListenerConfig{ + "0": {IP: host, Port: port}, + }, + } + + notified := false + _, ok := tryUpdateListenerConfig(cfg, func() { notified = true }, true) + + if ok { + t.Error("tryUpdateListenerConfig ok = true, want false") + } + if !notified { + t.Error("expected notifyFunc to run before the recorded exit") + } + if !exited { + t.Fatal("expected provisionExit to be called") + } + if exitCode != 42 { + t.Errorf("exit code = %d, want 42 (LISTENER_CONFIGURED_ADDR_UNAVAILABLE)", exitCode) + } + + result, err := readProvisionResult() + if err != nil { + t.Fatalf("could not read provision result: %v", err) + } + if result.Code != string(provisionCodeListenerAddrUnavail) { + t.Errorf("result code = %s, want %s", result.Code, provisionCodeListenerAddrUnavail) + } + if result.Stage != string(provisionStageListener) { + t.Errorf("result stage = %s, want %s", result.Stage, provisionStageListener) + } + if result.ExitCode != 42 { + t.Errorf("result exit code = %d, want 42", result.ExitCode) + } + if result.Detail == nil || len(result.Detail.Attempts) == 0 { + t.Fatal("expected the occupied address to appear as a recorded bind attempt") + } + + occupiedAddr := net.JoinHostPort(host, portStr) + // Windows words WSAEADDRINUSE differently, so only require the canonical + // message on platforms that produce it. + requireInUseText := runtime.GOOS != "windows" + var sawUDP, sawTCP bool + for _, a := range result.Detail.Attempts { + if a.Addr != occupiedAddr || a.OSError == "" { + continue + } + if requireInUseText && !strings.Contains(strings.ToLower(a.OSError), "address already in use") { + continue + } + switch a.Proto { + case "udp": + sawUDP = true + case "tcp": + sawTCP = true + } + } + if !sawUDP { + t.Error("expected a udp attempt on the occupied address with a bind error") + } + if !sawTCP { + t.Error("expected a tcp attempt on the occupied address with a bind error") + } +} + +// The exhaustion path (exit 41) is not covered: forcing every fallback, +// including a freshly randomized ip/port, to fail has no deterministic seam, +// so a test would race whatever ports are free on the host. diff --git a/cmd/cli/commands_service_start.go b/cmd/cli/commands_service_start.go index 436cc6f..d4f9588 100644 --- a/cmd/cli/commands_service_start.go +++ b/cmd/cli/commands_service_start.go @@ -18,6 +18,46 @@ import ( "github.com/Control-D-Inc/ctrld" ) +// serviceStageFailureCode maps an aborted service-manager task to its +// provisioning code. Other abortOnError tasks (like config validation) keep +// their own error paths. +func serviceStageFailureCode(taskName string) (provisionFailureCode, bool) { + switch taskName { + case "Install": + return provisionCodeServiceInstall, true + case "Start": + return provisionCodeServiceStartFailed, true + default: + return "", false + } +} + +// serviceTaskErrorSummary describes which service-manager task failed and why, +// for use as a provisioning result message. +func serviceTaskErrorSummary(taskName string, err error) string { + return fmt.Sprintf("%s failed: %v", taskName, err) +} + +// resultStalenessTolerance absorbs clock granularity between "ctrld start" +// recording its start time and the daemon writing its result file. +const resultStalenessTolerance = 2 * time.Second + +// reportStartFailure reports why "ctrld start" failed after install/start +// looked fine. A result file the daemon wrote during this attempt names the +// failure better than a generic self-check code, so it wins. +func reportStartFailure(startedAt time.Time, fallbackMsg string) { + if r, err := readProvisionResult(); err == nil && provisionResultTrusted(r) { + if ts, err := time.Parse(time.RFC3339, r.Timestamp); err == nil { + if !ts.Before(startedAt.Add(-resultStalenessTolerance)) { + mainLog.Load().Error().Msg(r.failureLine()) + provisionExit(r.ExitCode) + return + } + } + } + failProvision(newProvisionResult(provisionCodeServiceSelfCheck, fallbackMsg, nil, provisionSecrets()...), nil) +} + // Start implements the logic from cmdStart.Run func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error { logger := mainLog.Load() @@ -236,23 +276,50 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error { {s.Start, true, "Start"}, {noticeWritingControlDConfig, false, "Notice writing ControlD config"}, } + // Any result found later must come from this attempt, not a stale run. + clearProvisionResult() + startAttemptAt := time.Now() logger.Notice().Msg("Starting existing ctrld service") - if doTasks(tasks) { - logger.Notice().Msg("Service started") - sockDir, err := socketDir() - if err != nil { - logger.Warn().Err(err).Msg("Failed to get socket directory") - os.Exit(1) + failedTask, taskErr := doTasksE(tasks) + if taskErr != nil { + if code, ok := serviceStageFailureCode(failedTask); ok { + failProvision(newProvisionResult(code, serviceTaskErrorSummary(failedTask, taskErr), nil, provisionSecrets()...), nil) + return nil } - reportSetDnsOk(sockDir) - // Verify service registration after successful start. - if err := verifyServiceRegistration(); err != nil { - logger.Warn().Err(err).Msg("Service registry verification failed") - } - } else { - logger.Error().Err(err).Msg("Failed to start existing ctrld service") os.Exit(1) } + sockDir, err := socketDir() + if err != nil { + logger.Warn().Err(err).Msg("Failed to get socket directory") + os.Exit(1) + } + + // The daemon can start and still fail provisioning (for example a + // listener bind conflict). Self-check like a fresh install so this + // path reports the daemon's failure code instead of a false + // "Service started" — but never uninstall an existing service. + time.Sleep(1 * time.Second) + ok, status, err := selfCheckStatus(ctx, s, sockDir) + if !ok || status != service.StatusRunning { + fallbackMsg := "ctrld service did not pass its post-start self-check" + if err != nil { + fallbackMsg = fmt.Sprintf("An error occurred while performing test query: %s", err) + logger.Error().Msg(fallbackMsg) + } + if status == service.StatusRunning && err == nil { + fallbackMsg = "ctrld service was running, but a DNS query could not be sent to its listener; check firewall rules blocking/intercepting/redirecting DNS queries" + logger.Error().Msg(fallbackMsg) + } + reportStartFailure(startAttemptAt, fallbackMsg) + return nil + } + logger.Notice().Msg("Service started") + clearProvisionResult() + reportSetDnsOk(sockDir) + // Verify service registration after successful start. + if err := verifyServiceRegistration(); err != nil { + logger.Warn().Err(err).Msg("Service registry verification failed") + } return nil } @@ -307,7 +374,7 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error { }) return nil }, false, "Save current DNS"}, - {s.Install, false, "Install"}, + {s.Install, true, "Install"}, {func() error { return ConfigureWindowsServiceFailureActions(ctrldServiceName) }, false, "Configure Windows service failure actions"}, @@ -316,65 +383,83 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error { // generated after s.Start, so we notice users here for consistent with nextdns mode. {noticeWritingControlDConfig, false, "Notice writing ControlD config"}, } + // Any result found later must come from this attempt, not a stale run. + clearProvisionResult() + startAttemptAt := time.Now() logger.Notice().Msg("Starting service") - if doTasks(tasks) { - // add a small delay to ensure the service is started and did not crash - time.Sleep(1 * time.Second) + failedTask, taskErr := doTasksE(tasks) + if taskErr != nil { + if code, ok := serviceStageFailureCode(failedTask); ok { + failProvision(newProvisionResult(code, serviceTaskErrorSummary(failedTask, taskErr), nil, provisionSecrets()...), nil) + return nil + } + // Not a service-stage task. doTasksE already logged the cause; exit + // non-zero instead of the old silent fall-through that exited 0. + os.Exit(1) + return nil + } - ok, status, err := selfCheckStatus(ctx, s, sockDir) - switch { - case ok && status == service.StatusRunning: - logger.Notice().Msg("Service started") - default: - marker := append(bytes.Repeat([]byte("="), 32), '\n') - // If ctrld service is not running, emitting log obtained from ctrld process. - if status != service.StatusRunning || ctx.Err() != nil { - logger.Error().Msg("Ctrld service may not have started due to an error or misconfiguration, service log:") - _, _ = logger.Write(marker) - - // Wait for log collection to complete - <-stopLogCh - - // Retrieve logs from HTTP server if available - if logServerSocketPath != "" { - hlc := newHTTPLogClient(logServerSocketPath) - logs, err := hlc.GetLogs() - if err != nil { - logger.Warn().Err(err).Msg("Failed to get logs from HTTP log server") - } - if len(logs) == 0 { - logger.Write([]byte("\n")) - } else { - logger.Write(logs) - logger.Write([]byte("\n")) - } - } else { - logger.Write([]byte("\n")) - } - } - // Report any error if occurred. - if err != nil { - _, _ = logger.Write(marker) - msg := fmt.Sprintf("An error occurred while performing test query: %s\n", err) - logger.Write([]byte(msg)) - } - // If ctrld service is running but selfCheckStatus failed, it could be related - // to user's system firewall configuration, notice users about it. - if status == service.StatusRunning && err == nil { - _, _ = logger.Write(marker) - logger.Write([]byte("ctrld service was running, but a DNS query could not be sent to its listener\n")) - logger.Write([]byte("Please check your system firewall if it is configured to block/intercept/redirect DNS queries\n")) - } + // add a small delay to ensure the service is started and did not crash + time.Sleep(1 * time.Second) + ok, status, err := selfCheckStatus(ctx, s, sockDir) + switch { + case ok && status == service.StatusRunning: + logger.Notice().Msg("Service started") + clearProvisionResult() + default: + marker := append(bytes.Repeat([]byte("="), 32), '\n') + fallbackMsg := "ctrld service did not pass its post-start self-check" + // If ctrld service is not running, emitting log obtained from ctrld process. + if status != service.StatusRunning || ctx.Err() != nil { + logger.Error().Msg("Ctrld service may not have started due to an error or misconfiguration, service log:") _, _ = logger.Write(marker) - uninstall(p, s) - os.Exit(1) + + // Wait for log collection to complete + <-stopLogCh + + // Retrieve logs from HTTP server if available + if logServerSocketPath != "" { + hlc := newHTTPLogClient(logServerSocketPath) + logs, err := hlc.GetLogs() + if err != nil { + logger.Warn().Err(err).Msg("Failed to get logs from HTTP log server") + } + if len(logs) == 0 { + logger.Write([]byte("\n")) + } else { + logger.Write(logs) + logger.Write([]byte("\n")) + } + } else { + logger.Write([]byte("\n")) + } } - reportSetDnsOk(sockDir) - // Verify service registration after successful start. - if err := verifyServiceRegistration(); err != nil { - logger.Warn().Err(err).Msg("Service registry verification failed") + // Report any error if occurred. + if err != nil { + _, _ = logger.Write(marker) + msg := fmt.Sprintf("An error occurred while performing test query: %s\n", err) + logger.Write([]byte(msg)) + fallbackMsg = msg } + // If ctrld service is running but selfCheckStatus failed, it could be related + // to user's system firewall configuration, notice users about it. + if status == service.StatusRunning && err == nil { + _, _ = logger.Write(marker) + logger.Write([]byte("ctrld service was running, but a DNS query could not be sent to its listener\n")) + logger.Write([]byte("Please check your system firewall if it is configured to block/intercept/redirect DNS queries\n")) + fallbackMsg = "ctrld service was running, but a DNS query could not be sent to its listener; check firewall rules blocking/intercepting/redirecting DNS queries" + } + + _, _ = logger.Write(marker) + uninstall(p, s) + reportStartFailure(startAttemptAt, fallbackMsg) + return nil + } + reportSetDnsOk(sockDir) + // Verify service registration after successful start. + if err := verifyServiceRegistration(); err != nil { + logger.Warn().Err(err).Msg("Service registry verification failed") } logger.Debug().Msg("Service start command completed") diff --git a/cmd/cli/commands_start_test.go b/cmd/cli/commands_start_test.go new file mode 100644 index 0000000..882fac2 --- /dev/null +++ b/cmd/cli/commands_start_test.go @@ -0,0 +1,122 @@ +package cli + +import ( + "testing" + "time" +) + +func TestServiceStageFailureCode(t *testing.T) { + tests := []struct { + taskName string + wantCode provisionFailureCode + wantOK bool + }{ + {"Install", provisionCodeServiceInstall, true}, + {"Start", provisionCodeServiceStartFailed, true}, + {"Checking config", "", false}, + {"", "", false}, + } + for _, tc := range tests { + code, ok := serviceStageFailureCode(tc.taskName) + if code != tc.wantCode || ok != tc.wantOK { + t.Errorf("serviceStageFailureCode(%q) = (%q, %v), want (%q, %v)", tc.taskName, code, ok, tc.wantCode, tc.wantOK) + } + } +} + +func stubProvisionExit(t *testing.T) *int { + t.Helper() + exitCode := -1 + old := provisionExit + provisionExit = func(code int) { exitCode = code } + t.Cleanup(func() { provisionExit = old }) + return &exitCode +} + +func TestReportStartFailureUsesFreshDaemonResult(t *testing.T) { + overrideProvisionResultPath(t) + exitCode := stubProvisionExit(t) + + startedAt := time.Now() + daemonResult := newProvisionResult(provisionCodeAPIUnreachable, "daemon could not reach the API", nil) + if err := writeProvisionResult(daemonResult); err != nil { + t.Fatal(err) + } + + reportStartFailure(startedAt, "generic self-check failure") + + if *exitCode != provisionExitCodeForCode[provisionCodeAPIUnreachable] { + t.Errorf("exit code = %d, want the daemon's own exit code %d", *exitCode, provisionExitCodeForCode[provisionCodeAPIUnreachable]) + } + out, err := readProvisionResult() + if err != nil { + t.Fatal(err) + } + if out.Code != string(provisionCodeAPIUnreachable) { + t.Errorf("persisted code = %q, want the daemon's own code untouched", out.Code) + } +} + +func TestReportStartFailureFallsBackOnStaleDaemonResult(t *testing.T) { + overrideProvisionResultPath(t) + exitCode := stubProvisionExit(t) + + stale := newProvisionResult(provisionCodeAPIUnreachable, "an old failure", nil) + stale.Timestamp = time.Now().Add(-1 * time.Hour).UTC().Format(time.RFC3339) + if err := writeProvisionResult(stale); err != nil { + t.Fatal(err) + } + + startedAt := time.Now() + reportStartFailure(startedAt, "test query failed: timeout") + + if *exitCode != provisionExitCodeForCode[provisionCodeServiceSelfCheck] { + t.Errorf("exit code = %d, want SERVICE_SELFCHECK_FAILED exit %d", *exitCode, provisionExitCodeForCode[provisionCodeServiceSelfCheck]) + } + out, err := readProvisionResult() + if err != nil { + t.Fatal(err) + } + if out.Code != string(provisionCodeServiceSelfCheck) { + t.Errorf("persisted code = %q, want %q", out.Code, provisionCodeServiceSelfCheck) + } + if out.Message != "test query failed: timeout" { + t.Errorf("persisted message = %q, want the fallback message", out.Message) + } +} + +func TestReportStartFailureRejectsUntrustedFile(t *testing.T) { + overrideProvisionResultPath(t) + exitCode := stubProvisionExit(t) + + planted := newProvisionResult(provisionCodeAPIUnreachable, "planted", nil) + planted.Code = "FAKE_CODE" + planted.ExitCode = 99 + if err := writeProvisionResult(planted); err != nil { + t.Fatal(err) + } + + reportStartFailure(time.Now().Add(-time.Minute), "self-check failed") + + if *exitCode != provisionExitCodeForCode[provisionCodeServiceSelfCheck] { + t.Errorf("exit = %d, want the fallback %d, never the planted 99", *exitCode, provisionExitCodeForCode[provisionCodeServiceSelfCheck]) + } +} + +func TestReportStartFailureFallsBackWhenResultFileMissing(t *testing.T) { + overrideProvisionResultPath(t) + exitCode := stubProvisionExit(t) + + reportStartFailure(time.Now(), "firewall hint") + + if *exitCode != provisionExitCodeForCode[provisionCodeServiceSelfCheck] { + t.Errorf("exit code = %d, want SERVICE_SELFCHECK_FAILED exit %d", *exitCode, provisionExitCodeForCode[provisionCodeServiceSelfCheck]) + } + out, err := readProvisionResult() + if err != nil { + t.Fatal(err) + } + if out.Message != "firewall hint" { + t.Errorf("persisted message = %q, want the fallback message", out.Message) + } +} diff --git a/cmd/cli/dns_intercept_darwin.go b/cmd/cli/dns_intercept_darwin.go index 96634c9..d60bc32 100644 --- a/cmd/cli/dns_intercept_darwin.go +++ b/cmd/cli/dns_intercept_darwin.go @@ -1654,12 +1654,17 @@ func isResourceExhaustion(err error, output []byte) bool { } func (p *prog) scheduleDNSAfterVPNSettleRefresh(reason string, delay time.Duration) { - time.AfterFunc(delay, func() { + timer := time.AfterFunc(delay, func() { if p.dnsInterceptState == nil { return } p.refreshDNSAfterVPNSettle(reason) }) + // Track the timer like the other delayed rechecks, so intercept teardown + // (and test cleanup) can stop it instead of letting it fire afterwards. + p.pfDelayedRecheckMu.Lock() + p.pfDelayedRecheckTimers = append(p.pfDelayedRecheckTimers, timer) + p.pfDelayedRecheckMu.Unlock() } // pfWatchdog periodically checks that our pf anchor is still active. diff --git a/cmd/cli/provision_result.go b/cmd/cli/provision_result.go new file mode 100644 index 0000000..93a0587 --- /dev/null +++ b/cmd/cli/provision_result.go @@ -0,0 +1,249 @@ +package cli + +import ( + "encoding/json" + "fmt" + "os" + "path/filepath" + "strings" + "time" + "unicode/utf8" + + "github.com/Control-D-Inc/ctrld" +) + +// A terminal provisioning failure reports the same stable code on three +// surfaces: a persisted result file, one fixed-format output line, and a +// stage-scoped process exit code. docs/provisioning-failure-codes.md maps +// each code to its scenario and must stay in sync with the constants below. +// Codes are append-only once released; renaming or reusing one breaks the +// support contract. + +type provisionStage string + +const ( + provisionStageBootstrap provisionStage = "bootstrap" + provisionStageListener provisionStage = "listener" + provisionStageService provisionStage = "service" +) + +type provisionFailureCode string + +const ( + provisionCodeAPIUnreachable provisionFailureCode = "API_UNREACHABLE" + provisionCodeAPIRejected provisionFailureCode = "API_REJECTED" + provisionCodeAPIDeviceInvalid provisionFailureCode = "API_DEVICE_INVALID" + provisionCodeListenerBindFailed provisionFailureCode = "LISTENER_BIND_FAILED" + provisionCodeListenerAddrUnavail provisionFailureCode = "LISTENER_CONFIGURED_ADDR_UNAVAILABLE" + provisionCodeServiceInstall provisionFailureCode = "SERVICE_INSTALL_FAILED" + provisionCodeServiceStartFailed provisionFailureCode = "SERVICE_START_FAILED" + provisionCodeServiceSelfCheck provisionFailureCode = "SERVICE_SELFCHECK_FAILED" +) + +var allProvisionFailureCodes = []provisionFailureCode{ + provisionCodeAPIUnreachable, + provisionCodeAPIRejected, + provisionCodeAPIDeviceInvalid, + provisionCodeListenerBindFailed, + provisionCodeListenerAddrUnavail, + provisionCodeServiceInstall, + provisionCodeServiceStartFailed, + provisionCodeServiceSelfCheck, +} + +var provisionStageForCode = map[provisionFailureCode]provisionStage{ + provisionCodeAPIUnreachable: provisionStageBootstrap, + provisionCodeAPIRejected: provisionStageBootstrap, + provisionCodeAPIDeviceInvalid: provisionStageBootstrap, + provisionCodeListenerBindFailed: provisionStageListener, + provisionCodeListenerAddrUnavail: provisionStageListener, + provisionCodeServiceInstall: provisionStageService, + provisionCodeServiceStartFailed: provisionStageService, + provisionCodeServiceSelfCheck: provisionStageService, +} + +// Exit codes are grouped by stage (bootstrap 30-39, listener 40-49, service +// 50-59) so the exit code alone names the failed stage. 0-3 belong to +// "ctrld status" and 126 to the deactivation pin check; never reuse those. +var provisionExitCodeForCode = map[provisionFailureCode]int{ + provisionCodeAPIUnreachable: 30, + provisionCodeAPIRejected: 31, + provisionCodeAPIDeviceInvalid: 32, + provisionCodeListenerBindFailed: 41, + provisionCodeListenerAddrUnavail: 42, + provisionCodeServiceInstall: 51, + provisionCodeServiceStartFailed: 52, + provisionCodeServiceSelfCheck: 53, +} + +const ( + provisionResultFileName = "provision_result.json" + // Detail identifies a failure, it is not a log. Caps keep the artifact + // small and predictable. + maxProvisionBindAttempts = 12 + maxProvisionStringLen = 256 +) + +type provisionBindAttempt struct { + Addr string `json:"addr"` + Proto string `json:"proto"` + OSError string `json:"os_error"` +} + +type provisionDetail struct { + Attempts []provisionBindAttempt `json:"attempts,omitempty"` +} + +type provisionResult struct { + Version int `json:"version"` + Timestamp string `json:"timestamp"` + Stage string `json:"stage"` + Code string `json:"code"` + ExitCode int `json:"exit_code"` + Message string `json:"message"` + Detail *provisionDetail `json:"detail,omitempty"` +} + +// provisionResultPath is a var so tests can point it at a temp dir. +var provisionResultPath = func() string { + return ctrld.AbsHomeDir(provisionResultFileName) +} + +// provisionExit is a var so tests can observe the exit code instead of dying. +var provisionExit = os.Exit + +// newProvisionResult builds a result with every field bounded and the given +// secrets stripped. The artifact reaches installer logs and support tickets, +// so callers pass every secret in scope (provision token, cd UID). +func newProvisionResult(code provisionFailureCode, message string, attempts []provisionBindAttempt, secrets ...string) *provisionResult { + sanitize := func(s string) string { + s = redactSecrets(s, secrets...) + if len(s) > maxProvisionStringLen { + // Cut on a rune boundary so a localized OS error does not end in + // a broken multi-byte sequence. + cut := maxProvisionStringLen + for cut > 0 && !utf8.RuneStart(s[cut]) { + cut-- + } + s = s[:cut] + } + return s + } + r := &provisionResult{ + Version: 1, + Timestamp: time.Now().UTC().Format(time.RFC3339), + Stage: string(provisionStageForCode[code]), + Code: string(code), + ExitCode: provisionExitCodeForCode[code], + Message: sanitize(message), + } + if len(attempts) > 0 { + if len(attempts) > maxProvisionBindAttempts { + attempts = attempts[:maxProvisionBindAttempts] + } + detail := &provisionDetail{Attempts: make([]provisionBindAttempt, 0, len(attempts))} + for _, a := range attempts { + detail.Attempts = append(detail.Attempts, provisionBindAttempt{ + Addr: sanitize(a.Addr), + Proto: sanitize(a.Proto), + OSError: sanitize(a.OSError), + }) + } + r.Detail = detail + } + return r +} + +// redactSecrets removes every non-empty secret from s. +func redactSecrets(s string, secrets ...string) string { + for _, secret := range secrets { + if secret == "" { + continue + } + s = strings.ReplaceAll(s, secret, "[redacted]") + } + return s +} + +// provisionResultTrusted rejects a result whose code, stage, or exit code is +// not part of the known contract, so a corrupt or planted file cannot drive +// what "ctrld start" logs and exits with. +func provisionResultTrusted(r *provisionResult) bool { + code := provisionFailureCode(r.Code) + stage, ok := provisionStageForCode[code] + if !ok { + return false + } + return r.Stage == string(stage) && r.ExitCode == provisionExitCodeForCode[code] +} + +func (r *provisionResult) failureLine() string { + return fmt.Sprintf("provisioning failed: stage=%s code=%s (exit %d)", r.Stage, r.Code, r.ExitCode) +} + +// writeProvisionResult persists the result atomically (temp file + rename in +// the same directory) so a reader never sees a partial file. +func writeProvisionResult(r *provisionResult) error { + path := provisionResultPath() + buf, err := json.MarshalIndent(r, "", " ") + if err != nil { + return err + } + tmp, err := os.CreateTemp(filepath.Dir(path), provisionResultFileName+".tmp*") + if err != nil { + return err + } + tmpName := tmp.Name() + if _, err := tmp.Write(buf); err != nil { + _ = tmp.Close() + _ = os.Remove(tmpName) + return err + } + if err := tmp.Close(); err != nil { + _ = os.Remove(tmpName) + return err + } + if err := os.Chmod(tmpName, 0o600); err != nil { + _ = os.Remove(tmpName) + return err + } + if err := os.Rename(tmpName, path); err != nil { + _ = os.Remove(tmpName) + return err + } + return nil +} + +func readProvisionResult() (*provisionResult, error) { + buf, err := os.ReadFile(provisionResultPath()) + if err != nil { + return nil, err + } + r := &provisionResult{} + if err := json.Unmarshal(buf, r); err != nil { + return nil, err + } + return r, nil +} + +// clearProvisionResult removes a stale result once provisioning succeeds, so +// support never diagnoses a healthy install from an old failure. +func clearProvisionResult() { + if err := os.Remove(provisionResultPath()); err != nil && !os.IsNotExist(err) { + mainLog.Load().Debug().Err(err).Msg("could not remove provision result file") + } +} + +// failProvision persists the result, prints the identifier line, unblocks a +// waiting "ctrld start" via notify, then exits with the stage code. The write +// comes first so the file survives even if logging or notify misbehaves. +func failProvision(r *provisionResult, notify func()) { + if err := writeProvisionResult(r); err != nil { + mainLog.Load().Warn().Err(err).Msg("could not persist provision result") + } + mainLog.Load().Error().Msg(r.failureLine()) + if notify != nil { + notify() + } + provisionExit(r.ExitCode) +} diff --git a/cmd/cli/provision_result_test.go b/cmd/cli/provision_result_test.go new file mode 100644 index 0000000..3003904 --- /dev/null +++ b/cmd/cli/provision_result_test.go @@ -0,0 +1,278 @@ +package cli + +import ( + "encoding/json" + "os" + "path/filepath" + "strconv" + "strings" + "testing" + "time" + "unicode/utf8" +) + +func overrideProvisionResultPath(t *testing.T) string { + t.Helper() + path := filepath.Join(t.TempDir(), provisionResultFileName) + old := provisionResultPath + provisionResultPath = func() string { return path } + t.Cleanup(func() { provisionResultPath = old }) + return path +} + +func TestProvisionCodesMapToOneStageAndInRangeExit(t *testing.T) { + stageRanges := map[provisionStage][2]int{ + provisionStageBootstrap: {30, 39}, + provisionStageListener: {40, 49}, + provisionStageService: {50, 59}, + } + reservedExits := map[int]string{ + statusExitRunning: "ctrld status running", + statusExitStopped: "ctrld status stopped", + statusExitUnknown: "ctrld status unknown", + statusExitNotReady: "ctrld status not ready", + deactivationPinInvalidExitCode: "deactivation pin invalid", + } + seenExits := make(map[int]provisionFailureCode) + for _, code := range allProvisionFailureCodes { + stage, ok := provisionStageForCode[code] + if !ok { + t.Fatalf("code %s has no stage", code) + } + exit, ok := provisionExitCodeForCode[code] + if !ok { + t.Fatalf("code %s has no exit code", code) + } + r := stageRanges[stage] + if exit < r[0] || exit > r[1] { + t.Errorf("code %s exit %d outside stage %s range %v", code, exit, stage, r) + } + if owner, ok := reservedExits[exit]; ok { + t.Errorf("code %s exit %d collides with %s", code, exit, owner) + } + if prev, dup := seenExits[exit]; dup { + t.Errorf("codes %s and %s share exit %d", prev, code, exit) + } + seenExits[exit] = code + } + if len(allProvisionFailureCodes) != 8 { + t.Errorf("expected 8 codes, got %d", len(allProvisionFailureCodes)) + } +} + +func TestNewProvisionResultRedactsSecrets(t *testing.T) { + token := "org-secret-token-12345" + cdUIDValue := "abcdef123456" + attempts := []provisionBindAttempt{ + {Addr: "127.0.0.1:53", Proto: "udp", OSError: "bind failed for " + token}, + } + r := newProvisionResult( + provisionCodeListenerBindFailed, + "could not bind, token="+token+" uid="+cdUIDValue, + attempts, + token, cdUIDValue, + ) + raw, err := json.Marshal(r) + if err != nil { + t.Fatal(err) + } + for _, secret := range []string{token, cdUIDValue} { + if strings.Contains(string(raw), secret) { + t.Errorf("serialized result contains secret %q: %s", secret, raw) + } + } +} + +func TestNewProvisionResultBoundsDetail(t *testing.T) { + long := strings.Repeat("x", 1000) + var attempts []provisionBindAttempt + for i := 0; i < 50; i++ { + attempts = append(attempts, provisionBindAttempt{Addr: long, Proto: "udp", OSError: long}) + } + r := newProvisionResult(provisionCodeListenerBindFailed, long, attempts) + if got := len(r.Detail.Attempts); got > maxProvisionBindAttempts { + t.Errorf("attempts not capped: %d > %d", got, maxProvisionBindAttempts) + } + if len(r.Message) > maxProvisionStringLen { + t.Errorf("message not capped: %d", len(r.Message)) + } + for _, a := range r.Detail.Attempts { + if len(a.Addr) > maxProvisionStringLen || len(a.OSError) > maxProvisionStringLen { + t.Error("attempt fields not capped") + } + } +} + +func TestProvisionResultFields(t *testing.T) { + r := newProvisionResult(provisionCodeAPIRejected, "the API rejected this configuration", nil) + if r.Version != 1 { + t.Errorf("version = %d, want 1", r.Version) + } + if r.Stage != string(provisionStageBootstrap) { + t.Errorf("stage = %q, want bootstrap", r.Stage) + } + if r.ExitCode != provisionExitCodeForCode[provisionCodeAPIRejected] { + t.Errorf("exit = %d", r.ExitCode) + } + if _, err := time.Parse(time.RFC3339, r.Timestamp); err != nil { + t.Errorf("timestamp %q not RFC3339: %v", r.Timestamp, err) + } + if r.Detail != nil { + t.Error("nil attempts should give nil detail") + } +} + +func TestProvisionResultTrusted(t *testing.T) { + good := newProvisionResult(provisionCodeListenerBindFailed, "x", nil) + if !provisionResultTrusted(good) { + t.Error("constructor-built result must be trusted") + } + bogusCode := newProvisionResult(provisionCodeListenerBindFailed, "x", nil) + bogusCode.Code = "TOTALLY_MADE_UP" + if provisionResultTrusted(bogusCode) { + t.Error("unknown code must not be trusted") + } + wrongExit := newProvisionResult(provisionCodeListenerBindFailed, "x", nil) + wrongExit.ExitCode = 126 + if provisionResultTrusted(wrongExit) { + t.Error("exit code not matching the contract must not be trusted") + } + wrongStage := newProvisionResult(provisionCodeListenerBindFailed, "x", nil) + wrongStage.Stage = string(provisionStageService) + if provisionResultTrusted(wrongStage) { + t.Error("stage not matching the code must not be trusted") + } +} + +func TestNewProvisionResultTruncatesOnRuneBoundary(t *testing.T) { + msg := strings.Repeat("é", maxProvisionStringLen) // 2 bytes per rune + r := newProvisionResult(provisionCodeListenerBindFailed, msg, nil) + if len(r.Message) > maxProvisionStringLen { + t.Errorf("message not capped: %d bytes", len(r.Message)) + } + if !utf8.ValidString(r.Message) { + t.Error("truncation split a multi-byte rune") + } +} + +func TestFailureCodeDocTableMatchesConstants(t *testing.T) { + buf, err := os.ReadFile(filepath.Join("..", "..", "docs", "provisioning-failure-codes.md")) + if os.IsNotExist(err) { + // The Windows CI runner executes prebuilt test binaries outside the + // repo; the sync guarantee is still enforced on runners with a checkout. + t.Skip("failure-code doc not available in this test environment") + } + if err != nil { + t.Fatalf("could not read the failure-code doc: %v", err) + } + doc := string(buf) + rows := 0 + for _, line := range strings.Split(doc, "\n") { + if strings.HasPrefix(line, "| `") { + rows++ + } + } + if rows != len(allProvisionFailureCodes) { + t.Errorf("doc table has %d code rows, want %d", rows, len(allProvisionFailureCodes)) + } + for _, code := range allProvisionFailureCodes { + row := "| `" + string(code) + "` | " + string(provisionStageForCode[code]) + " | " + strconv.Itoa(provisionExitCodeForCode[code]) + " |" + if !strings.Contains(doc, row) { + t.Errorf("doc table missing row for %s (want prefix %q)", code, row) + } + } +} + +func TestProvisionFailureLineFormat(t *testing.T) { + r := newProvisionResult(provisionCodeListenerBindFailed, "could not find available listen ip and port", nil) + want := "provisioning failed: stage=listener code=LISTENER_BIND_FAILED (exit 41)" + if got := r.failureLine(); got != want { + t.Errorf("failureLine() = %q, want %q", got, want) + } +} + +func TestProvisionResultRoundTrip(t *testing.T) { + overrideProvisionResultPath(t) + in := newProvisionResult(provisionCodeServiceStartFailed, "service failed to start", nil) + if err := writeProvisionResult(in); err != nil { + t.Fatal(err) + } + out, err := readProvisionResult() + if err != nil { + t.Fatal(err) + } + if out.Code != in.Code || out.Stage != in.Stage || out.ExitCode != in.ExitCode || out.Message != in.Message { + t.Errorf("round trip mismatch: in=%+v out=%+v", in, out) + } +} + +func TestWriteProvisionResultOverwritesAtomically(t *testing.T) { + path := overrideProvisionResultPath(t) + first := newProvisionResult(provisionCodeAPIUnreachable, "first", nil) + if err := writeProvisionResult(first); err != nil { + t.Fatal(err) + } + second := newProvisionResult(provisionCodeListenerBindFailed, "second", nil) + if err := writeProvisionResult(second); err != nil { + t.Fatal(err) + } + out, err := readProvisionResult() + if err != nil { + t.Fatal(err) + } + if out.Code != string(provisionCodeListenerBindFailed) || out.Message != "second" { + t.Errorf("overwrite failed: %+v", out) + } + entries, err := os.ReadDir(filepath.Dir(path)) + if err != nil { + t.Fatal(err) + } + if len(entries) != 1 { + t.Errorf("temp files left behind: %v", entries) + } +} + +func TestClearProvisionResult(t *testing.T) { + path := overrideProvisionResultPath(t) + clearProvisionResult() // missing file must not panic or error loudly + if err := writeProvisionResult(newProvisionResult(provisionCodeAPIUnreachable, "x", nil)); err != nil { + t.Fatal(err) + } + clearProvisionResult() + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Errorf("result file still present after clear: %v", err) + } +} + +func TestReadProvisionResultMissing(t *testing.T) { + overrideProvisionResultPath(t) + if _, err := readProvisionResult(); err == nil { + t.Error("expected error reading missing result file") + } +} + +func TestFailProvisionWritesLogsNotifiesAndExits(t *testing.T) { + overrideProvisionResultPath(t) + exitCode := -1 + oldExit := provisionExit + provisionExit = func(code int) { exitCode = code } + t.Cleanup(func() { provisionExit = oldExit }) + + notified := false + r := newProvisionResult(provisionCodeListenerBindFailed, "no listen addr", nil) + failProvision(r, func() { notified = true }) + + if !notified { + t.Error("notify func not called") + } + if exitCode != provisionExitCodeForCode[provisionCodeListenerBindFailed] { + t.Errorf("exit code = %d", exitCode) + } + out, err := readProvisionResult() + if err != nil { + t.Fatalf("result not persisted: %v", err) + } + if out.Code != string(provisionCodeListenerBindFailed) { + t.Errorf("persisted code = %q", out.Code) + } +} diff --git a/cmd/cli/service.go b/cmd/cli/service.go index 7046353..63ac5f4 100644 --- a/cmd/cli/service.go +++ b/cmd/cli/service.go @@ -179,23 +179,31 @@ type task struct { Name string } -// doTasks executes a list of tasks and returns success status -func doTasks(tasks []task) bool { - for _, task := range tasks { - mainLog.Load().Debug().Msgf("Running task %s", task.Name) - if err := task.f(); err != nil { - if task.abortOnError { - mainLog.Load().Error().Msgf("Error running task %s: %v", task.Name, err) - return false +// doTasksE runs tasks in order and reports which abortOnError task, if any, +// stopped the run. Use it over doTasks when the failure must be attributed +// to a specific task. +func doTasksE(tasks []task) (failedTaskName string, err error) { + for _, t := range tasks { + mainLog.Load().Debug().Msgf("Running task %s", t.Name) + if taskErr := t.f(); taskErr != nil { + if t.abortOnError { + mainLog.Load().Error().Msgf("Error running task %s: %v", t.Name, taskErr) + return t.Name, taskErr } // if this is darwin stop command, dont print debug // since launchctl complains on every start - if runtime.GOOS != "darwin" || task.Name != "Stop" { - mainLog.Load().Debug().Msgf("Error running task %s: %v", task.Name, err) + if runtime.GOOS != "darwin" || t.Name != "Stop" { + mainLog.Load().Debug().Msgf("Error running task %s: %v", t.Name, taskErr) } } } - return true + return "", nil +} + +// doTasks executes a list of tasks and returns success status +func doTasks(tasks []task) bool { + _, err := doTasksE(tasks) + return err == nil } // checkHasElevatedPrivilege checks if the process has elevated privileges and exits if not diff --git a/cmd/cli/service_test.go b/cmd/cli/service_test.go index 155bd3e..5047797 100644 --- a/cmd/cli/service_test.go +++ b/cmd/cli/service_test.go @@ -1,6 +1,7 @@ package cli import ( + "errors" "strings" "testing" ) @@ -26,3 +27,59 @@ func Test_ensureSystemdKillMode(t *testing.T) { }) } } + +func TestDoTasksESuccess(t *testing.T) { + var ran []string + tasks := []task{ + {func() error { ran = append(ran, "a"); return nil }, false, "a"}, + {func() error { ran = append(ran, "b"); return nil }, true, "b"}, + } + failedTask, err := doTasksE(tasks) + if failedTask != "" || err != nil { + t.Errorf("doTasksE() = (%q, %v), want (\"\", nil)", failedTask, err) + } + if got := strings.Join(ran, ","); got != "a,b" { + t.Errorf("ran tasks %q, want all tasks run in order", got) + } +} + +func TestDoTasksEAbortsOnAbortOnErrorTask(t *testing.T) { + wantErr := errors.New("install failed") + var ran []string + tasks := []task{ + {func() error { ran = append(ran, "Stop"); return nil }, false, "Stop"}, + {func() error { ran = append(ran, "Install"); return wantErr }, true, "Install"}, + {func() error { ran = append(ran, "Start"); return nil }, true, "Start"}, + } + failedTask, err := doTasksE(tasks) + if failedTask != "Install" || !errors.Is(err, wantErr) { + t.Errorf("doTasksE() = (%q, %v), want (\"Install\", %v)", failedTask, err, wantErr) + } + if got := strings.Join(ran, ","); got != "Stop,Install" { + t.Errorf("ran tasks %q, want the run to stop right after the abort", got) + } +} + +func TestDoTasksENonAbortFailureContinues(t *testing.T) { + var ran []string + tasks := []task{ + {func() error { ran = append(ran, "a"); return errors.New("a failed") }, false, "a"}, + {func() error { ran = append(ran, "b"); return nil }, true, "b"}, + } + failedTask, err := doTasksE(tasks) + if failedTask != "" || err != nil { + t.Errorf("doTasksE() = (%q, %v), want (\"\", nil) since the failing task did not abort", failedTask, err) + } + if got := strings.Join(ran, ","); got != "a,b" { + t.Errorf("ran tasks %q, want the run to continue past the non-abort failure", got) + } +} + +func TestDoTasksDelegatesToDoTasksE(t *testing.T) { + if !doTasks([]task{{func() error { return nil }, true, "ok"}}) { + t.Error("doTasks() = false, want true on success") + } + if doTasks([]task{{func() error { return errors.New("boom") }, true, "boom"}}) { + t.Error("doTasks() = true, want false when an abortOnError task fails") + } +} diff --git a/docs/provisioning-failure-codes.md b/docs/provisioning-failure-codes.md new file mode 100644 index 0000000..d391353 --- /dev/null +++ b/docs/provisioning-failure-codes.md @@ -0,0 +1,62 @@ +# Provisioning failure codes + +When ctrld hits a terminal failure during provisioning, it reports the same +stable code on three surfaces: + +- **Result file** — `provision_result.json` in the ctrld home directory + (next to the persisted internal `ctrld.log`). JSON with `stage`, `code`, + `exit_code`, `message`, and for listener failures a bounded + `detail.attempts` list of `{addr, proto, os_error}`. Written atomically, + removed on the next successful provisioning. Never contains provision + tokens, resolver/device IDs, or configuration contents. +- **Output line** — one fixed-format line on the CLI output: + `provisioning failed: stage= code= (exit )`. + Installer or MDM wrappers can extract exactly this line (fixed charset: + `stage=[a-z]* code=[A-Z_]* (exit [0-9]*)`) into their own logs without + risking token leakage from other output. +- **Exit code** — stage-scoped: bootstrap 30–39, listener 40–49, + service 50–59. Unrelated existing contracts are unchanged + (`ctrld status` exits 0–3; invalid deactivation pin exits 126). + +A customer or administrator only needs to report the code (or the whole +output line). The table below is the maintained support mapping; it must +stay in sync with `cmd/cli/provision_result.go` and changes in the same MR. + +## Codes + +| Code | Stage | Exit | Failure scenario | Next action / evidence | +|---|---|---|---|---| +| `API_UNREACHABLE` | bootstrap | 30 | The Control D API could not be reached or answered with a retryable error (network failure, proxy interference, 5xx, timeout) and retries ran out. The service manager may retry the service later. | Check the device's network path to `api.controld.com` (DNS, proxy, firewall, captive portal). Ask for the result file's `message` and whether other TLS traffic works. | +| `API_REJECTED` | bootstrap | 31 | The API answered and permanently rejected the configuration (4xx other than 408/429): bad or revoked token, malformed request. ctrld exits without burning service-manager restarts because retrying cannot change the answer. | Verify the provision token / org configuration in the Control D dashboard. Re-push after fixing credentials. Evidence: HTTP status in the result file `message`. | +| `API_DEVICE_INVALID` | bootstrap | 32 | The API reports the device/resolver no longer exists (error code 40402). ctrld self-uninstalls its service because the identity is gone server-side. | Confirm the device was deleted or re-provisioned in the dashboard; re-provision with a current token. No local evidence needed beyond the code. | +| `LISTENER_BIND_FAILED` | listener | 41 | No listen address could be bound after all fallbacks (configured address, 0.0.0.0:53, localhost:53, port 5354, random) were exhausted. `detail.attempts` records each tried address with the UDP/TCP OS error, e.g. `address already in use` (another DNS service owns the port) or `can't assign requested address` (address not on any interface). | Read `detail.attempts`: `address already in use` → find the process owning the port (`sudo lsof -i :53 -nP`); `can't assign requested address` → the configured IP is not present on the device. Then fix the conflict or the listener config. | +| `LISTENER_CONFIGURED_ADDR_UNAVAILABLE` | listener | 42 | An explicitly configured listener address could not be bound and configuration checks forbid falling back to another address, or (macOS intercept mode) the required explicit address is unavailable. | The configured `ip:port` in the listener config is wrong for this device or occupied. Verify the address exists on an interface and nothing else binds it; correct the config rather than expecting fallback. | +| `SERVICE_INSTALL_FAILED` | service | 51 | The OS service manager refused to install the service (launchd/systemd/SCM registration failed). | Check OS-level constraints: permissions/elevation, MDM policy blocking daemon installation, corrupted previous install. Evidence: result file `message` (service manager error), plus `launchctl print system/ctrld` / `systemctl status ctrld` / SCM state. | +| `SERVICE_START_FAILED` | service | 52 | The service installed but the service manager could not start it. | Check the service manager's own log for the start error, then the ctrld home dir `ctrld.log`. Often permissions or a binary quarantined by security tooling. | +| `SERVICE_SELFCHECK_FAILED` | service | 53 | The service started but never became healthy: no fresher failure was reported by the daemon, and the post-install DNS self-check failed. The just-installed service is rolled back (uninstalled). If the daemon itself recorded a more specific failure (e.g. a listener code), that code is reported instead of this one. | Ask for the drained service log printed by `ctrld start` and the result file. If the service was running but unreachable, check host firewall rules intercepting DNS to the listener. | + +## Reading the result file + +macOS and Linux (default service home is `/etc/controld`): + +```sh +sudo cat /etc/controld/provision_result.json +``` + +On Windows the file sits next to `ctrld.exe` in the install directory. A +custom `homedir` config moves it accordingly; routers and mobile use their +platform home directory. + +The file sits in the same directory as the persisted internal log +(`ctrld.log`) for the user the service runs as. On a healthy install the +file is absent. + +## Rules for maintainers + +- Codes are append-only once released. Never rename, renumber, or reuse a + code or exit number; add a new one and note the deprecation here. +- Every code added in `cmd/cli/provision_result.go` needs a row here in the + same MR. Tests enforce the code/stage/exit maps and that this table has + exactly one row per code. +- Detail must stay bounded and free of secrets: the constructor strips the + provision token and cd UID and caps sizes; do not bypass it.