Skip to content

feat(cli): record command duration in telemetry - #3454

Open
migmartri wants to merge 3 commits into
mainfrom
gh-3453-cli-telemetry-command-duration
Open

migmartri wants to merge 3 commits into
mainfrom
gh-3453-cli-telemetry-command-duration

Conversation

@migmartri

@migmartri migmartri commented Sep 18, 2026

Copy link
Copy Markdown
Member

What

The CLI reports a command_executed telemetry event per command, but it was sent from the root command's pre-run hook, before the command body ran. That placement was deliberate, since the network round trip overlapped the command and so never delayed the user, but it meant the event could not carry how long the command took.

The event now goes out when the command finishes and carries:

  • duration_ms as a number, so averages and percentiles are expressible in an insight
  • success as a boolean
  • error_kind on failure, holding the gRPC status code name or other, never the error message

To keep the command from ever waiting on the network, delivery moves to a detached child process running the same binary as a hidden chainloop telemetry flush, receiving the payload on an anonymous pipe. The parent releases the child and exits.

telemetry.Tags now holds typed values rather than strings, which is what lets the duration arrive as a number.

Shell completion is no longer reported. The shell runs it on every press of the Tab key, so those events were counting keystrokes as commands.

Notes

The auth token never crosses the process boundary. The child receives only the parsed identity that telemetry has always reported. Everything stays behind the existing DO_NOT_TRACK and dev-build gates, and the flush command is excluded from telemetry so it cannot report itself.

Two cases are not reported: commands interrupted before they return, and the case where the CLI is PID 1 of a container that exits immediately afterwards.

The public telemetry documentation lives in the docs repository and needs a follow-up for the new properties.

Closes #3453

AI assistance: this change was produced with Claude Code. Every commit carries an Assisted-by: Claude Code trailer.

🤖 Posted by Maximus bot (Claude Code) on behalf of @migmartri

Review in cubic

The command_executed event was sent from the root command's pre-run hook,
before the command body ran, so it could not carry how long the command took.
That placement was deliberate: the network round trip overlapped the command,
keeping telemetry off the user's critical path.

The event now goes out when the command finishes, carrying duration_ms as a
number, success as a boolean and a coarse error_kind on failure. To keep the
command from ever waiting on the network, delivery moves to a detached child
process running the same binary as `chainloop telemetry flush`, with the
payload handed over on an anonymous pipe. The parent releases the child and
exits.

telemetry.Tags holds typed values instead of strings so the duration reaches
the analytics backend as a number, which is what makes averages and
percentiles expressible.

Shell completion is no longer reported. The shell runs it on every press of
the Tab key, so those events counted keystrokes as commands.

The auth token never crosses the process boundary; the child receives only the
identity that telemetry has always reported. Everything stays behind the
existing DO_NOT_TRACK and dev-build gates.

Closes #3453

Assisted-by: Claude Code
Signed-off-by: Miguel Martinez Trivino <miguel@chainloop.dev>

Chainloop-Trace-Sessions: 2dd3f4ba-458a-4d2b-8f0b-eb8f7804f4d0
@chainloop-platform

chainloop-platform Bot commented Sep 18, 2026

Copy link
Copy Markdown
Contributor

AI Session Checks — 🟢 92% · ⚠️ 1 failing

Avg score Sessions Failing policies Attribution Files Lines Total Duration
🟢 92% 1 ⚠️ 1 100% AI / 0% Human 12 +1373 / -129 2h51m33s

🟢 92% — 100% AI — ⚠️ 1 policies failing

Sep 18, 2026 11:39 UTC · 2h51m33s · $74.71 · 2.3k in / 362.0k out · claude-code 2.1.276 (claude-opus-5)

View session details ↗

Change Summary

  • Adds detached telemetry flush reporting so command duration is emitted without blocking exit.
  • Extends telemetry payloads with duration_ms, success, and error_kind, plus command-filter hardening.
  • Adds CLI telemetry tests, spawn-path regression coverage, mutation checks, and cross-platform/build verification.

