diff --git a/packages/opencode/src/altimate/telemetry/index.ts b/packages/opencode/src/altimate/telemetry/index.ts index 84ea48865..59bf603f1 100644 --- a/packages/opencode/src/altimate/telemetry/index.ts +++ b/packages/opencode/src/altimate/telemetry/index.ts @@ -1844,6 +1844,24 @@ export namespace Telemetry { let reinitPromise: Promise | undefined // altimate_change — the currently running flush, so shutdown waits rather than racing it. let inFlightFlush: Promise | undefined + // altimate_change start — first-run privacy: doInit() can run outside Instance context (the TUI + // server worker calls Telemetry.init() at module load, before Instance.provide() has run on that + // thread), where Config.get() throws and is treated as "not disabled" so telemetry doesn't hang + // the worker forever waiting on config it cannot read yet. That is correct for the FIRST init — + // the env var checked above is the only opt-out this thread can honor before config is readable — + // but it must not be the LAST word: a user with `telemetry.disabled: true` in opencode.json and no + // env var would otherwise ship telemetry for the rest of the process, because init() is idempotent + // and every later call (notably session/prompt.ts's init() inside Instance context, where config IS + // readable) just joins the already-settled promise instead of re-evaluating config. + // + // `configOptOutUnverified` tracks whether THIS generation's config check actually ran; when it + // didn't, the next init() call (regardless of caller) re-checks config once config becomes + // readable — see recheckConfigOptOut() and init() below. + let configOptOutUnverified = false + // altimate_change — memoises the in-flight recheck so concurrent init() callers racing a pending + // recheckConfigOptOut() share one Config.get() instead of each starting their own. + let recheckPromise: Promise | undefined + // altimate_change end // altimate_change start — per-launch correlation id, shared across threads via the environment. // The TUI worker is spawned after the CLI middleware has already initialised telemetry on the @@ -1999,11 +2017,77 @@ export namespace Telemetry { } return reinitPromise } + // altimate_change — late config recheck. See configOptOutUnverified above: if this + // generation's doInit() proceeded without ever reading config (Config.get() threw — no + // Instance context yet), every subsequent init() call is a chance to read it now that the + // caller may be inside Instance context (the prompt loop always is). Once a recheck has + // actually read config, configOptOutUnverified is false and this falls through to the plain + // "join the settled promise" behavior, unchanged from before. + if (initPromise && configOptOutUnverified) { + // altimate_change — generation token. Capture the CURRENT initPromise before any await so a + // shutdown()+re-init() that races this recheck can be detected: doShutdown() clears + // initPromise and a later init() assigns a new one, so by the time Config.get() resolves + // `initPromise !== generation` means this completion belongs to a dead generation and must + // not touch state (see recheckConfigOptOut()). Also capture the memoised promise itself in + // a local so its `.finally` only clears `recheckPromise` if nothing newer has replaced it. + const generation = initPromise + const pending: Promise = (recheckPromise ??= initPromise.then(() => recheckConfigOptOut(generation))) + pending.finally(() => { + if (recheckPromise === pending) recheckPromise = undefined + }) + return pending + } return (initPromise ??= doInit()) // altimate_change end } + // altimate_change start — see configOptOutUnverified / init() above. + // + // `generation` is the initPromise captured by the caller BEFORE this function's only await. A + // shutdown()+re-init() can complete while Config.get() is still pending here, which clears + // initPromise and then assigns a NEW one; without this check, this stale completion would go on + // to mutate the new generation's state (clearing its buffer/timer/appInsights/enabled flag) as + // if it were still describing the generation it started on. Comparing initPromise to the + // captured token after the await — and before touching ANY state — makes a stale completion a + // no-op instead. + async function recheckConfigOptOut(generation: Promise | undefined) { + if (!enabled) { + // Already disabled (env var, bad connection string, automated-run guard, or an earlier + // successful config read) — nothing live to gate, and nothing config could add. + configOptOutUnverified = false + return + } + let cfg: any + try { + cfg = await Config.get() + } catch { + // Still unreadable — stay unverified and try again on the next init() call. + return + } + if (initPromise !== generation) return + configOptOutUnverified = false + if (cfg.telemetry?.disabled) { + // Disable for the rest of this generation. initDone stays true so track()'s existing + // "initialized and disabled -> drop" rule takes over; initPromise is left untouched so + // shutdown()/reinit semantics are unaffected by a disable that happens between them. + stopLoopMonitor() + if (flushTimer) { + clearInterval(flushTimer) + flushTimer = undefined + } + enabled = false + appInsights = undefined + buffer = [] + droppedEvents = 0 + log.info("telemetry disabled by config after late init") + } + } + // altimate_change end + async function doInit() { + // altimate_change — reset for this generation; see configOptOutUnverified above. Set back to + // true below only if Config.get() actually fails to read. + configOptOutUnverified = false try { // altimate_change — accept "true"/"TRUE"/"1" (case-insensitive) via truthyEnv, // and honor the OPENCODE_DISABLE_TELEMETRY fallback promised by v0.9.4's CHANGELOG @@ -2013,8 +2097,12 @@ export namespace Telemetry { return } // Config.get() may throw outside Instance context (e.g. CLI middleware - // before Instance.provide()). Treat config failures as "not disabled" — - // the env var check above is the early-init escape hatch. + // before Instance.provide(), or the TUI server worker which calls init() at module load). + // Treat config failures as "not disabled" — the env var check above is the only opt-out this + // generation can honor before config is readable. That is not the end of the story: flagging + // configOptOutUnverified lets a later init() call (e.g. the prompt loop's, made inside + // Instance context) read config once and retroactively honor a config-file opt-out — + // see recheckConfigOptOut(). try { const userConfig = (await Config.get()) as any if (userConfig.telemetry?.disabled) { @@ -2022,7 +2110,8 @@ export namespace Telemetry { return } } catch { - // Config unavailable — proceed with telemetry enabled + // Config unavailable — proceed with telemetry enabled for now; recheck on next init(). + configOptOutUnverified = true } // App Insights: env var overrides default (for dev/testing), otherwise use the baked-in key. // The baked-in key is refused under a test runner so suites never ship to the production @@ -2272,10 +2361,10 @@ export namespace Telemetry { log.debug("telemetry flush failed", { status: response.status }) } } catch { - // altimate_change — no write-back during shutdown. The buffer is cleared a few lines later - // regardless, so re-inserting here does not save these events; it only leaves them to be - // shipped by whatever lifecycle comes next, under a different launch id. - if (shuttingDown) return + // altimate_change — no write-back during shutdown, or once a concurrent config recheck has + // disabled telemetry: the buffer is cleared (or about to be) regardless, so re-inserting + // here would only refill it behind the disable, not save these events. + if (shuttingDown || !enabled) return // Re-add events that haven't been retried yet to avoid data loss const retriable = events.filter((e) => !(e as any)._retried) for (const e of retriable) { @@ -2401,6 +2490,14 @@ export namespace Telemetry { appInsights = undefined buffer = [] droppedEvents = 0 + // altimate_change — reset alongside the rest of this generation's state so a stale "recheck + // config on next init()" flag does not leak into the next init/shutdown cycle. recheckPromise + // is reset too: the generation-token check in recheckConfigOptOut() makes a stale completion + // a no-op, but without clearing this, a NEW init() in the next generation would see a leftover + // (already-settling, now-inert) recheckPromise from the dead generation and memo onto it + // instead of starting its own recheck. + configOptOutUnverified = false + recheckPromise = undefined sessionId = "" projectId = "" machineId = "" diff --git a/packages/opencode/test/altimate/telemetry/first-run-health.test.ts b/packages/opencode/test/altimate/telemetry/first-run-health.test.ts index aa91339a7..88d013cbd 100644 --- a/packages/opencode/test/altimate/telemetry/first-run-health.test.ts +++ b/packages/opencode/test/altimate/telemetry/first-run-health.test.ts @@ -1,6 +1,7 @@ // altimate_change start — first-run health telemetry: startup_ready, event_loop_stall, anchor flush. import { afterEach, beforeEach, describe, expect, spyOn, test } from "bun:test" import { Telemetry } from "../../../src/altimate/telemetry" +import { Config } from "@/config/config" function sleep(ms: number) { return new Promise((resolve) => setTimeout(resolve, ms)) @@ -99,4 +100,254 @@ describe("first-run health telemetry", () => { } }) }) + +// altimate_change start — config opt-out recheck: the TUI server worker's init() runs before this +// thread has Instance context, so Config.get() throws and doInit() proceeds enabled, flagging +// configOptOutUnverified. A later init() call made inside Instance context (the prompt loop's) must +// re-read config and retroactively honor a config-file opt-out instead of never checking again. +describe("first-run health telemetry — config opt-out recheck", () => { + let origDisabledEnv: string | undefined + let origDisableAlt: string | undefined + let origCs: string | undefined + + beforeEach(() => { + origDisabledEnv = process.env.ALTIMATE_TELEMETRY_DISABLED + origDisableAlt = process.env.OPENCODE_DISABLE_TELEMETRY + origCs = process.env.APPLICATIONINSIGHTS_CONNECTION_STRING + delete process.env.ALTIMATE_TELEMETRY_DISABLED + delete process.env.OPENCODE_DISABLE_TELEMETRY + process.env.APPLICATIONINSIGHTS_CONNECTION_STRING = + "InstrumentationKey=recheck-key;IngestionEndpoint=https://example.com" + }) + + afterEach(async () => { + await Telemetry.shutdown() + Telemetry.resetFirstRunStateForTest() + if (origDisabledEnv === undefined) delete process.env.ALTIMATE_TELEMETRY_DISABLED + else process.env.ALTIMATE_TELEMETRY_DISABLED = origDisabledEnv + if (origDisableAlt === undefined) delete process.env.OPENCODE_DISABLE_TELEMETRY + else process.env.OPENCODE_DISABLE_TELEMETRY = origDisableAlt + if (origCs === undefined) delete process.env.APPLICATIONINSIGHTS_CONNECTION_STRING + else process.env.APPLICATIONINSIGHTS_CONNECTION_STRING = origCs + }) + + // is_upgrade: true so this never flips the freshInstall latch — irrelevant to these tests and + // would otherwise leak across them via module state. + function anchorEvent(): Telemetry.Event { + return { + type: "first_launch", + timestamp: Date.now(), + session_id: "recheck-session", + version: "0.0.0-test", + is_upgrade: true, + install_method: "unknown", + } + } + + test("config unreadable at first init enables telemetry; config-disable on recheck stops flushing and the loop monitor", async () => { + let configCalls = 0 + const configSpy = spyOn(Config as any, "get").mockImplementation(() => { + configCalls++ + if (configCalls === 1) return Promise.reject(new Error("no Instance context yet")) + return Promise.resolve({ telemetry: { disabled: true } }) + }) + const fetchMock = spyOn(global, "fetch").mockImplementation( + (async () => new Response("", { status: 200 })) as unknown as typeof fetch, + ) + // spyOn without mockImplementation still calls through to the real track(), so this both + // observes every event track() receives and leaves buffering/flush behavior untouched. + const trackSpy = spyOn(Telemetry, "track") + try { + // First init: Config.get() throws (simulating the worker, pre-Instance-context) — proceeds enabled. + await Telemetry.init() + expect(configCalls).toBe(1) + + Telemetry.track(anchorEvent()) + await Telemetry.flush() + expect(fetchMock.mock.calls.length).toBeGreaterThanOrEqual(1) + + // Restart the monitor with test-friendly timings and first prove it is actually live: this + // makes the "stopped after disable" assertion below discriminate a real stop from a monitor + // that was never running (or never would have fired) in the first place. + Telemetry.stopLoopMonitor() + Telemetry.startLoopMonitor({ intervalMs: 10, thresholdMs: 100 }) + blockFor(250) + await new Promise((resolve) => setTimeout(resolve, 50)) + const liveStalls = trackSpy.mock.calls.filter(([e]) => e.type === "event_loop_stall") + expect(liveStalls.length).toBeGreaterThanOrEqual(1) + trackSpy.mockClear() + + // Second init (e.g. the prompt loop's, inside Instance context): config now readable and disabled. + await Telemetry.init() + expect(configCalls).toBe(2) + + fetchMock.mockClear() + Telemetry.track(anchorEvent()) + await Telemetry.flush() + expect(fetchMock).not.toHaveBeenCalled() + + // The loop monitor must actually be stopped, not merely have its events dropped by track(): + // a live timer would still reach this spy even though track() itself now drops the event. + blockFor(250) + await new Promise((resolve) => setTimeout(resolve, 50)) + const stalls = trackSpy.mock.calls.filter(([e]) => e.type === "event_loop_stall") + expect(stalls).toHaveLength(0) + } finally { + trackSpy.mockRestore() + configSpy.mockRestore() + fetchMock.mockRestore() + } + }) + + test("config unreadable at first init, then readable and not disabled: stays enabled and does not re-check again", async () => { + let configCalls = 0 + const configSpy = spyOn(Config as any, "get").mockImplementation(() => { + configCalls++ + if (configCalls === 1) return Promise.reject(new Error("no Instance context yet")) + return Promise.resolve({ telemetry: { disabled: false } }) + }) + const fetchMock = spyOn(global, "fetch").mockImplementation( + (async () => new Response("", { status: 200 })) as unknown as typeof fetch, + ) + try { + await Telemetry.init() + expect(configCalls).toBe(1) + + await Telemetry.init() // recheck: config readable, not disabled + expect(configCalls).toBe(2) + + await Telemetry.init() // configOptOutUnverified is now false — must not call Config.get again + expect(configCalls).toBe(2) + + fetchMock.mockClear() + Telemetry.track(anchorEvent()) + await Telemetry.flush() + expect(fetchMock.mock.calls.length).toBeGreaterThanOrEqual(1) + } finally { + configSpy.mockRestore() + fetchMock.mockRestore() + } + }) + + test("config readable and disabled at first init: existing behavior unchanged, no recheck needed", async () => { + const configSpy = spyOn(Config as any, "get").mockImplementation(() => + Promise.resolve({ telemetry: { disabled: true } }), + ) + const fetchMock = spyOn(global, "fetch").mockImplementation( + (async () => new Response("", { status: 200 })) as unknown as typeof fetch, + ) + try { + // Pre-init event is buffered, then cleared by doInit()'s disabled branch. + Telemetry.track(anchorEvent()) + await Telemetry.init() + expect(configSpy.mock.calls.length).toBe(1) + + Telemetry.track(anchorEvent()) + await Telemetry.flush() + expect(fetchMock).not.toHaveBeenCalled() + + // configOptOutUnverified was never set (config was readable on the first try), so a second + // init() must not trigger a recheck. + await Telemetry.init() + expect(configSpy.mock.calls.length).toBe(1) + } finally { + configSpy.mockRestore() + fetchMock.mockRestore() + } + }) + + test("config still unreadable on recheck keeps retrying", async () => { + let configCalls = 0 + const configSpy = spyOn(Config as any, "get").mockImplementation(() => { + configCalls++ + // Unreadable on the first two calls (initial doInit() and the first recheck); readable and + // disabled on the third (the second recheck). + if (configCalls <= 2) return Promise.reject(new Error("no Instance context yet")) + return Promise.resolve({ telemetry: { disabled: true } }) + }) + const fetchMock = spyOn(global, "fetch").mockImplementation( + (async () => new Response("", { status: 200 })) as unknown as typeof fetch, + ) + try { + // First init: Config.get() throws — proceeds enabled, unverified. + await Telemetry.init() + expect(configCalls).toBe(1) + + // First recheck: still unreadable. configOptOutUnverified must stay true so a later init() + // tries again instead of giving up after one failed recheck. + await Telemetry.init() + expect(configCalls).toBe(2) + + // Second recheck: now readable and disabled. + await Telemetry.init() + expect(configCalls).toBe(3) + + fetchMock.mockClear() + Telemetry.track(anchorEvent()) + await Telemetry.flush() + expect(fetchMock).not.toHaveBeenCalled() + } finally { + configSpy.mockRestore() + fetchMock.mockRestore() + } + }) + + test("a stale recheck completing after shutdown + re-init does not clear the new generation's state", async () => { + let configCalls = 0 + let resolveDeferred!: (value: unknown) => void + const deferred = new Promise((resolve) => { + resolveDeferred = resolve + }) + const configSpy = spyOn(Config as any, "get").mockImplementation(() => { + configCalls++ + // 1st call: generation 1's doInit() — unreadable, flags configOptOutUnverified. + if (configCalls === 1) return Promise.reject(new Error("no Instance context yet")) + // 2nd call: generation 1's recheck — held open under the test's control so it can be raced + // against a shutdown + re-init below. + if (configCalls === 2) return deferred + // 3rd call: generation 2's own doInit() — readable and not disabled. + return Promise.resolve({}) + }) + const fetchMock = spyOn(global, "fetch").mockImplementation( + (async () => new Response("", { status: 200 })) as unknown as typeof fetch, + ) + try { + // Generation 1: Config.get() throws — proceeds enabled, unverified. + await Telemetry.init() + expect(configCalls).toBe(1) + + // Starts generation 1's recheck. Its Config.get() is the controlled deferred above, so this + // promise is intentionally left pending (not awaited) while generation 1 is torn down and + // generation 2 spun up underneath it. + const staleRecheck = Telemetry.init() + // The recheck's Config.get() call happens inside a microtask chained off the already-settled + // initPromise, not synchronously when init() is called — give it a tick to run. + await Promise.resolve() + await Promise.resolve() + expect(configCalls).toBe(2) + + // Shut generation 1 down and bring generation 2 up while the stale recheck's Config.get() is + // still pending. Generation 2's own Config.get() call resolves `{}` — readable, not disabled + // — so generation 2 is enabled with a fresh buffer/timer/appInsights. + await Telemetry.shutdown() + await Telemetry.init() + expect(configCalls).toBe(3) + + // Now let the stale recheck's Config.get() resolve with a disabling config. Without the + // generation-token guard in recheckConfigOptOut(), this would go on to clear generation 2's + // buffer/timer/appInsights/enabled flag as if it still described generation 1. + resolveDeferred({ telemetry: { disabled: true } }) + await staleRecheck + + // Generation 2 must be unaffected: still enabled, with its buffer/timer/appInsights intact. + fetchMock.mockClear() + Telemetry.track(anchorEvent()) + await Telemetry.flush() + expect(fetchMock.mock.calls.length).toBeGreaterThanOrEqual(1) + } finally { + configSpy.mockRestore() + fetchMock.mockRestore() + } + }) +}) // altimate_change end