diff --git a/src/instrumentation/EVENTS.md b/src/instrumentation/EVENTS.md index a3186665da..ef0814813d 100644 --- a/src/instrumentation/EVENTS.md +++ b/src/instrumentation/EVENTS.md @@ -474,8 +474,8 @@ success or termination). Emitted by `WorkspaceOperationTelemetry` (start and update), `WorkspaceOpenTelemetry` (open, picker, dev container), and -`WorkspaceStateTelemetry` / `WorkspaceAgentTelemetry` (the state-transition -logs). +`recordWorkspaceState` / `recordAgentState` (the state-transition events, from +transitions detected by `WorkspaceStateObserver` / `WorkspaceAgentObserver`). ### Spans @@ -537,6 +537,9 @@ Opening a workspace from any entry point. ### Logs +Both state-transition events are sampled from the workspace event stream, so +intermediate hops between samples may coalesce into a single transition. + #### `workspace.state_transitioned` | Attribute | Values | @@ -550,6 +553,9 @@ Opening a workspace from any entry point. #### `workspace.agent.state_transitioned` +Emitted for every agent in the workspace, deduped per agent, for the whole +monitored session (not only the connected agent during connection setup). + | Attribute | Values | | -------------------------------------------- | ---------------------------------------------------- | | `workspace_name`, `agent_name` | names | diff --git a/src/instrumentation/workspace.ts b/src/instrumentation/workspace.ts index f98f32eda4..d25783e9c2 100644 --- a/src/instrumentation/workspace.ts +++ b/src/instrumentation/workspace.ts @@ -1,159 +1,71 @@ import { WorkspaceUpdateCancelledError } from "../api/updateParameters"; +import { + INITIAL_STATE, + type AgentStateTransition, + type WorkspaceStateTransition, +} from "../workspace/observers"; -import type { - Workspace, - WorkspaceAgent, - WorkspaceAgentLifecycle, - WorkspaceAgentStatus, - WorkspaceBuild, - WorkspaceBuildParameter, - WorkspaceStatus, -} from "coder/site/src/api/typesGenerated"; +import type { WorkspaceBuildParameter } from "coder/site/src/api/typesGenerated"; import type { TelemetryReporter } from "../telemetry/reporter"; import type { Span } from "../telemetry/span"; -/** Sentinel for `from*` before any state is observed. `"unknown"` is a real server-reported value, so avoid it. */ -const INITIAL_STATE = "none"; - -/** Statuses where a provisioner job is actively running. */ -const PROVISIONING_STATUSES: ReadonlySet = new Set([ - "pending", - "starting", - "stopping", - "canceling", - "deleting", -]); - export type WorkspacePromptAction = "start" | "update"; export type WorkspaceUpdatePrompt = "parameters" | "confirmation"; -interface ObservedWorkspaceState { - readonly status: WorkspaceStatus; - readonly buildTransition: WorkspaceBuild["transition"]; - readonly buildReason: WorkspaceBuild["reason"]; - readonly observedAtMs: number; -} - -interface ObservedAgentState { - readonly status: WorkspaceAgentStatus; - readonly lifecycleState: WorkspaceAgentLifecycle; - readonly observedAtMs: number; -} - /** - * Emits `workspace.state_transitioned` as a workspace progresses through - * statuses, plus `observed_build_duration_ms` when a provisioner run resolves. - * Construct one per workspace; `WorkspaceMonitor` is the sole call site. + * Emits `workspace.state_transitioned` for a detected workspace transition. + * Telemetry only; pair with `WorkspaceStateObserver`. */ -export class WorkspaceStateTelemetry { - private observed: ObservedWorkspaceState | undefined; - /** Set on first observation of a provisioning status; cleared when the build resolves. */ - private buildStartedAtMs: number | undefined; - - public constructor( - private readonly telemetry: TelemetryReporter, - private readonly workspaceName: string, - ) {} - - public observe(workspace: Workspace): void { - const { - status, - transition: buildTransition, - reason: buildReason, - } = workspace.latest_build; - const previous = this.observed; - if ( - previous?.status === status && - previous.buildTransition === buildTransition && - previous.buildReason === buildReason - ) { - return; - } - - const now = performance.now(); - const measurements: Record = previous - ? { observed_duration_ms: now - previous.observedAtMs } - : {}; - - const wasProvisioning = - previous && PROVISIONING_STATUSES.has(previous.status); - const isProvisioning = PROVISIONING_STATUSES.has(status); - if (isProvisioning) { - this.buildStartedAtMs ??= now; - } else { - if (wasProvisioning && this.buildStartedAtMs !== undefined) { - measurements.observed_build_duration_ms = now - this.buildStartedAtMs; - } - this.buildStartedAtMs = undefined; - } - - this.telemetry.log( - "workspace.state_transitioned", - { - workspace_name: this.workspaceName, - from: previous?.status ?? INITIAL_STATE, - to: status, - "build.transition": buildTransition, - "build.reason": buildReason, - }, - measurements, - ); - this.observed = { - status, - buildTransition, - buildReason, - observedAtMs: now, - }; +export function recordWorkspaceState( + telemetry: TelemetryReporter, + workspaceName: string, + transition: WorkspaceStateTransition, +): void { + const measurements: Record = {}; + if (transition.durationMs !== undefined) { + measurements.observed_duration_ms = transition.durationMs; + } + if (transition.buildDurationMs !== undefined) { + measurements.observed_build_duration_ms = transition.buildDurationMs; } + + telemetry.log( + "workspace.state_transitioned", + { + workspace_name: workspaceName, + from: transition.from ?? INITIAL_STATE, + to: transition.to, + "build.transition": transition.buildTransition, + "build.reason": transition.buildReason, + }, + measurements, + ); } /** - * Emits `workspace.agent.state_transitioned` as the agent's `status` and - * `lifecycle_state` change. The agent has two state dimensions so the event - * carries `status.*` and `lifecycle_state.*` properties. Construct one per - * workspace. + * Emits `workspace.agent.state_transitioned` for a detected agent transition. + * Telemetry only; pair with `WorkspaceAgentObserver`. */ -export class WorkspaceAgentTelemetry { - private observed: ObservedAgentState | undefined; - - public constructor( - private readonly telemetry: TelemetryReporter, - private readonly workspaceName: string, - ) {} - - public observe(agent: WorkspaceAgent): void { - const previous = this.observed; - if ( - previous?.status === agent.status && - previous.lifecycleState === agent.lifecycle_state - ) { - return; - } - const now = performance.now(); - - this.telemetry.log( - "workspace.agent.state_transitioned", - { - workspace_name: this.workspaceName, - agent_name: agent.name, - "status.from": previous?.status ?? INITIAL_STATE, - "status.to": agent.status, - "lifecycle_state.from": previous?.lifecycleState ?? INITIAL_STATE, - "lifecycle_state.to": agent.lifecycle_state, - }, - previous ? { observed_duration_ms: now - previous.observedAtMs } : {}, - ); - this.observed = { - status: agent.status, - lifecycleState: agent.lifecycle_state, - observedAtMs: now, - }; - } - - public reset(): void { - this.observed = undefined; - } +export function recordAgentState( + telemetry: TelemetryReporter, + workspaceName: string, + transition: AgentStateTransition, +): void { + telemetry.log( + "workspace.agent.state_transitioned", + { + workspace_name: workspaceName, + agent_name: transition.agentName, + "status.from": transition.statusFrom ?? INITIAL_STATE, + "status.to": transition.statusTo, + "lifecycle_state.from": transition.lifecycleFrom ?? INITIAL_STATE, + "lifecycle_state.to": transition.lifecycleTo, + }, + transition.durationMs !== undefined + ? { observed_duration_ms: transition.durationMs } + : {}, + ); } /** diff --git a/src/remote/workspaceStateMachine.ts b/src/remote/workspaceStateMachine.ts index f0915da4cf..fc4242d967 100644 --- a/src/remote/workspaceStateMachine.ts +++ b/src/remote/workspaceStateMachine.ts @@ -16,10 +16,7 @@ import { streamAgentLogs, streamBuildLogs, } from "../api/workspace"; -import { - WorkspaceAgentTelemetry, - WorkspaceOperationTelemetry, -} from "../instrumentation/workspace"; +import { WorkspaceOperationTelemetry } from "../instrumentation/workspace"; import { maybeAskAgent } from "../promptUtils"; import { vscodeProposed } from "../vscodeProposed"; @@ -47,7 +44,6 @@ export class WorkspaceStateMachine implements vscode.Disposable { private readonly terminal: TerminalOutputChannel; private readonly buildLogStream = new LazyStream(); private readonly agentLogStream = new LazyStream(); - private readonly agentTelemetry: WorkspaceAgentTelemetry; private readonly operationTelemetry: WorkspaceOperationTelemetry; private agent: { id: string; name: string } | undefined; @@ -68,7 +64,6 @@ export class WorkspaceStateMachine implements vscode.Disposable { this.terminal = new TerminalOutputChannel("Coder: Workspace Build"); const telemetry = container.getTelemetryService(); const workspaceName = `${parts.username}/${parts.workspace}`; - this.agentTelemetry = new WorkspaceAgentTelemetry(telemetry, workspaceName); this.operationTelemetry = new WorkspaceOperationTelemetry( telemetry, workspaceName, @@ -184,7 +179,6 @@ export class WorkspaceStateMachine implements vscode.Disposable { `Agent ${this.agent.name} not found in ${workspaceName} resources`, ); } - this.agentTelemetry.observe(agent); switch (agent.status) { case "connecting": @@ -365,7 +359,6 @@ export class WorkspaceStateMachine implements vscode.Disposable { private resetAgent(): void { this.agent = undefined; - this.agentTelemetry.reset(); } dispose(): void { diff --git a/src/workspace/observers.ts b/src/workspace/observers.ts new file mode 100644 index 0000000000..5b06641d0f --- /dev/null +++ b/src/workspace/observers.ts @@ -0,0 +1,159 @@ +import { extractAgents } from "../api/api-helper"; + +import type { + Workspace, + WorkspaceAgentLifecycle, + WorkspaceAgentStatus, + WorkspaceBuild, + WorkspaceStatus, +} from "coder/site/src/api/typesGenerated"; + +/** Statuses where a provisioner job is actively running. */ +const PROVISIONING_STATUSES: ReadonlySet = new Set([ + "pending", + "starting", + "stopping", + "canceling", + "deleting", +]); + +interface ObservedWorkspaceState { + readonly status: WorkspaceStatus; + readonly buildTransition: WorkspaceBuild["transition"]; + readonly buildReason: WorkspaceBuild["reason"]; + readonly observedAtMs: number; +} + +interface ObservedAgentState { + readonly name: string; + readonly status: WorkspaceAgentStatus; + readonly lifecycleState: WorkspaceAgentLifecycle; + readonly observedAtMs: number; +} + +/** Sentinel for `from*` before any state is observed. `"unknown"` is a real server-reported value, so avoid it. */ +export const INITIAL_STATE = "none"; + +/** Reported by `WorkspaceStateObserver`. */ +export interface WorkspaceStateTransition { + /** Previous status, or `undefined` on the first observation. */ + readonly from: WorkspaceStatus | undefined; + readonly to: WorkspaceStatus; + readonly buildTransition: WorkspaceBuild["transition"]; + readonly buildReason: WorkspaceBuild["reason"]; + /** Time spent in the previous state; `undefined` on the first observation. */ + readonly durationMs: number | undefined; + /** Set only on the observation where a provisioner run resolves. */ + readonly buildDurationMs: number | undefined; +} + +/** Reported by `WorkspaceAgentObserver`. */ +export interface AgentStateTransition { + readonly agentName: string; + readonly statusFrom: WorkspaceAgentStatus | undefined; + readonly statusTo: WorkspaceAgentStatus; + readonly lifecycleFrom: WorkspaceAgentLifecycle | undefined; + readonly lifecycleTo: WorkspaceAgentLifecycle; + /** Time since the previous observation of this agent; `undefined` on the first. */ + readonly durationMs: number | undefined; +} + +export interface AgentObservation { + readonly transitions: AgentStateTransition[]; + /** Names of agents present on a prior observation and absent now. */ + readonly removed: string[]; +} + +/** + * Construct one per workspace. + */ +export class WorkspaceStateObserver { + private previous: ObservedWorkspaceState | undefined; + /** Set on first observation of a provisioning status; cleared when the build resolves. */ + private buildStartedAtMs: number | undefined; + + public observe(workspace: Workspace): WorkspaceStateTransition | undefined { + const { + status, + transition: buildTransition, + reason: buildReason, + } = workspace.latest_build; + const now = performance.now(); + const previous = this.previous; + + if ( + previous?.status === status && + previous?.buildTransition === buildTransition && + previous?.buildReason === buildReason + ) { + return undefined; + } + this.previous = { status, buildTransition, buildReason, observedAtMs: now }; + + let buildDurationMs: number | undefined; + if (PROVISIONING_STATUSES.has(status)) { + this.buildStartedAtMs ??= now; + } else if (this.buildStartedAtMs !== undefined) { + buildDurationMs = now - this.buildStartedAtMs; + this.buildStartedAtMs = undefined; + } + + return { + from: previous?.status, + to: status, + buildTransition, + buildReason, + durationMs: previous ? now - previous.observedAtMs : undefined, + buildDurationMs, + }; + } +} + +/** + * Construct one per workspace. + */ +export class WorkspaceAgentObserver { + /** Previous observed state per agent ID, tracked independently. */ + private readonly previous = new Map(); + + public observe(workspace: Workspace): AgentObservation { + const now = performance.now(); + const transitions: AgentStateTransition[] = []; + const seen = new Set(); + + for (const agent of extractAgents(workspace.latest_build.resources)) { + seen.add(agent.id); + const previous = this.previous.get(agent.id); + if ( + previous?.status === agent.status && + previous?.lifecycleState === agent.lifecycle_state + ) { + continue; + } + this.previous.set(agent.id, { + name: agent.name, + status: agent.status, + lifecycleState: agent.lifecycle_state, + observedAtMs: now, + }); + transitions.push({ + agentName: agent.name, + statusFrom: previous?.status, + statusTo: agent.status, + lifecycleFrom: previous?.lifecycleState, + lifecycleTo: agent.lifecycle_state, + durationMs: previous ? now - previous.observedAtMs : undefined, + }); + } + + const removed: string[] = []; + for (const [id, { name }] of this.previous) { + if (!seen.has(id)) { + removed.push(name); + this.previous.delete(id); + } + } + + return { transitions, removed }; + } +} diff --git a/src/workspace/workspaceMonitor.ts b/src/workspace/workspaceMonitor.ts index ff6d23da46..debcf6c545 100644 --- a/src/workspace/workspaceMonitor.ts +++ b/src/workspace/workspaceMonitor.ts @@ -6,7 +6,10 @@ import { formatDistanceToNowStrict } from "date-fns"; import * as vscode from "vscode"; import { createWorkspaceIdentifier, errToStr } from "../api/api-helper"; -import { WorkspaceStateTelemetry } from "../instrumentation/workspace"; +import { + recordAgentState, + recordWorkspaceState, +} from "../instrumentation/workspace"; import { areNotificationsDisabled, areUpdateNotificationsDisabled, @@ -14,12 +17,22 @@ import { import { createStatusBarItem } from "../util/statusBar"; import { vscodeProposed } from "../vscodeProposed"; +import { + INITIAL_STATE, + WorkspaceAgentObserver, + WorkspaceStateObserver, +} from "./observers"; + import type { CoderApi } from "../api/coderApi"; import type { ServiceContainer } from "../core/container"; import type { ContextManager } from "../core/contextManager"; import type { Logger } from "../logging/logger"; +import type { TelemetryReporter } from "../telemetry/reporter"; import type { UnidirectionalStream } from "../websocket/eventStreamConnection"; +const stateVerb = (from: string | undefined) => + from === undefined ? "state observed" : "state changed"; + /** * Monitor a single workspace using a WebSocket for events like shutdown and deletion. * Notify the user about relevant changes and update contexts as needed. The @@ -45,7 +58,9 @@ export class WorkspaceMonitor implements vscode.Disposable { // For logging. private readonly name: string; - private readonly telemetry: WorkspaceStateTelemetry; + private readonly telemetry: TelemetryReporter; + private readonly stateObserver = new WorkspaceStateObserver(); + private readonly agentObserver = new WorkspaceAgentObserver(); private readonly logger: Logger; private readonly contextManager: ContextManager; @@ -59,10 +74,7 @@ export class WorkspaceMonitor implements vscode.Disposable { this.logger = container.getLogger(); this.contextManager = container.getContextManager(); this.name = createWorkspaceIdentifier(workspace); - this.telemetry = new WorkspaceStateTelemetry( - container.getTelemetryService(), - this.name, - ); + this.telemetry = container.getTelemetryService(); this.latestWorkspace = workspace; const statusBarItem = createStatusBarItem("workspaceUpdate"); @@ -135,12 +147,48 @@ export class WorkspaceMonitor implements vscode.Disposable { } private update(workspace: Workspace) { - this.telemetry.observe(workspace); + this.observeState(workspace); + this.observeAgents(workspace); this.latestWorkspace = workspace; this.updateContext(workspace); this.updateStatusBar(workspace); } + private observeState(workspace: Workspace) { + const transition = this.stateObserver.observe(workspace); + if (!transition) { + return; + } + const verb = stateVerb(transition.from); + this.logger.info(`Workspace ${this.name} ${verb}`, { + from: transition.from ?? INITIAL_STATE, + to: transition.to, + transition: transition.buildTransition, + reason: transition.buildReason, + }); + recordWorkspaceState(this.telemetry, this.name, transition); + } + + private observeAgents(workspace: Workspace) { + const { transitions, removed } = this.agentObserver.observe(workspace); + for (const transition of transitions) { + const verb = stateVerb(transition.statusFrom); + this.logger.info( + `Workspace ${this.name} agent ${transition.agentName} ${verb}`, + { + statusFrom: transition.statusFrom ?? INITIAL_STATE, + statusTo: transition.statusTo, + lifecycleFrom: transition.lifecycleFrom ?? INITIAL_STATE, + lifecycleTo: transition.lifecycleTo, + }, + ); + recordAgentState(this.telemetry, this.name, transition); + } + for (const name of removed) { + this.logger.info(`Workspace ${this.name} agent ${name} removed`); + } + } + private maybeNotify(workspace: Workspace) { const cfg = vscode.workspace.getConfiguration(); if (areNotificationsDisabled(cfg)) { diff --git a/test/mocks/testHelpers.ts b/test/mocks/testHelpers.ts index e886d0a120..914cc45f4c 100644 --- a/test/mocks/testHelpers.ts +++ b/test/mocks/testHelpers.ts @@ -11,6 +11,11 @@ import * as vscode from "vscode"; import { SessionStore, type SessionData } from "@/deployment/sessionStore"; +import { + resource as createResource, + workspace as createWorkspace, +} from "@repo/mocks"; + import { createTestTelemetryService } from "./telemetry"; import { window as vscodeWindow } from "./vscode.runtime"; @@ -18,6 +23,9 @@ import type { Experiment, User, Workspace, + WorkspaceAgent, + WorkspaceBuild, + WorkspaceStatus, } from "coder/site/src/api/typesGenerated"; import type { WebSocketEventType } from "coder/site/src/utils/OneWayWebSocket"; import type { IncomingMessage } from "node:http"; @@ -923,6 +931,24 @@ export class MockOAuthInterceptor { readonly dispose = vi.fn(); } +/** + * Build a workspace in `status` with the given agents on its latest build. + * `build` overrides other `latest_build` fields. + */ +export function workspaceWith( + status: WorkspaceStatus, + agents: WorkspaceAgent[] = [], + build: Partial = {}, +): Workspace { + return createWorkspace({ + latest_build: { + status, + resources: [createResource({ agents })], + ...build, + }, + }); +} + /** * Create a mock User for testing. */ diff --git a/test/unit/instrumentation/workspace.test.ts b/test/unit/instrumentation/workspace.test.ts index 4b00b61016..87fee54b86 100644 --- a/test/unit/instrumentation/workspace.test.ts +++ b/test/unit/instrumentation/workspace.test.ts @@ -2,16 +2,11 @@ import { describe, expect, it } from "vitest"; import { WorkspaceUpdateCancelledError } from "@/api/updateParameters"; import { - WorkspaceAgentTelemetry, + recordAgentState, + recordWorkspaceState, WorkspaceOperationTelemetry, - WorkspaceStateTelemetry, } from "@/instrumentation/workspace"; -import { - agent as createAgent, - workspace as createWorkspace, -} from "@repo/mocks"; - import { createTelemetryHarness } from "../../mocks/telemetry"; import type { TelemetryService } from "@/telemetry/service"; @@ -25,10 +20,6 @@ function setup(make: (svc: TelemetryService, name: string) => T) { const newOps = (svc: TelemetryService, name: string) => new WorkspaceOperationTelemetry(svc, name); -const newState = (svc: TelemetryService, name: string) => - new WorkspaceStateTelemetry(svc, name); -const newAgentTelemetry = (svc: TelemetryService, name: string) => - new WorkspaceAgentTelemetry(svc, name); describe("WorkspaceOperationTelemetry", () => { it.each([ @@ -190,113 +181,92 @@ describe("WorkspaceOperationTelemetry", () => { }); }); -describe("WorkspaceStateTelemetry.observe", () => { - it("emits the first observation with from=none and no duration", () => { - const { sink, instance: state } = setup(newState); +describe("recordWorkspaceState", () => { + it("emits workspace.state_transitioned with flat dotted keys", () => { + const { sink, service } = createTelemetryHarness(); - state.observe( - createWorkspace({ - latest_build: { - status: "running", - transition: "start", - reason: "initiator", - }, - }), - ); + recordWorkspaceState(service, WORKSPACE_NAME, { + from: "starting", + to: "running", + buildTransition: "start", + buildReason: "initiator", + durationMs: 1200, + buildDurationMs: 3400, + }); const event = sink.expectOne("workspace.state_transitioned"); expect(event.properties).toMatchObject({ workspace_name: WORKSPACE_NAME, - from: "none", + from: "starting", to: "running", "build.transition": "start", "build.reason": "initiator", }); - expect(event.measurements.observed_duration_ms).toBeUndefined(); + expect(event.measurements).toMatchObject({ + observed_duration_ms: 1200, + observed_build_duration_ms: 3400, + }); }); - it("ignores duplicate observations of the same state", () => { - const { sink, instance: state } = setup(newState); - const ws = createWorkspace({ latest_build: { status: "running" } }); + it("uses the sentinel for from and omits absent measurements", () => { + const { sink, service } = createTelemetryHarness(); - state.observe(ws); - state.observe(ws); - - expect(sink.eventsNamed("workspace.state_transitioned")).toHaveLength(1); - }); + recordWorkspaceState(service, WORKSPACE_NAME, { + from: undefined, + to: "running", + buildTransition: "start", + buildReason: "initiator", + durationMs: undefined, + buildDurationMs: undefined, + }); - it("records observed_duration_ms across transitions and observed_build_duration_ms once a build resolves", () => { - const { sink, instance: state } = setup(newState); - - state.observe(createWorkspace({ latest_build: { status: "stopped" } })); - state.observe(createWorkspace({ latest_build: { status: "starting" } })); - state.observe(createWorkspace({ latest_build: { status: "running" } })); - - const [first, second, third] = sink.eventsNamed( - "workspace.state_transitioned", - ); - expect(first.measurements.observed_duration_ms).toBeUndefined(); - expect(second.measurements.observed_duration_ms).toEqual( - expect.any(Number), - ); - expect(second.measurements.observed_build_duration_ms).toBeUndefined(); - expect(third.measurements.observed_build_duration_ms).toEqual( - expect.any(Number), - ); + const event = sink.expectOne("workspace.state_transitioned"); + expect(event.properties.from).toBe("none"); + expect(event.measurements.observed_duration_ms).toBeUndefined(); + expect(event.measurements.observed_build_duration_ms).toBeUndefined(); }); }); -describe("WorkspaceAgentTelemetry.observe", () => { - it("emits the first observation with from=none", () => { - const { sink, instance: agentTelemetry } = setup(newAgentTelemetry); - - agentTelemetry.observe( - createAgent({ status: "connecting", lifecycle_state: "created" }), - ); - - expect(sink.expectOne("workspace.agent.state_transitioned")).toMatchObject({ - properties: { - "status.from": "none", - "status.to": "connecting", - "lifecycle_state.from": "none", - "lifecycle_state.to": "created", - }, +describe("recordAgentState", () => { + it("emits workspace.agent.state_transitioned with flat dotted keys", () => { + const { sink, service } = createTelemetryHarness(); + + recordAgentState(service, WORKSPACE_NAME, { + agentName: "main", + statusFrom: "connecting", + statusTo: "connected", + lifecycleFrom: "starting", + lifecycleTo: "ready", + durationMs: 800, }); - }); - - it("dedupes consecutive identical observations", () => { - const { sink, instance: agentTelemetry } = setup(newAgentTelemetry); - const a = createAgent({ status: "connected", lifecycle_state: "ready" }); - - agentTelemetry.observe(a); - agentTelemetry.observe(a); - - expect(sink.eventsNamed("workspace.agent.state_transitioned")).toHaveLength( - 1, - ); - }); - - it("reset() makes the next observation emit from=none again", () => { - const { sink, instance: agentTelemetry } = setup(newAgentTelemetry); - agentTelemetry.observe(createAgent({ status: "connected" })); - agentTelemetry.reset(); - agentTelemetry.observe(createAgent({ status: "connecting" })); - - const events = sink.eventsNamed("workspace.agent.state_transitioned"); - expect(events).toHaveLength(2); - expect(events[1].properties["status.from"]).toBe("none"); + const event = sink.expectOne("workspace.agent.state_transitioned"); + expect(event.properties).toMatchObject({ + workspace_name: WORKSPACE_NAME, + agent_name: "main", + "status.from": "connecting", + "status.to": "connected", + "lifecycle_state.from": "starting", + "lifecycle_state.to": "ready", + }); + expect(event.measurements.observed_duration_ms).toBe(800); }); - it("includes observed_duration_ms between transitions", () => { - const { sink, instance: agentTelemetry } = setup(newAgentTelemetry); + it("uses the sentinel for absent from values and omits duration", () => { + const { sink, service } = createTelemetryHarness(); - agentTelemetry.observe(createAgent({ status: "connecting" })); - agentTelemetry.observe(createAgent({ status: "connected" })); + recordAgentState(service, WORKSPACE_NAME, { + agentName: "main", + statusFrom: undefined, + statusTo: "connecting", + lifecycleFrom: undefined, + lifecycleTo: "created", + durationMs: undefined, + }); - const events = sink.eventsNamed("workspace.agent.state_transitioned"); - expect(events[1].measurements.observed_duration_ms).toEqual( - expect.any(Number), - ); + const event = sink.expectOne("workspace.agent.state_transitioned"); + expect(event.properties["status.from"]).toBe("none"); + expect(event.properties["lifecycle_state.from"]).toBe("none"); + expect(event.measurements.observed_duration_ms).toBeUndefined(); }); }); diff --git a/test/unit/remote/workspaceStateMachine.test.ts b/test/unit/remote/workspaceStateMachine.test.ts index dddc465f06..e437b67467 100644 --- a/test/unit/remote/workspaceStateMachine.test.ts +++ b/test/unit/remote/workspaceStateMachine.test.ts @@ -432,76 +432,6 @@ describe("WorkspaceStateMachine", () => { expect(event.measurements.durationMs).toEqual(expect.any(Number)); }, ); - - it("emits agent state transitions with observed duration", async () => { - const sink = new TestSink(); - const { sm, progress } = setup("start", createTestTelemetryService(sink)); - - await sm.processWorkspace( - runningWorkspace({ status: "connecting", lifecycle_state: "created" }), - progress, - ); - await sm.processWorkspace(runningWorkspace(), progress); - - const events = sink.eventsNamed("workspace.agent.state_transitioned"); - expect(events).toHaveLength(2); - expect(events[0].properties).toMatchObject({ - "status.from": "none", - "status.to": "connecting", - "lifecycle_state.from": "none", - "lifecycle_state.to": "created", - }); - expect(events[1].properties).toMatchObject({ - "status.from": "connecting", - "status.to": "connected", - "lifecycle_state.from": "created", - "lifecycle_state.to": "ready", - }); - expect(events[1].measurements.observed_duration_ms).toEqual( - expect.any(Number), - ); - }); - - it("resets agent telemetry on restart so the next transition emits from 'none'", async () => { - const sink = new TestSink(); - const { sm, progress } = setup("start", createTestTelemetryService(sink)); - - // The build log stream is closed when we return to running; give the - // mock something disposable so close() doesn't blow up. - vi.mocked(streamBuildLogs).mockResolvedValueOnce({ - close: vi.fn(), - } as never); - - // Establish a baseline: connected/ready. - await sm.processWorkspace(runningWorkspace(), progress); - - // Workspace enters a build state; resetAgent fires. - await sm.processWorkspace( - createWorkspace({ latest_build: { status: "stopping" } }), - progress, - ); - - // Next agent observation must restart from "none", not the prior baseline. - await sm.processWorkspace( - runningWorkspace({ status: "connecting", lifecycle_state: "created" }), - progress, - ); - - const events = sink.eventsNamed("workspace.agent.state_transitioned"); - expect(events).toHaveLength(2); - expect(events[0].properties).toMatchObject({ - "status.from": "none", - "status.to": "connected", - "lifecycle_state.from": "none", - "lifecycle_state.to": "ready", - }); - expect(events[1].properties).toMatchObject({ - "status.from": "none", - "status.to": "connecting", - "lifecycle_state.from": "none", - "lifecycle_state.to": "created", - }); - }); }); describe("agent selection", () => { diff --git a/test/unit/workspace/observers.test.ts b/test/unit/workspace/observers.test.ts new file mode 100644 index 0000000000..bae54e9338 --- /dev/null +++ b/test/unit/workspace/observers.test.ts @@ -0,0 +1,199 @@ +import { describe, expect, it } from "vitest"; + +import { + WorkspaceAgentObserver, + WorkspaceStateObserver, +} from "@/workspace/observers"; + +import { agent as createAgent } from "@repo/mocks"; + +import { workspaceWith } from "../../mocks/testHelpers"; + +describe("WorkspaceStateObserver", () => { + it("reports the first observation with from=undefined and no durations", () => { + const observer = new WorkspaceStateObserver(); + + const transition = observer.observe( + workspaceWith("running", [], { + transition: "start", + reason: "initiator", + }), + ); + + expect(transition).toMatchObject({ + from: undefined, + to: "running", + buildTransition: "start", + buildReason: "initiator", + durationMs: undefined, + buildDurationMs: undefined, + }); + }); + + it("returns undefined for a duplicate observation", () => { + const observer = new WorkspaceStateObserver(); + const ws = workspaceWith("running"); + + observer.observe(ws); + + expect(observer.observe(ws)).toBeUndefined(); + }); + + it("reports the prior status and a duration on a change", () => { + const observer = new WorkspaceStateObserver(); + + observer.observe(workspaceWith("starting")); + const transition = observer.observe(workspaceWith("running")); + + expect(transition).toMatchObject({ from: "starting", to: "running" }); + expect(transition?.durationMs).toEqual(expect.any(Number)); + }); + + it("reports a change when only transition or reason changes", () => { + const observer = new WorkspaceStateObserver(); + + observer.observe(workspaceWith("running", [], { transition: "start" })); + const transition = observer.observe( + workspaceWith("running", [], { transition: "stop" }), + ); + + expect(transition).toMatchObject({ + from: "running", + to: "running", + buildTransition: "stop", + }); + }); + + it("sets buildDurationMs only when a provisioner run resolves", () => { + const observer = new WorkspaceStateObserver(); + + const first = observer.observe(workspaceWith("stopped")); + const second = observer.observe(workspaceWith("starting")); + const third = observer.observe(workspaceWith("running")); + + expect(first?.buildDurationMs).toBeUndefined(); + expect(second?.buildDurationMs).toBeUndefined(); + expect(third?.buildDurationMs).toEqual(expect.any(Number)); + }); +}); + +describe("WorkspaceAgentObserver", () => { + it("reports the first observation of each agent with statusFrom=undefined", () => { + const observer = new WorkspaceAgentObserver(); + + const { transitions, removed } = observer.observe( + workspaceWith("running", [ + createAgent({ + name: "main", + status: "connecting", + lifecycle_state: "created", + }), + ]), + ); + + expect(removed).toEqual([]); + expect(transitions).toHaveLength(1); + expect(transitions[0]).toMatchObject({ + agentName: "main", + statusFrom: undefined, + statusTo: "connecting", + lifecycleFrom: undefined, + lifecycleTo: "created", + durationMs: undefined, + }); + }); + + it("dedupes an unchanged agent", () => { + const observer = new WorkspaceAgentObserver(); + const ws = workspaceWith("running", [ + createAgent({ status: "connected", lifecycle_state: "ready" }), + ]); + + observer.observe(ws); + + expect(observer.observe(ws).transitions).toEqual([]); + }); + + it("reports a change when only the lifecycle state changes", () => { + const observer = new WorkspaceAgentObserver(); + + observer.observe( + workspaceWith("running", [ + createAgent({ status: "connected", lifecycle_state: "starting" }), + ]), + ); + const { transitions } = observer.observe( + workspaceWith("running", [ + createAgent({ status: "connected", lifecycle_state: "ready" }), + ]), + ); + + expect(transitions).toHaveLength(1); + expect(transitions[0]).toMatchObject({ + statusFrom: "connected", + statusTo: "connected", + lifecycleFrom: "starting", + lifecycleTo: "ready", + }); + }); + + it("tracks each agent independently", () => { + const observer = new WorkspaceAgentObserver(); + + observer.observe( + workspaceWith("running", [ + createAgent({ id: "a1", name: "first", status: "connected" }), + createAgent({ id: "a2", name: "second", status: "connecting" }), + ]), + ); + + const { transitions } = observer.observe( + workspaceWith("running", [ + createAgent({ id: "a1", name: "first", status: "connected" }), + createAgent({ id: "a2", name: "second", status: "connected" }), + ]), + ); + + expect(transitions).toHaveLength(1); + expect(transitions[0]).toMatchObject({ + agentName: "second", + statusFrom: "connecting", + statusTo: "connected", + }); + }); + + it("reports an agent that disappears since the previous observation", () => { + const observer = new WorkspaceAgentObserver(); + + observer.observe( + workspaceWith("running", [ + createAgent({ id: "a1", name: "first" }), + createAgent({ id: "a2", name: "second" }), + ]), + ); + + const { removed } = observer.observe( + workspaceWith("running", [createAgent({ id: "a1", name: "first" })]), + ); + + expect(removed).toEqual(["second"]); + }); + + it("treats a returning agent id as a fresh observation after removal", () => { + const observer = new WorkspaceAgentObserver(); + + observer.observe( + workspaceWith("running", [ + createAgent({ id: "a1", name: "first", status: "connected" }), + ]), + ); + observer.observe(workspaceWith("starting", [])); + const { transitions } = observer.observe( + workspaceWith("running", [ + createAgent({ id: "a1", name: "first", status: "connecting" }), + ]), + ); + + expect(transitions[0].statusFrom).toBeUndefined(); + }); +}); diff --git a/test/unit/workspace/workspaceMonitor.test.ts b/test/unit/workspace/workspaceMonitor.test.ts index d156f8952c..29fd685848 100644 --- a/test/unit/workspace/workspaceMonitor.test.ts +++ b/test/unit/workspace/workspaceMonitor.test.ts @@ -3,7 +3,10 @@ import * as vscode from "vscode"; import { WorkspaceMonitor } from "@/workspace/workspaceMonitor"; -import { workspace as createWorkspace } from "@repo/mocks"; +import { + agent as createAgent, + workspace as createWorkspace, +} from "@repo/mocks"; import { createTestTelemetryService, @@ -17,6 +20,7 @@ import { MockEventStream, MockStatusBarItem, createMockLogger, + workspaceWith, } from "../../mocks/testHelpers"; import type { @@ -28,7 +32,7 @@ import type { CoderApi } from "@/api/coderApi"; import type { TelemetryService } from "@/telemetry/service"; function workspaceEvent( - overrides?: Parameters[0], + overrides?: Parameters[0] | Workspace, ): ServerSentEvent { return { type: "data", data: createWorkspace(overrides) }; } @@ -50,6 +54,7 @@ describe("WorkspaceMonitor", () => { const config = new MockConfigurationProvider(); const statusBar = new MockStatusBarItem(); const contextManager = new MockContextManager(); + const logger = createMockLogger(); const client = { watchWorkspace: vi.fn().mockResolvedValue(stream), getTemplate: vi.fn().mockResolvedValue({ @@ -64,24 +69,26 @@ describe("WorkspaceMonitor", () => { client, createMockServiceContainer({ telemetry, - logger: createMockLogger(), + logger, contextManager, }), ); - return { monitor, client, stream, config, statusBar, contextManager }; + return { + monitor, + client, + stream, + config, + statusBar, + contextManager, + logger, + }; } describe("telemetry", () => { - const buildSinkContext = () => { + it("records the initial state, then again on a change", async () => { enableLocalTelemetry(); - return { - stream: new MockEventStream(), - sink: new TestSink(), - }; - }; - - it("emits initial state plus subsequent transitions with duration", async () => { - const { stream, sink } = buildSinkContext(); + const sink = new TestSink(); + const stream = new MockEventStream(); await setup( stream, @@ -89,13 +96,7 @@ describe("WorkspaceMonitor", () => { createWorkspace({ latest_build: { status: "running" } }), ); stream.pushMessage( - workspaceEvent({ - latest_build: { - status: "stopping", - transition: "stop", - reason: "autostop", - }, - }), + workspaceEvent({ latest_build: { status: "stopping" } }), ); const events = sink.eventsNamed("workspace.state_transitioned"); @@ -104,92 +105,136 @@ describe("WorkspaceMonitor", () => { from: "none", to: "running", }); - expect(events[0].measurements.observed_duration_ms).toBeUndefined(); - expect(events[1]).toMatchObject({ - properties: { - from: "running", - to: "stopping", - "build.transition": "stop", - "build.reason": "autostop", - }, - measurements: { observed_duration_ms: expect.any(Number) }, + expect(events[1].properties).toMatchObject({ + from: "running", + to: "stopping", }); }); + }); - it("dedupes on (status, build transition, build reason); re-emits when only reason changes", async () => { - const { stream, sink } = buildSinkContext(); - - await setup( - stream, - createTestTelemetryService(sink), + describe("state logging", () => { + it("logs the initial workspace state as observed with flat scalars", async () => { + const { logger } = await setup( + new MockEventStream(), + undefined, createWorkspace({ latest_build: { - status: "stopping", - transition: "stop", - reason: "autostop", - }, - }), - ); - // Same status with a different reason: must not dedupe. - stream.pushMessage( - workspaceEvent({ - latest_build: { - status: "stopping", - transition: "stop", + status: "running", + transition: "start", reason: "initiator", }, }), ); - // Identical to the previous: deduped. + + expect(logger.info).toHaveBeenCalledWith( + expect.stringContaining("state observed"), + { + from: "none", + to: "running", + transition: "start", + reason: "initiator", + }, + ); + }); + + it("logs subsequent workspace changes as changed", async () => { + const { stream, logger } = await setup( + new MockEventStream(), + undefined, + createWorkspace({ latest_build: { status: "running" } }), + ); + stream.pushMessage( - workspaceEvent({ - latest_build: { - status: "stopping", - transition: "stop", - reason: "initiator", - }, - }), + workspaceEvent({ latest_build: { status: "stopping" } }), ); - const reasons = sink - .eventsNamed("workspace.state_transitioned") - .map((e) => e.properties["build.reason"]); - expect(reasons).toEqual(["autostop", "initiator"]); + expect(logger.info).toHaveBeenCalledWith( + expect.stringContaining("state changed"), + expect.objectContaining({ from: "running", to: "stopping" }), + ); }); + }); - it("emits observed_build_duration_ms on the event that resolves a build run", async () => { - const { stream, sink } = buildSinkContext(); + describe("agent state", () => { + it("logs the initial agent state and records telemetry", async () => { + enableLocalTelemetry(); + const sink = new TestSink(); + const { logger } = await setup( + new MockEventStream(), + createTestTelemetryService(sink), + workspaceWith("running", [ + createAgent({ + name: "main", + status: "connecting", + lifecycle_state: "created", + }), + ]), + ); - await setup( - stream, + expect(logger.info).toHaveBeenCalledWith( + expect.stringContaining("agent main state observed"), + { + statusFrom: "none", + statusTo: "connecting", + lifecycleFrom: "none", + lifecycleTo: "created", + }, + ); + expect( + sink.eventsNamed("workspace.agent.state_transitioned"), + ).toHaveLength(1); + }); + + it("logs and records each agent transition across all agents", async () => { + enableLocalTelemetry(); + const sink = new TestSink(); + const { stream } = await setup( + new MockEventStream(), createTestTelemetryService(sink), - createWorkspace({ latest_build: { status: "pending" } }), + workspaceWith("running", [ + createAgent({ id: "a1", name: "first", status: "connected" }), + createAgent({ id: "a2", name: "second", status: "connecting" }), + ]), ); + stream.pushMessage( - workspaceEvent({ latest_build: { status: "starting" } }), + workspaceEvent( + workspaceWith("running", [ + createAgent({ id: "a1", name: "first", status: "connected" }), + createAgent({ id: "a2", name: "second", status: "connected" }), + ]), + ), ); - stream.pushMessage( - workspaceEvent({ latest_build: { status: "running" } }), + + const events = sink.eventsNamed("workspace.agent.state_transitioned"); + // Two initial observations plus the one "second" transition. + expect(events).toHaveLength(3); + expect(events[2].properties).toMatchObject({ + agent_name: "second", + "status.from": "connecting", + "status.to": "connected", + }); + }); + + it("logs when an agent disappears", async () => { + const { stream, logger } = await setup( + new MockEventStream(), + undefined, + workspaceWith("running", [ + createAgent({ id: "a1", name: "first" }), + createAgent({ id: "a2", name: "second" }), + ]), ); + stream.pushMessage( - workspaceEvent({ latest_build: { status: "stopping" } }), + workspaceEvent( + workspaceWith("running", [createAgent({ id: "a1", name: "first" })]), + ), ); - const events = sink.eventsNamed("workspace.state_transitioned"); - // pending and starting are intermediate; only running carries observed_build_duration_ms. - expect(events.map((e) => e.properties.to)).toEqual([ - "pending", - "starting", - "running", - "stopping", - ]); - expect(events[0].measurements.observed_build_duration_ms).toBeUndefined(); - expect(events[1].measurements.observed_build_duration_ms).toBeUndefined(); - expect(events[2].measurements.observed_build_duration_ms).toEqual( - expect.any(Number), + expect(logger.info).toHaveBeenCalledWith( + expect.stringContaining("agent second removed"), ); - // Next build cycle resets; stopping doesn't carry the previous duration. - expect(events[3].measurements.observed_build_duration_ms).toBeUndefined(); }); });