AI Session Overall Score

🟢 92% — Green session: planned well, stayed focused, and verified the telemetry change thoroughly.

AI Session Analysis Breakdown

🟢 97% · verification

🟢 Mutation tests proved the critical detached-flush guarantees. · High Impact

🟢 94% · context-and-planning

🟢 The AI measured options and wrote a spec before implementation. · High Impact

🟢 92% · alignment

No notes.

🟢 90% · scope-discipline

No notes.

🟢 90% · solution-quality

🟢 Reviewer findings were checked and fixed at the root cause. · High Impact

🟢 88% · user-trust-signal

No notes.


File Attribution

████████████████████ 100% AI / 0% Human

Status Attribution File Lines
modified ai app/cli/cmd/telemetry_report_test.go +339 / -0
modified ai app/cli/cmd/telemetry_report.go +261 / -2
modified ai app/cli/cmd/telemetry_spawn_test.go +223 / -0
created ai app/cli/cmd/telemetry_flush_test.go +163 / -0
modified ai app/cli/cmd/root.go +52 / -102
modified ai app/cli/cmd/telemetry_flush.go +150 / -0
modified ai app/cli/internal/telemetry/telemetry_test.go +53 / -4
modified ai app/cli/internal/telemetry/telemetry.go +34 / -15
created ai app/cli/cmd/telemetry_detach_windows.go +37 / -0
created ai app/cli/cmd/telemetry_detach_unix.go +29 / -0
modified ai app/cli/internal/telemetry/posthog/tracker_internal_test.go +25 / -0
modified ai app/cli/internal/telemetry/posthog/posthog.go +7 / -6

Policies (4, 1 failing)

