From 1f001a559a61d1268a8661703fb6411cd70c1f4e Mon Sep 17 00:00:00 2001 From: Anthony Wong Date: Thu, 20 Aug 2026 15:51:17 +0000 Subject: [PATCH] feat(cli): add stable provisioning failure codes for manual and MDM installs --- SPEC.md | 206 +++++++++++ cmd/cli/cli.go | 177 ++++++++-- cmd/cli/cli_provision_test.go | 329 ++++++++++++++++++ cmd/cli/commands.go | 201 ++++++++--- cmd/cli/commands_start_test.go | 122 +++++++ cmd/cli/dns_intercept_darwin.go | 7 +- cmd/cli/provision_result.go | 247 +++++++++++++ cmd/cli/provision_result_test.go | 278 +++++++++++++++ cmd/cli/service.go | 28 +- cmd/cli/service_test.go | 57 +++ docs/provisioning-failure-codes.md | 61 ++++ tasks/plan.md | 213 ++++++++++++ tasks/todo.md | 21 ++ .../test-postinstall-provision-failure.sh | 148 ++++++++ 14 files changed, 1988 insertions(+), 107 deletions(-) create mode 100644 SPEC.md create mode 100644 cmd/cli/cli_provision_test.go create mode 100644 cmd/cli/commands_start_test.go create mode 100644 cmd/cli/provision_result.go create mode 100644 cmd/cli/provision_result_test.go create mode 100644 docs/provisioning-failure-codes.md create mode 100644 tasks/plan.md create mode 100644 tasks/todo.md create mode 100755 test-scripts/darwin/test-postinstall-provision-failure.sh diff --git a/SPEC.md b/SPEC.md new file mode 100644 index 0000000..706baee --- /dev/null +++ b/SPEC.md @@ -0,0 +1,206 @@ +# SPEC: Stable customer-visible provisioning failure codes + +Issue: [#586](https://gitlab.int.windscribe.com/controld/clients/ctrld/-/issues/586) +Requested by: Catt Garrod (@catt). Scope expanded by: Anthony Wong (@anthony). + +## 1. Objective + +Terminal provisioning failures in ctrld — bootstrap/API setup, listener +binding, and service installation/startup — must produce a stable, +support-facing failure identifier that survives process exit and reaches +both manual CLI users and MDM-driven installs. A customer or admin reports +one code; Support maps it to a scenario and a next action without asking +for reruns or verbose logs. + +Motivating incident (v1.5.5, macOS): provisioning reached the Control D +API, then died with only `FTL listener.0 could not find available listen +ip and port`. The per-address UDP/TCP bind errors existed only at Info +level in an in-memory logger and vanished on exit. The macOS pkg +`postinstall` discards ctrld's stdout/stderr entirely and judges success +by plist existence, so nothing useful reached the MDM log. + +**Users:** end customers and IT admins reporting failures; Support agents +triaging them; MDM/RMM operators reading installer logs. + +### Failure contract (agreed design) + +Three surfaces, all carrying the same identifier: + +1. **Result file** — on terminal provisioning failure, ctrld writes a + small redacted JSON file (atomic write: temp + rename) in the ctrld + home directory (same base dir as the internal `ctrld.log`, + via `absHomeDir`). Removed/overwritten on later successful + provisioning so stale failures don't mislead. Schema: + + ```json + { + "version": 1, + "timestamp": "2026-08-18T12:00:00Z", + "stage": "listener", + "code": "LISTENER_BIND_FAILED", + "exit_code": 41, + "message": "could not find available listen ip and port", + "detail": { + "attempts": [ + {"addr": "127.0.0.1:53", "proto": "udp", "os_error": "address already in use"} + ] + } + } + ``` + + `detail` is bounded (cap recorded bind attempts; cap string lengths) + and redacted by construction: no provisioning tokens, resolver IDs, + config contents, or unrelated host data. + +2. **Exit code + final stderr line** — the installer-facing command + (`ctrld start`, and `ctrld run` when run manually in the foreground) + exits with a stage-scoped code and prints one final line containing + the string code and stage, e.g. + `provisioning failed: stage=listener code=LISTENER_BIND_FAILED (exit 41)`. + +3. **Installer log (MDM path)** — `scripts/pkg/postinstall` stops + discarding the signal: it captures `ctrld start`'s output to a + private temp file, extracts only the fixed-charset identifier line + (`stage=[a-z]* code=[A-Z_]* (exit [0-9]*)` — structurally unable to + carry the token), and echoes it with the exit code into the + installer log. The result file's `message`/`detail` fields are + deliberately never surfaced there. The plist-existence check remains + the final success gate. + +### Identifier format + +- **Primary identifier: stable string codes.** Initial set — + bootstrap: `API_UNREACHABLE`, `API_REJECTED`, `API_DEVICE_INVALID`; + listener: `LISTENER_BIND_FAILED`, `LISTENER_CONFIGURED_ADDR_UNAVAILABLE`; + service: `SERVICE_INSTALL_FAILED`, `SERVICE_START_FAILED`, + `SERVICE_SELFCHECK_FAILED`. Codes are append-only; renames are new + codes plus a deprecation note in the mapping doc. +- **Secondary: stage-scoped process exit codes** as a coarse machine + signal: bootstrap 30–39, listener 40–49, service install/start 50–59. + Each string code owns one exit code. Existing contracts are untouched: + `ctrld status` 0–3, deactivation-pin 126, success 0. +- One underlying failure maps to one code on every path (manual CLI and + MDM), on both branches. + +### Propagation (daemon → installer) + +The listener/bootstrap fatals fire inside the daemon process +(`ctrld run` under launchd/systemd/SCM), not in `ctrld start`. The +daemon writes the result file before exiting; the existing log-socket +exit notification (`notifyExitToLogServer`) already unblocks `ctrld +start`'s self-check. `ctrld start` then reads the result file, prints +the identifier, and exits with the mapped stage exit code. The daemon's +own exit-status semantics toward service managers are preserved — +in particular the deliberate exit-0 on permanent API rejection that +protects the restart-policy budget; the result file carries the failure +identity in that case. + +### Support mapping + +`docs/provisioning-failure-codes.md` in this repo: one row per code — +code, stage, exit code, failure scenario, next safe troubleshooting +action or evidence request. Updated in the same MR whenever a code is +added or changed. + +### Branch scope + +Full implementation on **both** `v1.0` (release line for v1.5.5) and +`master`. The branches diverge heavily (`v1.0`: zerolog fork, +`commands.go`, `service_status.go`, macOS pkg scripts; `master`: zap, +inline commands, no pkg scripts), so this is one shared contract +(codes, exit-code ranges, file schema, doc) implemented twice, as two +MRs referencing #586. + +## 2. Commands + +- Build: `go build ./...` +- Test: `go test ./cmd/cli/...` (full: `go test ./...`) +- Vet: `go vet ./...` +- Branch workflow: feature branch off `v1.0` for the v1.0 MR; separate + feature branch off `master` for the port MR. Rebase, never merge the + base branch in. + +## 3. Project structure + +New and touched files on `v1.0` (master port mirrors the same contract +at its equivalent emission points in its `cli.go`): + +- `cmd/cli/provision_result.go` (new) — stage + code enums, exit-code + mapping, result-file schema, atomic write/read/clear helpers, + bounded/redacted detail builders. Pattern follows `service_status.go` + (small file: named constants + classifier + dedicated tests). +- `cmd/cli/provision_result_test.go` (new). +- `cmd/cli/cli.go` — emission points: `run()` bootstrap failure branches + (permanent rejection, invalid-device, fatal fetch), and + `tryUpdateListenerConfig` / `tryUpdateListenerConfigIntercept` fatals, + which now record per-attempt `{addr, proto, os_error}` bind detail. +- `cmd/cli/commands.go` — `initStartCmd`: doTasks install/start failures + and the self-check failure branch read the result file, print the + identifier, and exit with the stage code (replacing bare `os.Exit(1)` + on those paths). +- `scripts/pkg/postinstall` — propagate exit code + result-file contents + into the installer log (v1.0 only; master has no pkg scripts). +- `docs/provisioning-failure-codes.md` (new) — support mapping. + +## 4. Code style + +- Per repo conventions and global rules: guard clauses, small functions, + descriptive names, explicit error handling — never weaken existing + handling (e.g. keep the permanent-rejection exit-0 rationale intact). +- Comments only for non-obvious constraints (e.g. why the daemon must + still exit 0 on permanent rejection), simple-english, self-contained — + no issue/MR references in code. +- Match each branch's logging idiom: zerolog fork on `v1.0`, zap on + `master`. No new dependencies. +- Conventional Commits; MR titles in simple-english; both MRs reference + #586 (release-line MR carries `Closes #586`). + +## 5. Testing strategy + +Test-first where the harness allows. Coverage required by the issue: + +- **Code/mapping unit tests** — every string code maps to exactly one + stage and one in-range exit code; ranges don't collide with existing + contracts (0–3 status, 126 pin). +- **Result file round-trip** — write/read/clear; atomic write; stale + file removed on success. +- **Redaction** — serialize a result built from inputs containing a + provision token, resolver ID, and config content; assert none appear. +- **Listener bind failure (regression test for the incident)** — occupy + a port, drive the listener-config path to exhaustion, assert the + result records `LISTENER_BIND_FAILED` with attempted address, UDP/TCP + operation, and OS error (`address already in use`-class). +- **Bootstrap failures** — mock API: permanent 4xx → `API_REJECTED`; + invalid-device 40402 → `API_DEVICE_INVALID`; unreachable → + `API_UNREACHABLE`. +- **Service install/start/self-check failures** — injected task + failures assert code selection and `ctrld start` exit code. +- **MDM surface** — shell-level check of `postinstall` failure branch + (result file present → correct log line and exit), aligned with the + existing `test-scripts/` approach; manual pkg verification steps + documented in the MR. +- Both branches: the shared contract tests exist on both; branch-specific + emission tests match each branch's structure. + +## 6. Boundaries + +**Always:** +- Redact tokens, resolver IDs, config contents, host data from every + customer-visible surface (result file, stderr line, installer log). +- Preserve existing exit-code contracts (`ctrld status` 0–3, pin 126) + and the daemon's service-manager-facing exit semantics. +- Bound all recorded detail (attempt counts, string lengths). +- Keep codes append-only once merged. + +**Ask first:** +- Changing the daemon's (`ctrld run` under a service manager) exit codes + or restart-relevant behavior beyond writing the result file. +- Adding any persisted file outside the ctrld home directory. +- Expanding scope to runtime (post-provisioning) failures — this ticket + owns terminal provisioning failures only. + +**Never:** +- Print or persist the provisioning token (the reason postinstall + discards output today — the replacement surface must stay token-free). +- Auto-detect or kill conflicting processes (explicitly out of scope). +- Break `ctrld status`'s documented exit-code contract. diff --git a/cmd/cli/cli.go b/cmd/cli/cli.go index daff7dd..1f495a3 100644 --- a/cmd/cli/cli.go +++ b/cmd/cli/cli.go @@ -342,29 +342,8 @@ func run(appCallback *AppCallback, stopCh chan struct{}) { return } - cdLogger := mainLog.Load().With().Str("mode", "cd").Logger() - // 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. - 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 @@ -374,6 +353,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) } @@ -740,6 +723,76 @@ 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()) { + cdLogger := mainLog.Load().With().Str("mode", "cd").Logger() + 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 @@ -1424,16 +1477,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 } @@ -1448,8 +1512,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 } @@ -1463,8 +1529,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 } @@ -1566,6 +1634,15 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, infoLogger *zerolog.Logger, noti _ = 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. @@ -1574,16 +1651,21 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, infoLogger *zerolog.Logger, noti 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 *zerolog.Event, 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...) }) } @@ -1635,8 +1717,10 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, infoLogger *zerolog.Logger, noti 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) @@ -1648,8 +1732,10 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, infoLogger *zerolog.Logger, noti 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 @@ -1716,8 +1802,11 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, infoLogger *zerolog.Logger, noti } 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 @@ -1755,8 +1844,10 @@ func tryUpdateListenerConfig(cfg *ctrld.Config, infoLogger *zerolog.Logger, noti } } 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 } } } @@ -1804,13 +1895,23 @@ func cdUIDFromProvToken() string { Metadata: ctrld.SystemMetadata(context.Background()), } // Process provision token if provided. - resolverConfig, err := controld.FetchResolverUID(context.Background(), req, rootCmd.Version, cdDev) + resolverConfig, err := fetchResolverUIDFn(context.Background(), req, rootCmd.Version, 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..34628da --- /dev/null +++ b/cmd/cli/cli_provision_test.go @@ -0,0 +1,329 @@ +package cli + +import ( + "context" + "fmt" + "net" + "net/http" + "path/filepath" + "runtime" + "strconv" + "strings" + "testing" + + "github.com/rs/zerolog" + + "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, _ zerolog.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, nil, 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.go b/cmd/cli/commands.go index 5b1a968..0cc6542 100644 --- a/cmd/cli/commands.go +++ b/cmd/cli/commands.go @@ -283,6 +283,46 @@ func initRunCmd() *cobra.Command { return runCmd } +// 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) +} + func initStartCmd() *cobra.Command { startCmd := &cobra.Command{ PreRun: func(cmd *cobra.Command, args []string) { @@ -524,23 +564,50 @@ NOTE: running "ctrld start" without any arguments will start already installed c {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() mainLog.Load().Notice().Msg("Starting existing ctrld service") - if doTasks(tasks) { - mainLog.Load().Notice().Msg("Service started") - sockDir, err := socketDir() - if err != nil { - mainLog.Load().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 } - reportSetDnsOk(sockDir) - // Verify service registration after successful start. - if err := verifyServiceRegistration(); err != nil { - mainLog.Load().Warn().Err(err).Msg("Service registry verification failed") - } - } else { - mainLog.Load().Error().Err(err).Msg("Failed to start existing ctrld service") os.Exit(1) } + sockDir, err := socketDir() + if err != nil { + mainLog.Load().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) + mainLog.Load().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" + mainLog.Load().Error().Msg(fallbackMsg) + } + reportStartFailure(startAttemptAt, fallbackMsg) + return + } + mainLog.Load().Notice().Msg("Service started") + clearProvisionResult() + reportSetDnsOk(sockDir) + // Verify service registration after successful start. + if err := verifyServiceRegistration(); err != nil { + mainLog.Load().Warn().Err(err).Msg("Service registry verification failed") + } return } @@ -605,7 +672,7 @@ NOTE: running "ctrld start" without any arguments will start already installed c }) 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"}, @@ -614,59 +681,77 @@ NOTE: running "ctrld start" without any arguments will start already installed c // 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() mainLog.Load().Notice().Msg("Starting service") - if doTasks(tasks) { - if err := p.router.Install(sc); err != nil { - mainLog.Load().Warn().Err(err).Msg("post installation failed, please check system/service log for details error") + failedTask, taskErr := doTasksE(tasks) + if taskErr != nil { + if code, ok := serviceStageFailureCode(failedTask); ok { + failProvision(newProvisionResult(code, serviceTaskErrorSummary(failedTask, taskErr), nil, provisionSecrets()...), nil) return } + // 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 + } - // add a small delay to ensure the service is started and did not crash - time.Sleep(1 * time.Second) + if err := p.router.Install(sc); err != nil { + mainLog.Load().Warn().Err(err).Msg("post installation failed, please check system/service log for details error") + return + } - ok, status, err := selfCheckStatus(ctx, s, sockDir) - switch { - case ok && status == service.StatusRunning: - mainLog.Load().Notice().Msg("Service started") - default: - marker := bytes.Repeat([]byte("="), 32) - // If ctrld service is not running, emitting log obtained from ctrld process. - if status != service.StatusRunning || ctx.Err() != nil { - mainLog.Load().Error().Msg("ctrld service may not have started due to an error or misconfiguration, service log:") - _, _ = mainLog.Load().Write(marker) - haveLog := false - for msg := range runCmdLogCh { - _, _ = mainLog.Load().Write([]byte(strings.ReplaceAll(msg, msgExit, ""))) - haveLog = true - } - // If we're unable to get log from "ctrld run", notice users about it. - if !haveLog { - mainLog.Load().Write([]byte(`"`)) - } - } - // Report any error if occurred. - if err != nil { - _, _ = mainLog.Load().Write(marker) - msg := fmt.Sprintf("An error occurred while performing test query: %s", err) - mainLog.Load().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 { - _, _ = mainLog.Load().Write(marker) - mainLog.Load().Write([]byte(`ctrld service was running, but a DNS query could not be sent to its listener`)) - mainLog.Load().Write([]byte(`Please check your system firewall if it is configured to block/intercept/redirect DNS queries`)) - } + // 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: + mainLog.Load().Notice().Msg("Service started") + clearProvisionResult() + default: + marker := bytes.Repeat([]byte("="), 32) + 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 { + mainLog.Load().Error().Msg("ctrld service may not have started due to an error or misconfiguration, service log:") _, _ = mainLog.Load().Write(marker) - uninstall(p, s) - os.Exit(1) + haveLog := false + for msg := range runCmdLogCh { + _, _ = mainLog.Load().Write([]byte(strings.ReplaceAll(msg, msgExit, ""))) + haveLog = true + } + // If we're unable to get log from "ctrld run", notice users about it. + if !haveLog { + mainLog.Load().Write([]byte(`"`)) + } } - reportSetDnsOk(sockDir) - // Verify service registration after successful start. - if err := verifyServiceRegistration(); err != nil { - mainLog.Load().Warn().Err(err).Msg("Service registry verification failed") + // Report any error if occurred. + if err != nil { + _, _ = mainLog.Load().Write(marker) + msg := fmt.Sprintf("An error occurred while performing test query: %s", err) + mainLog.Load().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 { + _, _ = mainLog.Load().Write(marker) + mainLog.Load().Write([]byte(`ctrld service was running, but a DNS query could not be sent to its listener`)) + mainLog.Load().Write([]byte(`Please check your system firewall if it is configured to block/intercept/redirect DNS queries`)) + fallbackMsg = "ctrld service was running, but a DNS query could not be sent to its listener; check firewall rules blocking/intercepting/redirecting DNS queries" + } + + _, _ = mainLog.Load().Write(marker) + uninstall(p, s) + reportStartFailure(startAttemptAt, fallbackMsg) + return + } + reportSetDnsOk(sockDir) + // Verify service registration after successful start. + if err := verifyServiceRegistration(); err != nil { + mainLog.Load().Warn().Err(err).Msg("Service registry verification failed") } }, } 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 e828103..a894886 100644 --- a/cmd/cli/dns_intercept_darwin.go +++ b/cmd/cli/dns_intercept_darwin.go @@ -1683,12 +1683,17 @@ func (p *prog) dnsInterceptIgnoredChangeReconcileDue(now time.Time) 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() } func (p *prog) pfExecBackoffActive() bool { diff --git a/cmd/cli/provision_result.go b/cmd/cli/provision_result.go new file mode 100644 index 0000000..bd513be --- /dev/null +++ b/cmd/cli/provision_result.go @@ -0,0 +1,247 @@ +package cli + +import ( + "encoding/json" + "fmt" + "os" + "path/filepath" + "strings" + "time" + "unicode/utf8" +) + +// 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 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 f75ee55..39b41db 100644 --- a/cmd/cli/service.go +++ b/cmd/cli/service.go @@ -216,22 +216,30 @@ type task struct { Name string } -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 +} + +func doTasks(tasks []task) bool { + _, err := doTasksE(tasks) + return err == nil } func checkHasElevatedPrivilege() { 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..6d8b299 --- /dev/null +++ b/docs/provisioning-failure-codes.md @@ -0,0 +1,61 @@ +# 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 )`. + The macOS pkg `postinstall` extracts exactly this line into the installer + log, so MDM consoles see it without any ctrld log configuration. +- **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. diff --git a/tasks/plan.md b/tasks/plan.md new file mode 100644 index 0000000..e1303fc --- /dev/null +++ b/tasks/plan.md @@ -0,0 +1,213 @@ +# Plan: provisioning failure codes (issue #586) + +Spec: SPEC.md. Baseline: `ac0e6aed` on `v1.0`. +Branches: `issue-586` (off `v1.0`), `issue-586-master` (off `master`). +Two MRs, both referencing #586; the `v1.0` MR carries `Closes #586`. + +## Shared contract (fixed here so parallel tasks cannot diverge) + +| Code | Stage | Exit | +|---|---|---| +| `API_UNREACHABLE` | bootstrap | 30 | +| `API_REJECTED` | bootstrap | 31 | +| `API_DEVICE_INVALID` | bootstrap | 32 | +| `LISTENER_BIND_FAILED` | listener | 41 | +| `LISTENER_CONFIGURED_ADDR_UNAVAILABLE` | listener | 42 | +| `SERVICE_INSTALL_FAILED` | service | 51 | +| `SERVICE_START_FAILED` | service | 52 | +| `SERVICE_SELFCHECK_FAILED` | service | 53 | + +- Result file: `provision_result.json` in the ctrld home dir (same + resolution as the persisted internal log: `absHomeDir` on v1.0, the + `userHomeDir`-based equivalent on master). Atomic write (temp + + rename in the same dir). Cleared when provisioning succeeds. +- Result schema (version 1): `version`, `timestamp` (RFC3339, UTC), + `stage`, `code`, `exit_code`, `message`, optional `detail.attempts[]` + of `{addr, proto, os_error}`; attempts capped at 12 entries, every + string capped at 256 chars. +- Identifier line, exact format (greppable, token-free by + construction): `provisioning failed: stage= code= (exit )`. +- Redaction: results are built through a constructor that takes the + secrets in scope (cd UID, provision token) and strips them from every + field. Messages come from our own summaries plus OS error strings, + never raw config or API bodies. +- Exit seam: `provisionExit = os.Exit` package var so tests can stub + process exit. Emission helper `failProvision(...)` writes the file, + logs the identifier line, calls the notify func, then exits with the + stage code. Nonzero exit is preserved everywhere the daemon exits + nonzero today; the deliberate clean return on permanent API rejection + stays a clean return (result file only). + +## Dependency graph + +``` +A1 (contract module + doc, v1.0) D1 (master port) + ├─► B1 daemon emissions (cli.go) depends on: contract table + ├─► B2 start-side (commands.go+service.go) (from A1) + C1 verified + └─► B3 postinstall (scripts, tests) implementation as reference + └─► C1 v1.0 checkpoint ────────────► D1 ─► E1 final checkpoint +``` + +## Group A — serial, runs inline (1 task) + +### A1. Contract foundation on `issue-586` +Create branch `issue-586` from `v1.0`. New files: +`cmd/cli/provision_result.go`, `cmd/cli/provision_result_test.go`, +`docs/provisioning-failure-codes.md`. + +Module contents: stage type + the 8 code constants + exit-code map; +`ProvisionResult` struct per schema; bounded/redacting constructor; +atomic `writeProvisionResult` / `readProvisionResult` / +`clearProvisionResult`; identifier-line formatter; `provisionExit` +seam; `failProvision` helper. Doc: full table — code, stage, exit, +failure scenario, next safe troubleshooting action / evidence request. + +Tests (RED first): every code maps to exactly one stage and one +in-range exit code (30–39/40–49/50–59); no collision with 0–3 +(`ctrld status`) or 126 (pin); file round-trip; atomic overwrite; +clear; redaction (a result built from inputs containing a fake token +and cd UID serializes without them); attempts/string caps enforced; +identifier line matches the exact format. + +Acceptance: `go build ./...` and `go test ./cmd/cli/` green; doc rows +exactly match the constants. + +## Group B — parallel Workflow fan-out, one subagent per task, worktree isolation, branched from `issue-586` after A1 + +### B1. Daemon emissions in `cli.go` +- Bootstrap branches in `run()` (`cli.go:339-372`): + - permanent rejection (`permanentAPIRejection`): write `API_REJECTED` + result (HTTP status + our own summary, no raw API body), keep the + existing clean return and its comment. + - invalid device (`controld.InvalidConfigCode`): write + `API_DEVICE_INVALID` before `uninstallInvalidCdUID`. + - fatal fetch: write `API_UNREACHABLE`, replace + `cdLogger.Fatal()` with error log + identifier line + + `failProvision` exit 30 (still nonzero for the service manager). +- Listener (`tryUpdateListenerConfig`, `tryUpdateListenerConfigIntercept`): + - record every failed bind attempt `{addr, proto, os_error}` — + capture UDP and TCP errors separately in `tryListen` (keep + `errors.Join` for control flow), cap per contract. + - exhaustion fatal (`cli.go:1639`) and converged-random fatal + (`cli.go:1720`) → `LISTENER_BIND_FAILED` exit 41 with attempts. + - no-fallback-allowed fatal (`cli.go:1652`) and intercept-mode fatals + (`cli.go:1452,1467`) → `LISTENER_CONFIGURED_ADDR_UNAVAILABLE` + exit 42 (fallback-exhausted intercept fatal stays + `LISTENER_BIND_FAILED`). + - all fatals keep calling the notify func first; final message + includes the code string. +- Clear the result file at the point provisioning is known good + (after `updateListenerConfig` succeeds in `run()`). + +Tests (RED first): occupy a UDP+TCP port, drive the listener path to +exhaustion with the exit seam stubbed, assert the result file has +`LISTENER_BIND_FAILED`, the attempted address, both protocols' +`os_error` (`address already in use` class); pure mapping test +API error → code (permanent 4xx → `API_REJECTED`, 40402 → +`API_DEVICE_INVALID`, network error → `API_UNREACHABLE`) following +`cli_preflight_test.go` patterns. + +Acceptance: only `cmd/cli/cli.go` + new/extended tests touched; +`go build ./... && go test ./cmd/cli/` green. + +### B2. `ctrld start` reporting in `commands.go` + `service.go` +- Add `doTasksE` (returns failed task name + error; `doTasks` keeps + its signature and delegates). +- Fresh-install path (`commands.go:618`): failed `Install` task → + `SERVICE_INSTALL_FAILED` (write result, print identifier line, exit + 51); failed `Start` task → `SERVICE_START_FAILED` (exit 52). This + fixes the current fall-through that exits 0 on install failure. +- Existing-service path (`commands.go:528-543`): failure → 52 with the + same reporting (replaces bare `os.Exit(1)`). +- Self-check failure branch (`commands.go:627-664`): keep the log + drain and `uninstall(p, s)`; then read the daemon's result file — + if present and stamped after this start attempt began, report its + stage/code/exit (daemon identity wins: e.g. `LISTENER_BIND_FAILED`); + otherwise write and report `SERVICE_SELFCHECK_FAILED` exit 53. + Extract this into a testable helper (fabricated result files + + stubbed exit seam). +- On successful start (self-check ok), clear any stale result file. + +Tests (RED first): `doTasksE` failure attribution; helper precedence +(fresh daemon result wins; stale/missing falls back to 53); exit-code +selection per failed task. + +Acceptance: only `cmd/cli/commands.go`, `cmd/cli/service.go` + tests +touched; build and package tests green. + +### B3. postinstall MDM surface +- `scripts/pkg/postinstall`: capture `ctrld start` output to a + `mktemp` file (chmod 600) instead of `/dev/null`; keep the plist + check as the success gate; on failure, `grep -m1 '^provisioning + failed: '` from the capture into the install log together with the + exit code; delete the capture file always; never echo any other + output line (token safety preserved by extracting only the + fixed-format line). +- Shell test `test-scripts/darwin/test-postinstall-provision-failure.sh` + (matching existing script conventions): stub `$CTRLD` that prints a + fake token plus a valid identifier line and exits 41; assert the + logged output contains stage/code/exit and not the token; assert + success path unchanged. Runs without root. +- Update `docs/macos-pkg-mdm.md` where it documents the discard + behavior/failure triage, and add the failure-code doc link. + +Acceptance: shell test passes locally (`sh test-scripts/darwin/...`); +only `scripts/pkg/postinstall`, `test-scripts/darwin/`, `docs/` +touched. + +## Checkpoint C1 — serial, after Group B merges + +Merge order: B1, B2, B3 into `issue-586`. Then: `go build ./...`, +`go vet ./...`, `go test ./cmd/cli/...` (and full `./...`), run the B3 +shell test, verify doc table == constants, and verify each spec +acceptance criterion has an implementation + test. Fix-forward any +merge fallout before Group D starts. + +## Group D — serial (1 task, own worktree off `master`) + +### D1. Master port on `issue-586-master` +Create `git worktree` with branch `issue-586-master` from +`origin/master`/`master`. Port with the v1.0 implementation as +reference, adapted to master's structure (zap-shaped logging idiom, +no `commands.go`): + +- `cmd/cli/provision_result.go` + tests: identical contract table. +- Bootstrap: `run()` branches at master `cli.go:340-374` (same + permanent-rejection clean return, invalid-device, fatal fetch). +- Listener: `tryUpdateListenerConfig` fatals at master + `cli.go:1657/1667/1719`; intercept variant at `cli.go:1487/1502`; + per-attempt capture (bind errors currently logged at Debug, + `cli.go:1665`). +- Start side: `commands_service_start.go` — both `doTasks` call sites, + self-check `default:` arm (`os.Exit(1)` ~line 370), same fall-through + audit, same precedence logic; `doTasksE` in `service.go`. +- `docs/provisioning-failure-codes.md`: same table (omit + pkg/postinstall-specific notes; master has no `scripts/pkg`). +- No postinstall work on master. + +Tests mirrored from v1.0 where the structure allows. + +Acceptance: in the master worktree, `go build ./...`, +`go test ./cmd/cli/...` green; constants table semantically identical +to `issue-586`. + +## Checkpoint E1 — serial, final + +- Cross-branch contract equality: compare code constants, exit codes, + identifier-line format, result schema between the two branches. +- Full test suites on both branches. +- Both branches committed (per-task Conventional Commits); no pushes, + no MRs yet — `/draft-review` is the next pipeline step. + +## Execution notes + +- Each parallel group runs as one Workflow fan-out, one subagent per + task, `isolation: 'worktree'` so parallel edits never conflict; + serial tasks (A1, C1, D1, E1) run inline (D1 manages its own + master-based worktree). +- Every subagent follows RED → GREEN → regression → build and commits + in its worktree; the orchestrator merges in dependency order and + runs the full suite before the next group. +- Subagent prompts are self-contained: they carry the contract table + and file anchors from this plan, not references to SPEC.md (worktree + copies may not include untracked files). diff --git a/tasks/todo.md b/tasks/todo.md new file mode 100644 index 0000000..10a2693 --- /dev/null +++ b/tasks/todo.md @@ -0,0 +1,21 @@ +# TODO: issue #586 provisioning failure codes + +Groups run in order; tasks inside a parallel group run as one Workflow +fan-out (one subagent per task, worktree isolation). + +## Group A (serial) +- [x] A1: contract module `cmd/cli/provision_result.go` + tests + `docs/provisioning-failure-codes.md` on branch `issue-586` + +## Group B (parallel after A1) +- [x] B1: daemon emissions — bootstrap + listener paths in `cmd/cli/cli.go` + tests +- [x] B2: `ctrld start` reporting — `cmd/cli/commands.go`, `cmd/cli/service.go` (doTasksE, exit-0 fall-through fix, self-check precedence) + tests +- [x] B3: postinstall MDM surface — `scripts/pkg/postinstall`, shell test, `docs/macos-pkg-mdm.md` + +## Checkpoint C1 (serial) +- [x] C1: merge B1→B2→B3 into `issue-586`, full build/vet/test, shell test, doc/constants parity, spec AC audit + +## Group D (serial) +- [x] D1: master port on `issue-586-master` (contract module, cli.go emissions, commands_service_start.go, docs) + tests + +## Checkpoint E1 (serial) +- [x] E1: cross-branch contract equality, full suites on both branches, commits tidy — stop before push/MR (`/draft-review` next) diff --git a/test-scripts/darwin/test-postinstall-provision-failure.sh b/test-scripts/darwin/test-postinstall-provision-failure.sh new file mode 100755 index 0000000..d9f6eed --- /dev/null +++ b/test-scripts/darwin/test-postinstall-provision-failure.sh @@ -0,0 +1,148 @@ +#!/bin/sh +# Test: the MDM pkg postinstall script surfaces ctrld's provisioning +# failure identifier in its output without leaking the provision token, +# and still reports success once the plist exists. +# +# Self-contained and root-free: every path postinstall touches is +# redirected into a throwaway temp directory via the +# CTRLD_POSTINSTALL_{PLIST,CTRLD,PREFS} overrides, and 'defaults' is +# stubbed on PATH so the profile-wait loop resolves on its first attempt. +# +# Out of scope: the upgrade path (plist already exists) calls the real +# launchctl and is not exercised here. +# +# Run: sh test-postinstall-provision-failure.sh + +SCRIPT_DIR=$(cd "$(dirname "$0")" && pwd) +POSTINSTALL="$SCRIPT_DIR/../../scripts/pkg/postinstall" + +WORKDIR=$(mktemp -d -t ctrld-postinstall-test) || { + echo "FAIL: could not create test work directory" >&2 + exit 1 +} +trap 'rm -rf "$WORKDIR"' EXIT + +FAKE_TOKEN="FAKE-PROVISION-TOKEN-DO-NOT-LEAK-93af0c" +export FAKE_TOKEN + +STUBBIN="$WORKDIR/stubbin" +mkdir -p "$STUBBIN" + +cat > "$STUBBIN/defaults" <<'STUB' +#!/bin/sh +# Stand-in for macOS 'defaults read ': answers ProvisionToken +# immediately, like a profile that only sets that one key, so the +# postinstall wait loop never has to sleep. +if [ "$1" = "read" ] && [ "$3" = "ProvisionToken" ]; then + echo "$FAKE_TOKEN" + exit 0 +fi +exit 1 +STUB +chmod +x "$STUBBIN/defaults" + +FAILURES=0 + +fail() { + echo "FAIL: $1" >&2 + FAILURES=$((FAILURES + 1)) +} + +assert_eq() { + # assert_eq + if [ "$1" != "$2" ]; then + fail "$3 (expected '$2', got '$1')" + fi +} + +assert_contains() { + # assert_contains + case "$1" in + *"$2"*) ;; + *) fail "$3 (expected to find '$2')" ;; + esac +} + +assert_not_contains() { + # assert_not_contains + case "$1" in + *"$2"*) fail "$3 (must not contain '$2')" ;; + *) ;; + esac +} + +# run_postinstall runs postinstall with the given plist/ctrld overrides and +# a private TMPDIR, so the caller can check that the postinstall's own +# capture file (created inside that TMPDIR via mktemp) does not survive. +run_postinstall() { + plist_override=$1 + ctrld_override=$2 + capture_tmpdir=$3 + output=$(PATH="$STUBBIN:$PATH" \ + TMPDIR="$capture_tmpdir" \ + CTRLD_POSTINSTALL_PLIST="$plist_override" \ + CTRLD_POSTINSTALL_CTRLD="$ctrld_override" \ + CTRLD_POSTINSTALL_PREFS="/does/not/matter" \ + sh "$POSTINSTALL" 2>&1) + exit_code=$? +} + +# --- Failure case: ctrld reports a listener bind failure --------------- + +failure_dir="$WORKDIR/failure" +failure_tmp="$failure_dir/tmp" +mkdir -p "$failure_tmp" +failure_plist="$failure_dir/ctrld.plist" +failure_ctrld="$failure_dir/ctrld" + +cat > "$failure_ctrld" <<'STUB' +#!/bin/sh +# Stands in for a ctrld that fails to bind its listener: echoes the raw +# token (as ctrld's own error output may) plus the fixed-format failure +# identifier behind a log-style prefix, then exits with the stage code. +echo "$FAKE_TOKEN" +echo "2024-01-01T00:00:00Z ERR ctrld: provisioning failed: stage=listener code=LISTENER_BIND_FAILED (exit 41)" +exit 41 +STUB +chmod +x "$failure_ctrld" + +run_postinstall "$failure_plist" "$failure_ctrld" "$failure_tmp" + +assert_eq "$exit_code" "1" "failure case: postinstall exit code" +assert_contains "$output" "stage=listener" "failure case: output names the stage" +assert_contains "$output" "LISTENER_BIND_FAILED" "failure case: output names the code" +assert_contains "$output" "41" "failure case: output names the exit code" +assert_not_contains "$output" "$FAKE_TOKEN" "failure case: output must not contain the provision token" + +leftover=$(ls -A "$failure_tmp" 2>/dev/null) +assert_eq "$leftover" "" "failure case: capture temp file removed" + +# --- Success case: ctrld provisions and writes the plist ---------------- + +success_dir="$WORKDIR/success" +success_tmp="$success_dir/tmp" +mkdir -p "$success_tmp" +success_plist="$success_dir/ctrld.plist" +success_ctrld="$success_dir/ctrld" + +cat > "$success_ctrld" < "$success_plist" +exit 0 +STUB +chmod +x "$success_ctrld" + +run_postinstall "$success_plist" "$success_ctrld" "$success_tmp" + +assert_eq "$exit_code" "0" "success case: postinstall exit code" +assert_contains "$output" "provisioning complete" "success case: output mentions success" + +if [ "$FAILURES" -gt 0 ]; then + echo "$FAILURES assertion(s) failed" >&2 + exit 1 +fi + +echo "OK: postinstall surfaces provisioning failure codes without leaking the token" +exit 0