diff --git a/cmd/tracebloc/main.go b/cmd/tracebloc/main.go index 29ef9f0..7300d82 100644 --- a/cmd/tracebloc/main.go +++ b/cmd/tracebloc/main.go @@ -23,6 +23,7 @@ import ( "os" "os/signal" "syscall" + "time" "github.com/tracebloc/cli/internal/cli" ) @@ -59,11 +60,23 @@ func main() { syscall.SIGINT, syscall.SIGTERM) defer stop() - executed, err := cli.NewRootCmd(cli.BuildInfo{ + info := cli.BuildInfo{ Version: version, GitSHA: gitSHA, BuildDate: buildDate, - }).ExecuteContextC(ctx) + } + root := cli.NewRootCmd(info) + + started := time.Now() + executed, err := root.ExecuteContextC(ctx) + + // backend#1907: one command-outcome event per invocation, emitted from the + // single point every command path converges on — command name, duration, + // exit code, OS/arch, version, error class. No arguments, no paths (see + // internal/cli/telemetry.go for why that is structural rather than a rule). + // Opt-out via TRACEBLOC_NO_TELEMETRY / DO_NOT_TRACK; best-effort and silent, + // so nothing here can change what the customer sees or what we exit with. + cli.RecordCommandOutcome(root, executed, info, cli.ExitCodeFromError(err), time.Since(started)) // F1: after the command runs, a quiet once-a-day nudge if a newer release // exists (best-effort; silent on dev builds, off a terminal, in CI, or with diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 9943e9e..5f852c9 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -131,6 +131,34 @@ produces that code. | `9` | The ingestion Job exited non-zero, completed with row-level failures the summary panel reports, or its outcome couldn't be determined / followed | `data ingest` | `exitIngestFailed` | | `130` | You hit Ctrl-C while something was already running — the sign-in wait, `client status --wait`, the seal check, or an installer re-run (128+SIGINT). Ctrl-C at a *question* is `0` instead: nothing had started | `login`, `client status --wait`, `client status --seal`, `upgrade`, `prepare-host` | `exitInterrupted` | +## Usage reporting + +The CLI records one outcome event per command so we can see failures like the +ones on this page without waiting for someone to report them. It is on by +default and it is a fixed, closed set of fields — there is no free-text field +in the record at all: + +| Field | Example | Where it comes from | +|---|---|---| +| command | `data ingest` | the command you ran, looked up in the CLI's own command list. A value that isn't one of those commands is reported as `unregistered` | +| exit code | `4` | the table above | +| error class | `no_secure_environment` | derived from that exit code, nothing else | +| duration | `1520` ms | wall clock | +| OS / architecture | `darwin` / `arm64` | compiled into the binary | +| version | `0.10.9` | the release you're running | + +**What is never sent:** your arguments, any file or directory path, any dataset +or file contents, your username, your hostname, your kubeconfig, your tokens. +Not "filtered out" — the record has nowhere to put them. Each run gets a fresh +random id, so runs are not linked to each other or to you. + +Turn it off with either of: + +```bash +export TRACEBLOC_NO_TELEMETRY=1 +export DO_NOT_TRACK=1 +``` + ## Still stuck? Open an issue at [github.com/tracebloc/cli/issues](https://github.com/tracebloc/cli/issues) diff --git a/internal/cli/telemetry.go b/internal/cli/telemetry.go new file mode 100644 index 0000000..67c5964 --- /dev/null +++ b/internal/cli/telemetry.go @@ -0,0 +1,173 @@ +package cli + +// Command-outcome telemetry wiring — backend#1907. +// +// One event per invocation, emitted from the single place every command path +// converges on (main.go, after ExecuteContextC returns). Hooking each handler +// instead would mean N call sites that each have to remember, and §6.5's +// "terminal event on every path" would then be true only for the handlers +// somebody remembered. +// +// WHERE THIS STOPS TODAY. The transport is a seam. RFC-BACKEND-1872's Collector +// gateway was replaced on 17 Aug by an ingest endpoint on the backend +// (rfcs#28), which is backend#1905 and does not exist yet — so pendingSink +// returns nil and every event is validated and dropped. That is deliberate: +// validation runs on every build regardless, so a malformed event fails in CI +// wherever the binary was built, and connecting #1905 is one function. + +import ( + "crypto/rand" + "encoding/hex" + "os" + "strings" + "time" + + "github.com/spf13/cobra" + + "github.com/tracebloc/cli/internal/api" + "github.com/tracebloc/cli/internal/config" + "github.com/tracebloc/cli/internal/telemetry" +) + +// telemetryOptOutVars disable emission when set. Opt-OUT, per the ticket: +// telemetry that only the already-convinced enable measures the wrong +// population, and the population this exists for is people whose install just +// failed. DO_NOT_TRACK is the cross-vendor spelling; supporting it means a user +// who has already expressed the preference once does not have to learn ours. +var telemetryOptOutVars = []string{"TRACEBLOC_NO_TELEMETRY", "DO_NOT_TRACK"} + +// telemetryEnabled reports whether this invocation may emit. +// +// Anything other than the explicit "off" spellings counts as opting out. The +// asymmetry is on purpose: a user who typed TRACEBLOC_NO_TELEMETRY=please +// meant it, and guessing wrong in the other direction sends a record they +// declined. +func telemetryEnabled(getenv func(string) string) bool { + for _, name := range telemetryOptOutVars { + switch strings.ToLower(strings.TrimSpace(getenv(name))) { + case "", "0", "false": + continue + default: + return false + } + } + return true +} + +// commandPaths enumerates every path the tree can dispatch, DERIVED from the +// live tree rather than listed here. That is what makes the closed set in +// telemetry.NewOutcomeRecorder maintain itself: a command added to NewRootCmd is +// reportable the day it lands, and a value that is not a command in the tree can +// never be emitted — including one assembled out of user input. +func commandPaths(root *cobra.Command) []string { + var out []string + var walk func(c *cobra.Command) + walk = func(c *cobra.Command) { + out = append(out, commandPathOf(c)) + for _, sub := range c.Commands() { + walk(sub) + } + } + walk(root) + return out +} + +// commandPathOf renders one command as the contract's tracebloc.cli.command +// value: the invocation minus the binary name, "data ingest" (§7.1). The bare +// root reports its own name rather than an empty string, which normalise would +// drop as absent — leaving the one invocation shape a first-time user is most +// likely to produce as the only one with no command on the record. +func commandPathOf(c *cobra.Command) string { + if c == nil { + return "" + } + path := strings.TrimSpace(c.CommandPath()) + root := c.Root().Name() + if path == root || path == "" { + return root + } + return strings.TrimSpace(strings.TrimPrefix(path, root)) +} + +// telemetryEnv picks deployment.environment for the records. +// +// The signed-in environment wins because it is the backend these records are +// about; $CLIENT_ENV and the prod default are api.ResolveEnv's existing answer, +// reused rather than restated. An unrecognised value is not repaired here — the +// emitter refuses to export under a guessed environment (§3.2), and that +// refusal belongs in one place. +func telemetryEnv(signedInEnv string) string { + if api.IsKnownEnv(signedInEnv) { + return strings.ToLower(signedInEnv) + } + return api.ResolveEnv("") +} + +// signedInEnv reads the environment the config points at, best-effort. A +// missing or unreadable config is simply "not signed in". +func signedInEnv() string { + cfg, err := config.Load() + if err != nil || cfg == nil { + return "" + } + return cfg.CurrentEnv +} + +// processInstanceID is the per-PROCESS id §2 asks for off-cluster. +// +// Not the hostname, and not a persisted machine id. Hostnames in this product's +// field data are overwhelmingly "-macbook", which §7.3 forbids +// outright; a persisted id would be a durable identifier we would then have to +// answer erasure requests about. A fresh random value per run still separates +// concurrent runs, which is all service.instance.id is for here. +func processInstanceID() string { + b := make([]byte, 8) + if _, err := rand.Read(b); err != nil { + // Omitted rather than faked. New() drops an empty instance id, and a + // constant stand-in would silently fuse every affected run into one. + return "" + } + return hex.EncodeToString(b) +} + +// pendingSink is the transport seam for backend#1905. +// +// nil means validate-and-drop (telemetry.SetSink's documented contract). When +// the ingest endpoint lands this returns the client that posts to it, and +// nothing else in this file changes. +func pendingSink() telemetry.Sink { return nil } + +// RecordCommandOutcome emits the single terminal event for this invocation. +// main.go calls it once, after the command tree has returned and before exit. +// +// It never returns an error and never panics: a CLI that died because telemetry +// was unhappy would be a strictly worse CLI. A malformed event is caught by the +// tests below, where it is free. +func RecordCommandOutcome(root, executed *cobra.Command, info BuildInfo, exitCode int, elapsed time.Duration) { + _ = recordCommandOutcome(root, executed, info, exitCode, elapsed, os.Getenv, pendingSink()) +} + +// recordCommandOutcome is RecordCommandOutcome with its two ambient +// dependencies passed in, so the tests drive the real thing. +func recordCommandOutcome( + root, executed *cobra.Command, + info BuildInfo, + exitCode int, + elapsed time.Duration, + getenv func(string) string, + sink telemetry.Sink, +) error { + if !telemetryEnabled(getenv) { + return nil + } + emitter := telemetry.New(telemetryEnv(signedInEnv()), info.Version, processInstanceID()) + if sink != nil { + emitter.SetSink(sink) + } + recorder := telemetry.NewOutcomeRecorder(emitter, commandPaths(root)) + return recorder.Record(telemetry.Outcome{ + Command: commandPathOf(executed), + ExitCode: exitCode, + Elapsed: elapsed, + }) +} diff --git a/internal/cli/telemetry_test.go b/internal/cli/telemetry_test.go new file mode 100644 index 0000000..a376603 --- /dev/null +++ b/internal/cli/telemetry_test.go @@ -0,0 +1,398 @@ +package cli + +import ( + "encoding/json" + "fmt" + "os" + "path/filepath" + "regexp" + "strings" + "testing" + "time" + + "github.com/spf13/cobra" + "github.com/spf13/pflag" + + "github.com/tracebloc/cli/internal/api" + "github.com/tracebloc/cli/internal/telemetry" +) + +// telemetryCanary is a value that could only have come off a user's command +// line: a path segment with a patient identifier in it. Written down here, and +// never derived from anything the code under test produces — a needle iterated +// out of the haystack finds itself and nothing else. +const telemetryCanary = "CANARY-PATIENT-7" + +func testBuildInfo() BuildInfo { + return BuildInfo{Version: "0.10.9", GitSHA: "abc1234", BuildDate: "2026-08-18"} +} + +// isolateConfig points config.Load at an empty directory so these tests never +// read (or report on) the developer's real signed-in environment. +func isolateConfig(t *testing.T) { + t.Helper() + t.Setenv("TRACEBLOC_CONFIG_DIR", t.TempDir()) + t.Setenv("CLIENT_ENV", api.EnvProd) +} + +// captureOutcome runs the real recorder over the real tree and returns what +// reached the sink. +func captureOutcome( + t *testing.T, root, executed *cobra.Command, exitCode int, env map[string]string, +) (map[string]string, map[string]any, bool) { + t.Helper() + var res map[string]string + var rec map[string]any + delivered := 0 + sink := telemetry.Sink(func(r map[string]string, d map[string]any) { + res, rec = r, d + delivered++ + }) + getenv := func(k string) string { return env[k] } + if err := recordCommandOutcome( + root, executed, testBuildInfo(), exitCode, 1500*time.Millisecond, getenv, sink, + ); err != nil { + t.Fatalf("recordCommandOutcome: %v", err) + } + if delivered > 1 { + t.Fatalf("one invocation delivered %d events; the contract is exactly one", delivered) + } + return res, rec, delivered == 1 +} + +// walkTree yields every command in the tree, so the assertions below are +// derived from what actually dispatches rather than from a list somebody has to +// remember to extend. +func walkTree(root *cobra.Command) []*cobra.Command { + var out []*cobra.Command + var walk func(c *cobra.Command) + walk = func(c *cobra.Command) { + out = append(out, c) + for _, sub := range c.Commands() { + walk(sub) + } + } + walk(root) + return out +} + +// --- the closed set is the live tree ------------------------------------------ + +func TestEveryCommandInTheLiveTreeReportsItsOwnPath(t *testing.T) { + // The point of deriving the set from the tree: a command added to + // NewRootCmd is reportable the day it lands. If this ever fails for a new + // command, the enumeration and the dispatcher have drifted — which would + // mean that command's failures were being filed under "unregistered". + isolateConfig(t) + root := NewRootCmd(testBuildInfo()) + + commands := walkTree(root) + if len(commands) < 10 { + t.Fatalf("walked only %d commands — the tree was not built", len(commands)) + } + for _, cmd := range commands { + t.Run(cmd.CommandPath(), func(t *testing.T) { + _, rec, ok := captureOutcome(t, root, cmd, 0, nil) + if !ok { + t.Fatal("nothing was delivered") + } + want := commandPathOf(cmd) + if rec[telemetry.AttrCommand] != want { + t.Fatalf("%s = %v, want %q — this command is not in the enumerated set", + telemetry.AttrCommand, rec[telemetry.AttrCommand], want) + } + if rec[telemetry.AttrCommand] == telemetry.CommandUnregistered { + t.Fatalf("%q dispatches but is not enumerated", cmd.CommandPath()) + } + }) + } +} + +func TestTheBareRootIsNamedNotBlank(t *testing.T) { + // commandPathOf's root case: an empty string is dropped by the emitter's + // omit-when-absent rule, which would leave the invocation a first-time user + // is most likely to produce as the only one with no command on the record. + isolateConfig(t) + root := NewRootCmd(testBuildInfo()) + _, rec, ok := captureOutcome(t, root, root, 0, nil) + if !ok { + t.Fatal("nothing was delivered") + } + if rec[telemetry.AttrCommand] != root.Name() { + t.Fatalf("bare root reported %v, want %q", rec[telemetry.AttrCommand], root.Name()) + } +} + +// --- the privacy boundary, over the real tree --------------------------------- + +// TestNoFlagValueOrArgumentCanReachTheRecord is the ticket's hard boundary, +// checked against what the code emits rather than against a list of keys we +// hope nobody adds. +// +// Every command in the live tree has every one of its flags set to the canary, +// canary positional args attached, and a canary in the environment. Then the +// whole delivered payload — keys and values, resource and record — is searched. +func TestNoFlagValueOrArgumentCanReachTheRecord(t *testing.T) { + isolateConfig(t) + root := NewRootCmd(testBuildInfo()) + + inspected := 0 + for _, cmd := range walkTree(root) { + // Load the command up with everything a user could have typed. + cmd.Flags().VisitAll(func(f *pflag.Flag) { + _ = f.Value.Set(telemetryCanary) + f.Changed = true + }) + cmd.SetArgs([]string{"/Users/" + telemetryCanary + "/oncology.csv", telemetryCanary}) + + env := map[string]string{ + "CLIENT_ENV": api.EnvProd, + "TRACEBLOC_CONFIG_DIR": "/home/" + telemetryCanary + "/.tracebloc", + } + res, rec, ok := captureOutcome(t, root, cmd, 9, env) + if !ok { + t.Fatalf("%s delivered nothing", cmd.CommandPath()) + } + for k, v := range res { + assertNoTelemetryCanary(t, cmd.CommandPath(), "resource", k, v) + inspected++ + } + for k, v := range rec { + assertNoTelemetryCanary(t, cmd.CommandPath(), "record", k, fmt.Sprint(v)) + inspected++ + } + } + // The anchor: an inert loop over an empty payload reads exactly like a clean + // sweep in the log. + if inspected < 100 { + t.Fatalf("only %d attributes were searched — the sweep ran over nothing", inspected) + } +} + +func TestACommandPathCarryingAnArgumentIsRefusedNotCleaned(t *testing.T) { + // The failure mode this guards: some future caller passing os.Args, or a + // cobra change that starts including args in CommandPath(). The lookup makes + // that a countable "unregistered", never a partially-scrubbed string. + isolateConfig(t) + // The impostor's NAME is the canary, so commandPathOf hands the recorder a + // path carrying it. (Note what cobra itself does not do: Name() takes the + // first word of Use, so `Use: "ingest "` yields "ingest" — CommandPath + // structurally cannot contain an argument today. This test is the guard for + // the day that stops being true, or for a caller that builds the path itself.) + impostor := &cobra.Command{Use: telemetryCanary} + tree := NewRootCmd(testBuildInfo()) + tree.AddCommand(impostor) + // Enumerate from a tree that never had it — the set is what main.go builds + // from the dispatcher, and this command was never meant to be in it. + clean := NewRootCmd(testBuildInfo()) + + if got := commandPathOf(impostor); !strings.Contains(got, telemetryCanary) { + t.Fatalf("the fixture is inert: commandPathOf gave %q, which carries no canary "+ + "for the lookup to refuse", got) + } + + res, rec, ok := captureOutcome(t, clean, impostor, 1, nil) + if !ok { + t.Fatal("nothing was delivered") + } + if rec[telemetry.AttrCommand] != telemetry.CommandUnregistered { + t.Fatalf("%s = %v, want %q", telemetry.AttrCommand, + rec[telemetry.AttrCommand], telemetry.CommandUnregistered) + } + // Sweep the WHOLE payload, not just the one key. Checking only + // tracebloc.cli.command leaves the canary free to arrive under any other + // attribute — which is exactly what happened under the "smuggle the raw + // command into a second attribute" mutation: this test stayed green while + // the record carried the path verbatim. + for k, v := range res { + assertNoTelemetryCanary(t, "impostor", "resource", k, v) + } + for k, v := range rec { + assertNoTelemetryCanary(t, "impostor", "record", k, fmt.Sprint(v)) + } +} + +func TestTheWholePayloadIsSerialisableAndSmall(t *testing.T) { + // The record is what a transport will put on the wire. Anything that will + // not round-trip as JSON primitives is the retired extraData defect arriving + // by another door, and an outcome event that needs more than a kilobyte is + // carrying something it should not. + isolateConfig(t) + root := NewRootCmd(testBuildInfo()) + res, rec, ok := captureOutcome(t, root, root, 9, nil) + if !ok { + t.Fatal("nothing was delivered") + } + blob, err := json.Marshal(map[string]any{"resource": res, "attributes": rec}) + if err != nil { + t.Fatalf("the payload does not serialise: %v", err) + } + if len(blob) > 1024 { + t.Fatalf("an outcome event serialised to %d bytes: %s", len(blob), blob) + } +} + +// --- opt-out ------------------------------------------------------------------ + +func TestOptOutStopsEmissionEntirely(t *testing.T) { + isolateConfig(t) + root := NewRootCmd(testBuildInfo()) + + // DERIVED: the variables the production code declares, not a list restated + // here. Adding a spelling to telemetryOptOutVars covers it automatically. + for _, name := range telemetryOptOutVars { + for _, value := range []string{"1", "true", "yes", "please", " 1 "} { + t.Run(name+"="+strings.TrimSpace(value), func(t *testing.T) { + _, _, ok := captureOutcome(t, root, root, 0, map[string]string{name: value}) + if ok { + t.Fatalf("%s=%q still emitted", name, value) + } + }) + } + } +} + +func TestTheOffSpellingsDoNotOptOut(t *testing.T) { + // The mutation anchor for the test above: if telemetryEnabled returned false + // unconditionally, every opt-out case would pass and the feature would be + // dead. These are the values that must NOT disable it. + isolateConfig(t) + root := NewRootCmd(testBuildInfo()) + for _, value := range []string{"", "0", "false", "FALSE"} { + t.Run("value_"+value, func(t *testing.T) { + _, _, ok := captureOutcome(t, root, root, + 0, map[string]string{"TRACEBLOC_NO_TELEMETRY": value}) + if !ok { + t.Fatalf("%q disabled telemetry; only an explicit opt-out should", value) + } + }) + } +} + +// --- environment --------------------------------------------------------------- + +func TestTheEnvironmentIsNeverGuessed(t *testing.T) { + // §3.2 — an unrecognised environment must not export under a repaired or + // guessed value. `staging` is the classic near miss: it is the git branch + // name, and `stg` is the environment value. + for _, tc := range []struct { + signedIn string + want string + }{ + {api.EnvDev, api.EnvDev}, + {api.EnvStg, api.EnvStg}, + {"PROD", api.EnvProd}, + {"staging", api.EnvProd}, // not repaired to stg — falls back to the default + {"", api.EnvProd}, + } { + t.Run("signed_in_"+tc.signedIn, func(t *testing.T) { + t.Setenv("CLIENT_ENV", "") + if got := telemetryEnv(tc.signedIn); got != tc.want { + t.Fatalf("telemetryEnv(%q) = %q, want %q", tc.signedIn, got, tc.want) + } + }) + } +} + +func TestAnUnknownEnvironmentDeliversNothing(t *testing.T) { + // The end-to-end consequence: the emitter refuses to export under a value no + // query filters on, and the wiring must not have talked it out of that. + isolateConfig(t) + t.Setenv("CLIENT_ENV", "staging") + root := NewRootCmd(testBuildInfo()) + if _, _, ok := captureOutcome(t, root, root, 0, nil); ok { + t.Fatal("delivered a record under an unrecognised environment") + } +} + +func TestTheSignedInEnvironmentWins(t *testing.T) { + // A developer signed into dev must not have their runs filed under prod. + dir := t.TempDir() + t.Setenv("TRACEBLOC_CONFIG_DIR", dir) + t.Setenv("CLIENT_ENV", "") + body := `{"version":2,"current_env":"dev","profiles":{"dev":{"token":"x"}}}` + if err := os.WriteFile(filepath.Join(dir, "config.json"), []byte(body), 0o600); err != nil { + t.Fatal(err) + } + // Read it back before asserting on the record: a skip here would be a + // fail-open, and a config layout this fixture no longer matches must be a + // finding, not a quiet pass. + if got := signedInEnv(); got != api.EnvDev { + t.Fatalf("signedInEnv() = %q, want %q — the on-disk config layout changed "+ + "and this fixture (and possibly the reader) is stale", got, api.EnvDev) + } + root := NewRootCmd(testBuildInfo()) + res, _, ok := captureOutcome(t, root, root, 0, nil) + if !ok { + t.Fatal("nothing was delivered") + } + if res["deployment.environment"] != api.EnvDev { + t.Fatalf("deployment.environment = %q, want %q", + res["deployment.environment"], api.EnvDev) + } +} + +// --- instance id --------------------------------------------------------------- + +func TestTheInstanceIDIsPerProcessAndNotTheHostname(t *testing.T) { + // §2 asks for a stable per-process uuid off-cluster. Not the hostname: field + // hostnames are overwhelmingly "-macbook", which §7.3 forbids + // outright. Two calls must differ, and neither may look like a host. + host, _ := os.Hostname() + a, b := processInstanceID(), processInstanceID() + if a == b { + t.Fatal("two invocations shared an instance id — that is a durable identifier") + } + if len(a) != 16 { + t.Fatalf("instance id %q is not the expected 16 hex chars", a) + } + if host != "" && strings.Contains(a, host) { + t.Fatalf("the instance id embeds the hostname: %q", a) + } +} + +func assertNoTelemetryCanary(t *testing.T, where, layer, key, value string) { + t.Helper() + if strings.Contains(key, telemetryCanary) { + t.Fatalf("%s: %s key %q carries the canary", where, layer, key) + } + if strings.Contains(value, telemetryCanary) { + t.Fatalf("%s: %s %q = %q carries the canary", where, layer, key, value) + } +} + +// TestTheDocumentedOptOutVariablesAreTheRealOnes closes the gap that makes a +// stale doc worse than no doc: a user who exports the variable +// docs/troubleshooting.md names believes they have opted out. If the name there +// has drifted from telemetryOptOutVars, they have not, and nothing else would +// ever tell them. +// +// DERIVED both ways — it parses the variable names out of the document and +// compares the SET against the production slice, so neither a rename in the +// code nor an edit to the doc can pass on its own. +func TestTheDocumentedOptOutVariablesAreTheRealOnes(t *testing.T) { + body, err := os.ReadFile(filepath.Join("..", "..", "docs", "troubleshooting.md")) + if err != nil { + // Fail closed: an unreadable document is not evidence of agreement. + t.Fatalf("cannot read the document this guard checks: %v", err) + } + found := map[string]bool{} + for _, m := range regexp.MustCompile(`export ([A-Z_]+)=1`).FindAllStringSubmatch(string(body), -1) { + found[m[1]] = true + } + if len(found) == 0 { + t.Fatal("the document names no opt-out variable — either the section was " + + "removed (then remove this guard) or its shape changed and this parse is inert") + } + for _, name := range telemetryOptOutVars { + if !found[name] { + t.Errorf("%s disables telemetry but docs/troubleshooting.md does not tell "+ + "anyone so", name) + } + delete(found, name) + } + for name := range found { + t.Errorf("docs/troubleshooting.md tells users to export %s, which disables "+ + "nothing — telemetryOptOutVars is %v", name, telemetryOptOutVars) + } +} diff --git a/internal/telemetry/outcome.go b/internal/telemetry/outcome.go new file mode 100644 index 0000000..3dedc22 --- /dev/null +++ b/internal/telemetry/outcome.go @@ -0,0 +1,199 @@ +package telemetry + +import "time" + +// Command outcomes — backend#1907, RFC-BACKEND-1872 D12's host-process path. +// +// WHAT THIS IS FOR. The CLI is the least-observed surface in the product and +// the one that runs on the most different machines. Every failure in the +// backend#736 class — the binary landing on a PATH the shell does not read, a +// cluster command reading a kubeconfig context nobody meant, a package manager +// blocked on a lock held by something else — was invisible until a customer +// happened to mention it. One outcome event per invocation is what turns that +// class into a number. +// +// THE PRIVACY BOUNDARY IS STRUCTURAL, NOT EDITORIAL. The ticket's rule is "no +// arguments, no paths, no data", and a rule phrased that way is a convention +// that asks. What is built here instead is a record with no free-text channel +// at all: +// +// - the command is a LOOKUP into the set of paths enumerated from the live +// cobra tree at startup; anything else reports CommandUnregistered; +// - the error class is a lookup keyed on an INT — the CLI's own frozen +// exit-code contract — so the classifier cannot see an error message, a +// path or an argument, because it is never given one; +// - everything else is an int. +// +// A sanitiser would have to anticipate what it strips. A closed set only ever +// admits what was enumerated. That difference is why there is no redaction +// regex anywhere in this file. + +// The three terminal event names. Compile-time constants per contract §6.2 — +// no segment is ever computed. There is deliberately no cli.command.started: +// §6.5 requires a terminal event on every path where a `started` is emitted, +// and a process that is killed outright cannot honour that. +const ( + EventCommandSucceeded = "cli.command.succeeded" + EventCommandFailed = "cli.command.failed" + EventCommandCancelled = "cli.command.cancelled" +) + +// Record-scope attribute keys. tracebloc.cli.command is the contract's own name +// for this field (§7.1: "CLI command path — e.g. `data ingest`, never the +// arguments"). +const ( + AttrCommand = "tracebloc.cli.command" + AttrExitCode = "tracebloc.cli.exit_code" + AttrDurationMS = "tracebloc.cli.duration_ms" +) + +// CommandUnregistered is what a path outside the registered set reports. +// +// It is the fail-closed answer, and it is reported as a VALUE rather than by +// dropping the attribute so that "we saw a command we could not name" stays +// countable. A recorder built with no registered commands at all therefore +// reports this for everything — forgetting to register cannot silently turn the +// lookup into a pass-through. +const CommandUnregistered = "unregistered" + +// ExitCancelled is 128+SIGINT — the user pressed Ctrl-C. It is not a failure and +// must not inflate one: a cancel that counted as a failure would move the rate +// D9's alerts are written against every time someone changed their mind. +const ExitCancelled = 130 + +// The closed error.type vocabulary for the `cli` domain (contract §8.4; the +// spec's open question 1 says each emitter ticket proposes its own). +// +// DERIVED FROM THE EXIT CODES, NOT FROM THE ERROR TEXT. internal/cli/exitcodes.go +// already carries a reviewed, documented, FROZEN classification of every way the +// CLI can fail — it is the scripting contract customers branch on. Classifying +// from anywhere else would mean inventing a second taxonomy that drifts from the +// first, and would mean handing the classifier an error string, which is exactly +// the channel a path or a cell value travels down. +const ( + ClassUnspecifiedFailure = "unspecified_failure" + ClassInvalidInput = "invalid_input" + ClassLocalEnvironment = "local_environment" + ClassNoSecureEnvironment = "no_secure_environment" + ClassAuth = "auth" + ClassConflict = "conflict" + ClassClusterOperation = "cluster_operation" + ClassSubmitRejected = "submit_rejected" + ClassIngestFailed = "ingest_failed" + ClassUnclassified = "unclassified" +) + +// exitClasses maps the CLI's exit codes to that vocabulary. Several codes carry +// more than one per-command meaning (exitChecksFailed shares 2 with +// exitBadInput, exitNoSuchDataset shares 5 with exitAuth, and 7 is three +// meanings) — the class names the shared bucket, because the code is what a +// customer's script sees and grouping finer than the contract would be a +// distinction nothing downstream can act on. tracebloc.cli.command separates +// them when it matters. +var exitClasses = map[int]string{ + 1: ClassUnspecifiedFailure, + 2: ClassInvalidInput, + 3: ClassLocalEnvironment, + 4: ClassNoSecureEnvironment, + 5: ClassAuth, + 6: ClassConflict, + 7: ClassClusterOperation, + 8: ClassSubmitRejected, + 9: ClassIngestFailed, +} + +// ClassifyExit maps an exit code to a member of the closed vocabulary. +// +// Total by construction: every int has an answer, and an unmapped one is +// ClassUnclassified rather than the code rendered as a string. That is the +// fail-closed half — a code this table has not seen is a finding you can alert +// on, not a new namespace that appears on its own. +func ClassifyExit(code int) string { + if class, ok := exitClasses[code]; ok { + return class + } + return ClassUnclassified +} + +// Sink is the delivery seam. It is a named type so the wiring in internal/cli +// can say what it is handing over; Emitter.SetSink takes the same shape. +type Sink func(resource map[string]string, record map[string]any) + +// Outcome is one invocation, as measured by the caller. +type Outcome struct { + // Command is the cobra command path minus the arguments — "data ingest". + // It is not trusted: Record looks it up in the registered set and reports + // CommandUnregistered if it is not there. + Command string + // ExitCode is what the process is about to exit with. + ExitCode int + // Elapsed is wall-clock time for the invocation. + Elapsed time.Duration +} + +// OutcomeRecorder turns an Outcome into exactly one contract-conformant event. +type OutcomeRecorder struct { + emitter *Emitter + commands map[string]bool +} + +// NewOutcomeRecorder closes the tracebloc.cli.command value set over commands. +// +// The caller passes the paths enumerated from the live command tree, so the set +// is derived from the thing that actually dispatches rather than restated here. +// A command added to the tree is covered without touching this file; a value +// that is not a command in the tree cannot be emitted at all. +func NewOutcomeRecorder(e *Emitter, commands []string) *OutcomeRecorder { + set := make(map[string]bool, len(commands)) + for _, c := range commands { + if c != "" { + set[c] = true + } + } + return &OutcomeRecorder{emitter: e, commands: set} +} + +// Record emits the invocation's single terminal event. +func (r *OutcomeRecorder) Record(o Outcome) error { + name := EventCommandSucceeded + switch { + case o.ExitCode == 0: + case o.ExitCode == ExitCancelled: + name = EventCommandCancelled + default: + name = EventCommandFailed + } + + attrs := Attrs{ + AttrCommand: r.commandValue(o.Command), + AttrExitCode: o.ExitCode, + AttrDurationMS: durationMS(o.Elapsed), + } + // §8.4 — only the failure outcomes oblige the error set. Emit enforces this + // too; setting it here for a cancel would be a second, disagreeing opinion + // about what counts as a failure. + if name == EventCommandFailed { + attrs["error.type"] = ClassifyExit(o.ExitCode) + } + return r.emitter.Emit(name, attrs) +} + +// commandValue is the privacy boundary: a set membership test, not a cleanup +// pass. Whatever the caller hands over either IS one of the paths the tree can +// dispatch, or it does not reach the record in any form. +func (r *OutcomeRecorder) commandValue(path string) string { + if r.commands[path] { + return path + } + return CommandUnregistered +} + +// durationMS clamps below zero. A wall-clock delta can go negative across a +// clock step, and a negative duration is not a measurement — it is a number +// that would quietly skew every percentile computed over the column. +func durationMS(d time.Duration) int64 { + if ms := Duration(d); ms > 0 { + return ms + } + return 0 +} diff --git a/internal/telemetry/outcome_test.go b/internal/telemetry/outcome_test.go new file mode 100644 index 0000000..fe18e8c --- /dev/null +++ b/internal/telemetry/outcome_test.go @@ -0,0 +1,365 @@ +package telemetry + +import ( + "fmt" + "regexp" + "runtime" + "strings" + "testing" + "time" + + "github.com/tracebloc/cli/internal/api" +) + +// registered is the stand-in for what internal/cli enumerates from the live +// cobra tree. It is deliberately NOT the real tree here: this package must not +// know about cobra, and the tree-derived version of the same assertion lives in +// internal/cli/telemetry_test.go. +var registered = []string{"tracebloc", "data ingest", "cluster info", "login"} + +func recorderWithSink(t *testing.T) (*OutcomeRecorder, func() (map[string]string, map[string]any)) { + t.Helper() + e := New(api.EnvProd, "0.10.9", "abcdef0123456789") + var res map[string]string + var rec map[string]any + e.SetSink(func(r map[string]string, d map[string]any) { res, rec = r, d }) + return NewOutcomeRecorder(e, registered), func() (map[string]string, map[string]any) { return res, rec } +} + +// --- the event name is the outcome ------------------------------------------ + +func TestTheEventNameFollowsTheExitCode(t *testing.T) { + for _, tc := range []struct { + name string + code int + want string + }{ + {"success", 0, EventCommandSucceeded}, + {"generic failure", 1, EventCommandFailed}, + {"bad input", 2, EventCommandFailed}, + {"ingest failed", 9, EventCommandFailed}, + {"interrupted", ExitCancelled, EventCommandCancelled}, + {"a code no table knows", 77, EventCommandFailed}, + } { + t.Run(tc.name, func(t *testing.T) { + r, read := recorderWithSink(t) + if err := r.Record(Outcome{Command: "data ingest", ExitCode: tc.code}); err != nil { + t.Fatalf("Record: %v", err) + } + _, rec := read() + if rec["event.name"] != tc.want { + t.Fatalf("exit %d emitted %q, want %q", tc.code, rec["event.name"], tc.want) + } + }) + } +} + +func TestACancelIsNotAFailure(t *testing.T) { + // 130 is the user pressing Ctrl-C. Counting it as a failure moves the rate + // D9's alerts are written against every time somebody changes their mind, + // so the record must carry no error.type at all — not even an "ok" one. + r, read := recorderWithSink(t) + if err := r.Record(Outcome{Command: "login", ExitCode: ExitCancelled}); err != nil { + t.Fatalf("Record: %v", err) + } + _, rec := read() + if _, ok := rec["error.type"]; ok { + t.Fatalf("a cancel carried error.type=%v", rec["error.type"]) + } + if rec[AttrExitCode] != ExitCancelled { + t.Fatalf("the exit code was lost: %v", rec[AttrExitCode]) + } +} + +func TestEveryFailureCarriesAClassFromTheClosedVocabulary(t *testing.T) { + // DERIVED input domain: every key the production table declares, plus codes + // outside it. Mutation coverage cannot see a vocabulary gap (workspace + // CLAUDE.md rule 6), so the domain comes from the producer's own surface. + codes := []int{} + for code := range exitClasses { + codes = append(codes, code) + } + codes = append(codes, 42, 77, 255, -1) + + allowed := map[string]bool{ClassUnclassified: true} + for _, class := range exitClasses { + allowed[class] = true + } + + for _, code := range codes { + t.Run(fmt.Sprintf("exit_%d", code), func(t *testing.T) { + r, read := recorderWithSink(t) + if err := r.Record(Outcome{Command: "data ingest", ExitCode: code}); err != nil { + t.Fatalf("Record: %v", err) + } + _, rec := read() + class, ok := rec["error.type"].(string) + if !ok { + t.Fatalf("exit %d produced no error.type: %v", code, rec) + } + if !allowed[class] { + t.Fatalf("exit %d produced error.type %q, which is outside the "+ + "closed vocabulary %v", code, class, allowed) + } + }) + } +} + +func TestAnUnmappedExitCodeIsUnclassifiedNotStringified(t *testing.T) { + // Fail closed: a code the table has not seen must be a countable "we cannot + // name this", never the number rendered into a new value that appears on its + // own. Asserting WHICH answer, because "some member of the vocabulary" is + // also satisfied by returning ClassUnspecifiedFailure for everything. + if got := ClassifyExit(77); got != ClassUnclassified { + t.Fatalf("ClassifyExit(77) = %q, want %q", got, ClassUnclassified) + } + if got := ClassifyExit(2); got != ClassInvalidInput { + t.Fatalf("ClassifyExit(2) = %q, want %q — the mapped codes must still map", + got, ClassInvalidInput) + } +} + +// --- the privacy boundary ---------------------------------------------------- + +// canary is a value that could only have arrived from a user's command line. It +// is written down here, independently of anything the matcher checks — never +// iterated out of the thing under test (workspace CLAUDE.md rule 9). +const canary = "CANARY-PATIENT-7" + +func TestAnUnregisteredCommandIsReplacedNotSanitised(t *testing.T) { + // The whole ticket, in one assertion: an argument-bearing path is not + // cleaned up, it is refused. The two checks are separate on purpose — the + // "canary absent" half alone would pass if the attribute were dropped + // entirely, and the "value is unregistered" half is the mutation anchor: it + // reddens the moment commandValue stops looking the path up. + for _, path := range []string{ + "data ingest /Users/" + canary + "/oncology.csv", + "data ingest --name " + canary, + "login --token " + canary, + canary, + "", + } { + t.Run(path, func(t *testing.T) { + r, read := recorderWithSink(t) + if err := r.Record(Outcome{Command: path, ExitCode: 0}); err != nil { + t.Fatalf("Record: %v", err) + } + res, rec := read() + if rec[AttrCommand] != CommandUnregistered { + t.Fatalf("%s = %v, want %q", AttrCommand, rec[AttrCommand], CommandUnregistered) + } + assertNoCanary(t, res, rec) + }) + } +} + +func TestARegisteredCommandSurvivesIntact(t *testing.T) { + // The other half: the lookup must not become a blanket refusal, or the + // column is CommandUnregistered forever and nothing above is doing any work. + for _, path := range registered { + t.Run(path, func(t *testing.T) { + r, read := recorderWithSink(t) + if err := r.Record(Outcome{Command: path, ExitCode: 0}); err != nil { + t.Fatalf("Record: %v", err) + } + _, rec := read() + if rec[AttrCommand] != path { + t.Fatalf("%s = %v, want %q", AttrCommand, rec[AttrCommand], path) + } + }) + } +} + +func TestARecorderWithNoRegisteredCommandsFailsClosed(t *testing.T) { + // Forgetting to register must not turn the lookup into a pass-through. + e := New(api.EnvProd, "0.10.9", "abcdef0123456789") + var rec map[string]any + e.SetSink(func(_ map[string]string, d map[string]any) { rec = d }) + r := NewOutcomeRecorder(e, nil) + if err := r.Record(Outcome{Command: "data ingest", ExitCode: 0}); err != nil { + t.Fatalf("Record: %v", err) + } + if rec[AttrCommand] != CommandUnregistered { + t.Fatalf("an empty registry reported %v, want %q", rec[AttrCommand], CommandUnregistered) + } +} + +// TestEveryEmittedStringComesFromAClosedSet is the derived form of "no +// arguments, no paths, no data". +// +// It does not hold a list of forbidden keys — a list like that agrees with +// itself and says nothing about the twentieth attribute somebody adds. It walks +// what the code ACTUALLY emits and requires every value to be an int, or a +// member of a set assembled from the producer's own declarations. A free-text +// channel of any kind fails it, whether or not anyone thought to forbid the +// thing travelling down it. +func TestEveryEmittedStringComesFromAClosedSet(t *testing.T) { + allowed := map[string]bool{ + EventCommandSucceeded: true, + EventCommandFailed: true, + EventCommandCancelled: true, + CommandUnregistered: true, + ClassUnclassified: true, + } + for _, c := range registered { + allowed[c] = true + } + for _, class := range exitClasses { + allowed[class] = true + } + + // Resource values are process identity, not occurrence data: fixed strings, + // or shapes with no room for a payload. + shaped := map[string]*regexp.Regexp{ + "service.instance.id": regexp.MustCompile(`^[0-9a-f]{16}$`), + "service.version": regexp.MustCompile(`^[0-9A-Za-z.\-+]{1,32}$`), + } + fixed := map[string]string{ + "service.name": Service, + "tracebloc.component": Component, + "os.type": runtime.GOOS, + "host.arch": runtime.GOARCH, + "deployment.environment": api.EnvProd, + } + + paths := append([]string{}, registered...) + paths = append(paths, "data ingest /var/"+canary+"/rows.csv", canary, "") + codes := []int{0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 42, ExitCancelled} + + seen := 0 + for _, path := range paths { + for _, code := range codes { + r, read := recorderWithSink(t) + if err := r.Record(Outcome{ + Command: path, ExitCode: code, Elapsed: 1234 * time.Millisecond, + }); err != nil { + t.Fatalf("Record(%q, %d): %v", path, code, err) + } + res, rec := read() + + for k, v := range rec { + seen++ + switch value := v.(type) { + case int, int64: + case string: + if !allowed[value] { + t.Fatalf("record key %q carried %q, which is not in any "+ + "declared vocabulary — that is a free-text channel", k, value) + } + default: + t.Fatalf("record key %q carried %T; the record must be ints and "+ + "closed-set strings only", k, v) + } + } + for k, v := range res { + seen++ + if want, ok := fixed[k]; ok { + if v != want { + t.Fatalf("resource %q = %q, want %q", k, v, want) + } + continue + } + re, ok := shaped[k] + if !ok { + t.Fatalf("resource carries %q, which this guard has never been "+ + "taught to constrain — classify it before shipping it", k) + } + if !re.MatchString(v) { + t.Fatalf("resource %q = %q, outside %s", k, v, re) + } + } + } + } + // An inert run and full coverage look identical in a log. This is the anchor + // that says the loop above actually inspected something. + if want := len(paths) * len(codes) * 10; seen < want { + t.Fatalf("only %d attributes were inspected (expected at least %d) — the "+ + "guard ran over an empty record", seen, want) + } +} + +// --- measurements ------------------------------------------------------------- + +func TestDurationIsMillisecondsAndNeverNegative(t *testing.T) { + r, read := recorderWithSink(t) + if err := r.Record(Outcome{ + Command: "data ingest", ExitCode: 0, Elapsed: 2500 * time.Millisecond, + }); err != nil { + t.Fatalf("Record: %v", err) + } + _, rec := read() + if rec[AttrDurationMS] != int64(2500) { + t.Fatalf("%s = %v, want 2500", AttrDurationMS, rec[AttrDurationMS]) + } + + // A clock step can hand us a negative delta. A negative duration is not a + // measurement — it skews every percentile computed over the column. + r2, read2 := recorderWithSink(t) + if err := r2.Record(Outcome{ + Command: "data ingest", ExitCode: 0, Elapsed: -5 * time.Second, + }); err != nil { + t.Fatalf("Record: %v", err) + } + _, rec2 := read2() + if rec2[AttrDurationMS] != int64(0) { + t.Fatalf("a negative elapsed became %v, want 0", rec2[AttrDurationMS]) + } +} + +func TestAZeroDurationIsStillReported(t *testing.T) { + // A sub-millisecond command rounds to 0, and 0 is a measurement. §1.2's + // omit-when-absent rule must not swallow it — a command that always returns + // instantly would otherwise have no duration column at all. + r, read := recorderWithSink(t) + if err := r.Record(Outcome{Command: "tracebloc", ExitCode: 0, Elapsed: 0}); err != nil { + t.Fatalf("Record: %v", err) + } + _, rec := read() + if _, ok := rec[AttrDurationMS]; !ok { + t.Fatalf("a 0 ms duration was dropped as absent: %v", rec) + } +} + +// --- the resource layer ------------------------------------------------------- + +func TestOSAndArchAreOTelNamesInTheResourceLayer(t *testing.T) { + // §1.1 forbids re-inventing an attribute OTel already names, so these are + // os.type / host.arch and not tracebloc.os / tracebloc.arch. They are + // compile-time constants of the binary, so they belong to the process, not + // to the occurrence. + res := New(api.EnvProd, "0.10.9", "h").Resource() + if res["os.type"] != runtime.GOOS { + t.Fatalf("os.type = %q, want %q", res["os.type"], runtime.GOOS) + } + if res["host.arch"] != runtime.GOARCH { + t.Fatalf("host.arch = %q, want %q", res["host.arch"], runtime.GOARCH) + } + // …and being resource scope, a call site may not send them. The generic + // version of this assertion iterates resourceScope, so it covers these two + // automatically; this names the rule that must fire. + e := New(api.EnvProd, "0.10.9", "h") + for _, k := range []string{"os.type", "host.arch"} { + err := e.Emit(EventCommandSucceeded, Attrs{k: "impostor"}) + if err == nil { + t.Fatalf("a call site set %q", k) + } + if !strings.Contains(err.Error(), "RESOURCE scope") { + t.Fatalf("%q was refused by another rule, so the layer check is doing "+ + "no work for it: %v", k, err) + } + } +} + +func assertNoCanary(t *testing.T, res map[string]string, rec map[string]any) { + t.Helper() + for k, v := range res { + if strings.Contains(k, canary) || strings.Contains(v, canary) { + t.Fatalf("resource leaked the canary: %q = %q", k, v) + } + } + for k, v := range rec { + if strings.Contains(k, canary) || strings.Contains(fmt.Sprint(v), canary) { + t.Fatalf("record leaked the canary: %q = %v", k, v) + } + } +} diff --git a/internal/telemetry/telemetry.go b/internal/telemetry/telemetry.go index 1795053..df3689d 100644 --- a/internal/telemetry/telemetry.go +++ b/internal/telemetry/telemetry.go @@ -22,6 +22,7 @@ import ( "fmt" "reflect" "regexp" + "runtime" "sort" "strings" "time" @@ -85,10 +86,17 @@ var retired = map[string]bool{ // resourceScope is set once per process by New. A call site may never send one. // tracebloc.component is listed even though it is correctly tracebloc.-prefixed: // the namespace rule alone would wave it past. +// +// os.type and host.arch are here rather than in recordScope because they +// describe the PROCESS, not the occurrence: they are compile-time constants of +// this binary and cannot differ between two events from one run. §1.1 also +// forbids re-inventing them as tracebloc.os / tracebloc.arch — OpenTelemetry +// already names them, so the contract requires OTel's spelling. var resourceScope = map[string]bool{ "service.name": true, "service.version": true, "service.instance.id": true, "deployment.environment": true, "tracebloc.component": true, "tracebloc.tenant.id": true, + "os.type": true, "host.arch": true, } // recordScope is the set of OTel names a call site MAY send. event.name is @@ -127,6 +135,13 @@ func New(env, version, instanceID string) *Emitter { "service.name": Service, "tracebloc.component": Component, "service.version": normaliseVersion(version), + // backend#1907 asks for OS/arch on every command outcome. They are + // read from the Go build's own constants, never from `uname`, a + // hostname or an env var: a compile-time constant cannot carry a + // customer identifier, and runtime.GOOS/GOARCH are closed sets, so + // there is no value here a query cannot filter on. + "os.type": runtime.GOOS, + "host.arch": runtime.GOARCH, }} // §1.2 — omitted rather than stamped empty. os.Hostname() returns "" on // error, and an empty service.instance.id is the "sent as empty rather than diff --git a/scripts/coverage-floor.sh b/scripts/coverage-floor.sh index 723cfd3..01c9301 100755 --- a/scripts/coverage-floor.sh +++ b/scripts/coverage-floor.sh @@ -13,6 +13,12 @@ # tests. Current (develop, 2026-07-14, ubuntu CI runner): internal/cli 82.9%, # internal/submit 80.4%, internal/push 89.0%, internal/cluster 74.6%. # +# internal/telemetry joined the list with backend#1907, when it stopped being +# an unwired helper and became the thing that decides what leaves a customer's +# machine. It is the privacy boundary for the CLI, so a rotting test there is +# not a coverage regression like the others — it is the guard going quiet. It +# measures 100.0% today; the floor is set at 95 for the usual ratchet headroom. +# # NOTE: internal/cluster measures higher on a dev machine with a real # ~/.kube/config (78.5% on macOS) than on the bare CI runner (74.6%) — the # kubeconfig-resolution paths only execute where one exists. Floors must be @@ -30,6 +36,7 @@ internal/cli:80 internal/submit:78 internal/push:87 internal/cluster:73 +internal/telemetry:95 " status=0