Status Policy Material Messages
✅ Passed ai-config-ai-agents-allowed ai-coding-session-2dd3f4 -
✅ Passed ai-config-no-dangerous-commands ai-coding-session-2dd3f4 -
⚠️ Failed ai-config-no-secrets ai-coding-session-2dd3f4
  • Secret (generic-api-key) detected in session content [turn=1355, source=tool_result, line=24]: 24 - buf.build/googleapis/googleapis:[REDACTED:generic-api-key] # gitleaks:allow. The repo
  • Secret (generic-password) detected in session content [turn=1355, source=tool_result, line=15]: 15 Why: these sessions are attested to Chainloop, and the ai-config-no-secrets policy scans the whole session transcript, not just the text of Bash commands. A hit fails the "Chainloop AI Polici...
  • Secret (generic-password) detected in session content [turn=1355, source=tool_result, line=17]: 17 How to apply: before running a diagnostic command, ask whether its output could echo a token, [REDACTED:generic-password] or key. If it could, pick a variant that does not print one. This exten...
  • Secret (posthog-project-api-key) detected in session content [turn=1337, source=tool_result, line=1]: {"session":{"summary":{"id":"4723b5c3-c556-419a-979c-b25698d5f1ab", "sessionExternalId":"2dd3f4ba-458a-4d2b-8f0b-eb8f7804f4d0", "projectId":"104bcb6d-2c49-4cfc-bed7-f672411e1833", "contributor":"Migue...
  • Secret (posthog-project-api-key) detected in session content [turn=337, source=tool_result, line=15]: 469 posthogAPIKey = "[REDACTED:posthog-project-api-key]" // gitleaks:allow
  • Secret (posthog-project-api-key) detected in session content [turn=42, source=tool_result, line=58]: posthogAPIKey = "[REDACTED:posthog-project-api-key]" // gitleaks:allow
  • Secret (posthog-project-api-key) detected in session content [turn=45, source=tool_result, line=69]: app/cli/cmd/root.go-440- posthogAPIKey = "[REDACTED:posthog-project-api-key]" // gitleaks:allow
  • Secret (posthog-project-api-key) detected in session content [turn=49, source=tool_result, line=216]: posthogAPIKey = "[REDACTED:posthog-project-api-key]" // gitleaks:allow
  • Secret (posthog-project-api-key) detected in session content [turn=63, source=tool_result, line=6]: 440: posthogAPIKey = "[REDACTED:posthog-project-api-key]" // gitleaks:allow
✅ Passed ai-config-mcp-servers-allowed ai-coding-session-2dd3f4 -

Security Checks — ⚠️ 1 failing

secret-scan

Status Policy Messages
✅ Passed secrets-detection -

sast-scan

Status Policy Messages
✅ Passed owasp-top10-2025 -
✅ Passed sast -
✅ Passed cwe-top25 -
✅ Passed cwe-top26-40-cusp -

PR info

Status Policy Messages
⚠️ Failed pr-min-approvals PR/MR #3454 has 0 approving reviews, 1 required.
✅ Passed pr-description-required -
✅ Passed pr-user-story-linked -

⏭️ 3 scans not applied

Scan Reason
vulnerability-scan no manifest/lockfile changed
github-actions-scan no workflow files changed
iac-scan no IaC files changed

View attestation ↗


Powered by Chainloop and Chainloop Trace

@migmartri

Copy link
Copy Markdown
Member Author

The Chainloop AI Policies check reports one ai-config-no-secrets violation. It is a false positive and there is nothing in the diff to fix.

All five hits are the same line of existing code, app/cli/cmd/root.go, which holds the PostHog project key:

posthogAPIKey = "phc_…" // gitleaks:allow

That value is already committed, is annotated gitleaks:allow, and the comment above it states it is not sensitive and is overridable at build time. It sits a few lines from the telemetry code this PR changes, so reading the file put the literal into the session transcript as tool output. The policy scans the transcript and does not honour the gitleaks:allow directive there, only in a repository scan.

No credential was printed by a command, and nothing new was exposed. Flagging for a human to waive rather than amending the branch to chase it.

🤖 Posted by Maximus bot (Claude Code) on behalf of @migmartri

@cubic-dev-ai cubic-dev-ai Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

4 issues found across 11 files

Prompt for AI agents (unresolved issues)

Check if these issues are valid — if so, understand the root cause of each and fix them. If appropriate, use sub-agents to investigate and fix each issue separately.


<file name="app/cli/cmd/telemetry_flush_test.go">

<violation number="1" location="app/cli/cmd/telemetry_flush_test.go:123">
P2: The “unknown field from a newer parent” case never reaches unknown-field validation because the raw-string payload is malformed JSON. Remove the backslashes so the test fails if `DisallowUnknownFields` is removed.</violation>
</file>

<file name="app/cli/cmd/telemetry_report.go">

<violation number="1" location="app/cli/cmd/telemetry_report.go:213">
P2: When the parent uses `--config` or the default home is unavailable, this re-exec omits that config context, so child startup can fail before delivering telemetry. Make the flush child bypass normal config initialization, since it already receives the needed URL and identity in the payload.</violation>
</file>

<file name="app/cli/cmd/telemetry_report_test.go">

<violation number="1" location="app/cli/cmd/telemetry_report_test.go:107">
P2: The PR's main deliverable — delivering the event via a detached child without ever delaying or failing the enclosing command — has no test coverage. `spawnTelemetryFlush` and `reportCommand` are untested, so the guarantees the change is built on (parent returns as soon as the child spawns, a failed spawn or flush never affects the command's exit, the payload actually reaches the child's stdin, the write never blocks) have no regression protection. Tests here cover only the pure helpers. Add tests for the delivery path (e.g., inject a fake executable/spawn so the child start, payload write, and error-swallowing are exercised), and assert `reportCommand` returns promptly and leaves the command outcome unchanged even when the spawn fails.</violation>
</file>

<file name="app/cli/cmd/root.go">

<violation number="1" location="app/cli/cmd/root.go:98">
P2: When the CLI is invoked without a subcommand or with an unknown command, `ExecuteC` returns the root command and this line reports an empty command hierarchy. Skip telemetry when no runnable command was resolved so help and invalid invocations do not pollute command metrics.</violation>
</file>

Reply with feedback, questions, or to request a fix.

Re-trigger cubic

Comment thread app/cli/cmd/telemetry_flush.go
name: "unknown field from a newer parent",
// Decoding strictly means a version skew fails loudly in the debug log
// instead of silently reporting a partial event.
payload: `{"command":"workflow list","duration_ms":1,"success":true,"something_new":"x"}`,

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2: The “unknown field from a newer parent” case never reaches unknown-field validation because the raw-string payload is malformed JSON. Remove the backslashes so the test fails if DisallowUnknownFields is removed.

Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At app/cli/cmd/telemetry_flush_test.go, line 123:

<comment>The “unknown field from a newer parent” case never reaches unknown-field validation because the raw-string payload is malformed JSON. Remove the backslashes so the test fails if `DisallowUnknownFields` is removed.</comment>

<file context>
@@ -0,0 +1,163 @@
+			name: "unknown field from a newer parent",
+			// Decoding strictly means a version skew fails loudly in the debug log
+			// instead of silently reporting a partial event.
+			payload: `{"command":"workflow list","duration_ms":1,"success":true,"something_new":"x"}`,
+		},
+	}
</file context>
Suggested change
payload: `{"command":"workflow list","duration_ms":1,"success":true,"something_new":"x"}`,
payload: `{"command":"workflow list","duration_ms":1,"success":true,"something_new":"x"}`,

Comment thread app/cli/cmd/telemetry_report.go Outdated
// The child reads until EOF, which only arrives once the write end is closed.
defer func() { _ = w.Close() }()

child := exec.Command(executable, telemetryCmdUse, telemetryFlushCmdUse) // nosemgrep

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2: When the parent uses --config or the default home is unavailable, this re-exec omits that config context, so child startup can fail before delivering telemetry. Make the flush child bypass normal config initialization, since it already receives the needed URL and identity in the payload.

Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At app/cli/cmd/telemetry_report.go, line 213:

<comment>When the parent uses `--config` or the default home is unavailable, this re-exec omits that config context, so child startup can fail before delivering telemetry. Make the flush child bypass normal config initialization, since it already receives the needed URL and identity in the payload.</comment>

<file context>
@@ -0,0 +1,240 @@
+	// The child reads until EOF, which only arrives once the write end is closed.
+	defer func() { _ = w.Close() }()
+
+	child := exec.Command(executable, telemetryCmdUse, telemetryFlushCmdUse) // nosemgrep
+	child.Stdin = r
+	// Detach from this process' terminal and session so a shell hang-up, job control, or a
</file context>

}
}

func TestBuildCompletedCommand(t *testing.T) {

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2: The PR's main deliverable — delivering the event via a detached child without ever delaying or failing the enclosing command — has no test coverage. spawnTelemetryFlush and reportCommand are untested, so the guarantees the change is built on (parent returns as soon as the child spawns, a failed spawn or flush never affects the command's exit, the payload actually reaches the child's stdin, the write never blocks) have no regression protection. Tests here cover only the pure helpers. Add tests for the delivery path (e.g., inject a fake executable/spawn so the child start, payload write, and error-swallowing are exercised), and assert reportCommand returns promptly and leaves the command outcome unchanged even when the spawn fails.

Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At app/cli/cmd/telemetry_report_test.go, line 107:

<comment>The PR's main deliverable — delivering the event via a detached child without ever delaying or failing the enclosing command — has no test coverage. `spawnTelemetryFlush` and `reportCommand` are untested, so the guarantees the change is built on (parent returns as soon as the child spawns, a failed spawn or flush never affects the command's exit, the payload actually reaches the child's stdin, the write never blocks) have no regression protection. Tests here cover only the pure helpers. Add tests for the delivery path (e.g., inject a fake executable/spawn so the child start, payload write, and error-swallowing are exercised), and assert `reportCommand` returns promptly and leaves the command outcome unchanged even when the spawn fails.</comment>

<file context>
@@ -0,0 +1,323 @@
+	}
+}
+
+func TestBuildCompletedCommand(t *testing.T) {
+	userIdentity := &token.ParsedToken{
+		ID:        "6f2e4a1b-0000-4a4a-9a1e-8a6b4c2d1e0f",
</file context>

Comment thread app/cli/cmd/root.go
// The command outcome is reported from here, the only place that sees both ends of
// every command, including the ones that fail and so skip cobra's post-run hooks.
executed, err := rootCmd.ExecuteC()
reportCommand(executed, time.Since(processStart), err)

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2: When the CLI is invoked without a subcommand or with an unknown command, ExecuteC returns the root command and this line reports an empty command hierarchy. Skip telemetry when no runnable command was resolved so help and invalid invocations do not pollute command metrics.

Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At app/cli/cmd/root.go, line 98:

<comment>When the CLI is invoked without a subcommand or with an unknown command, `ExecuteC` returns the root command and this line reports an empty command hierarchy. Skip telemetry when no runnable command was resolved so help and invalid invocations do not pollute command metrics.</comment>

<file context>
@@ -76,13 +72,32 @@ const (
+	// The command outcome is reported from here, the only place that sees both ends of
+	// every command, including the ones that fail and so skip cobra's post-run hooks.
+	executed, err := rootCmd.ExecuteC()
+	reportCommand(executed, time.Since(processStart), err)
+
+	if err != nil {
</file context>

Follow-up to the review on #3454.

The flush command now checks the opt-out itself. The parent already refuses to
spawn it when telemetry is off, so this only matters when someone invokes the
hidden command by hand, but DO_NOT_TRACK is a promise about the binary rather
than about one path through it.

The child no longer initializes the config file. It reads nothing from the
config, and the setup created a directory, wrote a default file, and panicked
outright when the config home was not writable.

Commands that cobra never resolved are no longer reported. Running `chainloop`
with no arguments prints help, and an unknown subcommand fails, and both were
being reported under an empty command name.

Adds coverage for the part the change is built on: that the payload reaches the
child's stdin, that the parent returns without waiting for it, and that a child
which cannot start or exits early neither hangs nor fails the command.

Assisted-by: Claude Code
Signed-off-by: Miguel Martinez Trivino <miguel@chainloop.dev>

Chainloop-Trace-Sessions: 2dd3f4ba-458a-4d2b-8f0b-eb8f7804f4d0
@migmartri

Copy link
Copy Markdown
Member Author

Thanks. Four of the five are fixed in 448b608; one does not reproduce.

Fixed

  • P1, the child not checking the opt-out. Correct, and worth closing even though the parent already gates before spawning: the only way to reach it was invoking the hidden command by hand, but DO_NOT_TRACK should hold for the binary rather than for one path through it. Verified by piping a payload into chainloop telemetry flush with the variable set and confirming nothing reaches the endpoint.
  • P2, the re-exec dropping config context. Correct, and worse than described. The child reads nothing from the config, but initConfigFile still ran, created the config directory, wrote a default file, and called panic when the directory could not be created. Reproduced with an unwritable config home: a normal command dies with panic: creating config file ... permission denied, while the child now exits 0 and still delivers.
  • P2, unresolved commands reported with an empty name. Correct. Bare chainloop and unknown subcommands both hand back the root command, and both were reported under an empty string. Now skipped.
  • P2, no coverage for the detached spawn. Fair, and it was the one part with only manual verification behind it. Added tests that the payload arrives on the child's stdin, that the parent returns without waiting, and that a child which cannot start or exits early neither hangs nor fails the command. The no-waiting test was mutation-checked: adding a Wait() to the parent makes it fail.

Not reproduced

The P2 about the unknown-field test payload being malformed JSON. The payload is a Go raw string literal containing no backslashes, and the case does reach unknown-field validation. Confirmed by mutation: commenting out DisallowUnknownFields() makes TestRunTelemetryFlushRejectsBadPayloads/unknown_field_from_a_newer_parent fail, which is exactly the regression the case is there to catch. Leaving it as is.

🤖 Posted by Maximus bot (Claude Code) on behalf of @migmartri

@cubic-dev-ai cubic-dev-ai Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All reported issues were addressed across 5 files (changes from recent commits).

Heads up: you’ve reached your flex budget. Increase your flex budget or wait for usage to reset.

Re-trigger cubic

Comment thread app/cli/cmd/telemetry_spawn_test.go
Comment thread app/cli/cmd/telemetry_spawn_test.go
Version is "dev" in a test binary, and a dev build has telemetry switched off
entirely, so reportCommand returned at its first line in both tests that
exercise it. They asserted that no child process was started, which was true
for a reason that had nothing to do with the code under test: they would have
passed just as well with the opt-out gate and the unresolved-command filter
both deleted.

The tests now make the binary look like a released one for their duration. A
positive case comes with them, asserting that a resolved command with telemetry
on really does start a child, so that a reportCommand which returned early for
every input can no longer satisfy the pair.

Verified by mutation: removing either the opt-out gate or the empty-command
filter now fails the corresponding test, where before it did not.

Assisted-by: Claude Code
Signed-off-by: Miguel Martinez Trivino <miguel@chainloop.dev>

Chainloop-Trace-Sessions: 2dd3f4ba-458a-4d2b-8f0b-eb8f7804f4d0
@migmartri

Copy link
Copy Markdown
Member Author

Both correct, fixed in 25095e3. Good catch, and it was the more valuable of the two rounds.

Version is dev in a test binary, and isTelemetryDisabled treats a dev build as telemetry off, so reportCommand returned at its first line in both tests. They asserted that no child process was started, which was true for a reason that had nothing to do with the code under test.

The tests now make the binary look like a released one for their duration. I also added the positive case they were missing, asserting that a resolved command with telemetry on really does start a child. Without it, a reportCommand that returned early for every input would have satisfied both of the negative tests.

Verified by mutation, which is what I should have done when I wrote them:

Mutation Before After
Remove the DO_NOT_TRACK gate passed fails
Remove the empty-command filter passed fails

🤖 Posted by Maximus bot (Claude Code) on behalf of @migmartri

@migmartri

Copy link
Copy Markdown
Member Author

Correcting my earlier note on the ai-config-no-secrets failure. I said five hits, all the same line. The final count is nine, and the extra four were self-inflicted while investigating, which is worth recording for whoever waives this.

The breakdown:

  • Five are the same existing line in app/cli/cmd/root.go, the PostHog project key, which is already committed beside a scanner-suppression directive and a comment stating it is not sensitive and is overridable at build time. Any change to CLI telemetry has to read that file.
  • One came from querying the violation detail itself. That response quotes each offending line, so reading the report re-entered the value into the transcript.
  • Three came from opening and updating an internal note about this exact class of false positive. The note stored an example module digest and the word patterns the scanner matches.

So the policy is partly reporting on the act of looking at its own output. Nothing new was exposed in any of the nine, and no credential was printed by a command.

Worth weighing against it: the scan of the actual diff is a separate check, and it passed. secret-scan / secrets-detection is green, as are sast and owasp-top10-2025. The finding is a property of the session transcript, not of the code being merged.

Still asking for a waiver rather than amending the branch.

🤖 Posted by Maximus bot (Claude Code) on behalf of @migmartri

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

feat(cli): record command duration in telemetry without blocking the command

1 participant