From f737cddbf0405498d8baac014866ef6646c51eb4 Mon Sep 17 00:00:00 2001 From: St0rmz1 Date: Thu, 30 Jul 2026 09:43:44 -0700 Subject: [PATCH] feat(cloud-agent-next): add container lifecycle logging --- .../cloudflare/cloudflare-agent-sandbox.ts | 17 +++++++ .../cloud-agent-next/src/container-usage.ts | 45 +++++++++++++++++-- .../src/persistence/CloudAgentSession.ts | 4 ++ .../src/session/agent-runtime.ts | 16 ++++++- .../cloud-agent-next/src/websocket/ingest.ts | 12 +++++ 5 files changed, 88 insertions(+), 6 deletions(-) diff --git a/services/cloud-agent-next/src/agent-sandbox/cloudflare/cloudflare-agent-sandbox.ts b/services/cloud-agent-next/src/agent-sandbox/cloudflare/cloudflare-agent-sandbox.ts index cc8d5685ae..d9f709c7aa 100644 --- a/services/cloud-agent-next/src/agent-sandbox/cloudflare/cloudflare-agent-sandbox.ts +++ b/services/cloud-agent-next/src/agent-sandbox/cloudflare/cloudflare-agent-sandbox.ts @@ -752,6 +752,23 @@ export class CloudflareAgentSandbox implements AgentSandbox { }): Promise { const sandbox = await this.getSandbox(); const initial = await this.observeTarget(request.target); + // Inspection is a container fetch, so it wakes a sleeping container. An `absent` + // result therefore means we booted a container only to learn nothing was running + // in it — the signal for how much idle container time this path is creating. + logger + .withTags({ + logTag: 'wrapper_stop_inspection', + sessionId: this.metadata.identity.sessionId, + sandboxId: await this.resolveSandboxId(), + }) + .withFields({ + reason: request.reason, + attemptId: request.attemptId, + target: request.target.kind, + observation: initial.status, + observedWrapperCount: initial.status === 'present' ? initial.observed.length : 0, + }) + .info('Wrapper stop inspection completed'); if (initial.status !== 'present') return initial; try { diff --git a/services/cloud-agent-next/src/container-usage.ts b/services/cloud-agent-next/src/container-usage.ts index 41e0c0d5f7..bbd87a5391 100644 --- a/services/cloud-agent-next/src/container-usage.ts +++ b/services/cloud-agent-next/src/container-usage.ts @@ -32,6 +32,13 @@ const LAST_START_EPOCH_STORAGE_KEY = 'container-usage:last-start-epoch:v1'; type SandboxDurableObjectState = DurableObjectState<{}>; type ContainerStopParams = { reason: 'exit' | 'runtime_signal'; exitCode?: number }; +/** + * Why a billing generation — and therefore a physical container run — began. + * `container-start` is the SDK dispatching onStart; the other two adopt a container + * that was already running when attribution or a replacement generation arrived. + */ +type ContainerStartTrigger = 'container-start' | 'attribution-adoption' | 'replacement-generation'; + const pendingStopReasonSchema = z .object({ generation: z.uuid(), @@ -166,7 +173,7 @@ export abstract class MeteredSandbox extends StockSandbox { // Adopt containers that were already running when shadow metering rolled out. if (this.ctx.container?.running === true) { - await this.startBillingGeneration(parsed); + await this.startBillingGeneration(parsed, 'attribution-adoption'); } }); } @@ -207,7 +214,7 @@ export abstract class MeteredSandbox extends StockSandbox { return; } - await this.startBillingGeneration(input); + await this.startBillingGeneration(input, 'container-start'); }); } @@ -222,6 +229,20 @@ export abstract class MeteredSandbox extends StockSandbox { const requestedReason = activityExpiryRequested ? 'activity_expired' : await this.getPendingStopReason(context.generation); + // Pairs with `container_started`: reason plus lifetime makes idle-expiry patterns + // queryable in logs instead of only in the usage tables. + logger + .withTags({ logTag: 'container_stopped', sandboxId: context.instanceId }) + .withFields({ + sandboxClass: this.sandboxClassName, + generation: context.generation, + startEpochMs: context.startEpochMs, + reason: requestedReason ?? params?.reason ?? 'runtime_signal', + exitCode: params?.exitCode, + lifetimeMs: stoppedAtMs - context.startEpochMs, + sessionId: context.sessionId, + }) + .info('Container stopped'); const pending = await this.billingHeartbeat.persistStop( { reason: requestedReason ?? params?.reason ?? 'runtime_signal', @@ -275,7 +296,7 @@ export abstract class MeteredSandbox extends StockSandbox { if (this.ctx.container?.running !== true) return; if (await getBillingContext(this.ctx.storage)) return; const input = await this.getPendingAttribution(); - if (input) await this.startBillingGeneration(input); + if (input) await this.startBillingGeneration(input, 'replacement-generation'); }); } @@ -340,7 +361,10 @@ export abstract class MeteredSandbox extends StockSandbox { } } - private async startBillingGeneration(input: SandboxBillingInput): Promise { + private async startBillingGeneration( + input: SandboxBillingInput, + trigger: ContainerStartTrigger + ): Promise { const previousStartEpochMs = (await this.ctx.storage.get(LAST_START_EPOCH_STORAGE_KEY)) ?? -1; const startEpochMs = Math.max(Date.now(), previousStartEpochMs + 1); @@ -361,6 +385,19 @@ export abstract class MeteredSandbox extends StockSandbox { startEpochMs, } satisfies UsageContext & { startEpochMs: number }); await this.ctx.storage.delete(PENDING_STOP_REASON_STORAGE_KEY); + // The only worker-side record that a container run began. `service:sandboxId:startEpochMs` + // is the usage `intervalId`, so these fields join a log line to its usage row. + logger + .withTags({ logTag: 'container_started', sandboxId: input.sandboxId }) + .withFields({ + sandboxClass: this.sandboxClassName, + generation: context.generation, + startEpochMs, + trigger, + sessionId: input.sessionId, + durableObjectId: this.ctx.id.toString(), + }) + .info('Container started'); await this.admitAndScheduleBestEffort(context); } } diff --git a/services/cloud-agent-next/src/persistence/CloudAgentSession.ts b/services/cloud-agent-next/src/persistence/CloudAgentSession.ts index c737843ba5..1f6f8660bc 100644 --- a/services/cloud-agent-next/src/persistence/CloudAgentSession.ts +++ b/services/cloud-agent-next/src/persistence/CloudAgentSession.ts @@ -2686,10 +2686,14 @@ export class CloudAgentSession extends DurableObject { // Server has been idle too long and no wrapper/pending work remains, stop it logger + .withTags({ logTag: 'idle_kilo_server_stopped' }) .withFields({ sessionId: this.sessionId, idleMs, idleTimeoutMs, + // How late this sweep ran against its own deadline; aggregate to spot a + // sweeper that is firing well past idleTimeoutMs. + overdueMs: Math.max(0, idleMs - idleTimeoutMs), }) .info('Stopping idle kilo server'); diff --git a/services/cloud-agent-next/src/session/agent-runtime.ts b/services/cloud-agent-next/src/session/agent-runtime.ts index cf183352c9..b37bc18d4c 100644 --- a/services/cloud-agent-next/src/session/agent-runtime.ts +++ b/services/cloud-agent-next/src/session/agent-runtime.ts @@ -555,9 +555,21 @@ export function createAgentRuntime(dependencies: AgentRuntimeDependencies): Agen async function keepSandboxAlive(): Promise { try { - if (canUseSandboxRuntime && !(await canUseSandboxRuntime())) return; + // Both guards below skip renewal silently, which is indistinguishable in logs from + // a renewal that succeeded. Name the guard so a stalled sleep timer is diagnosable. + if (canUseSandboxRuntime && !(await canUseSandboxRuntime())) { + logger + .withFields({ sessionId: getSessionIdForLogs(), skipped: 'sandbox-runtime-unavailable' }) + .debug('AgentRuntime skipped sandbox sleep timer reset'); + return; + } const metadata = await getMetadata(); - if (!metadata) return; + if (!metadata) { + logger + .withFields({ sessionId: getSessionIdForLogs(), skipped: 'metadata-missing' }) + .debug('AgentRuntime skipped sandbox sleep timer reset'); + return; + } await resolveAgentSandbox(metadata).keepAlive(); } catch (error) { logger diff --git a/services/cloud-agent-next/src/websocket/ingest.ts b/services/cloud-agent-next/src/websocket/ingest.ts index cd031d374e..1b0b90695a 100644 --- a/services/cloud-agent-next/src/websocket/ingest.ts +++ b/services/cloud-agent-next/src/websocket/ingest.ts @@ -724,9 +724,21 @@ export function createIngestHandler( } if (now - attachment.lastHeartbeatUpdate >= HEARTBEAT_DEBOUNCE_MS) { + const sinceLastRenewalMs = now - attachment.lastHeartbeatUpdate; attachment.lastHeartbeatUpdate = now; ws.serializeAttachment(attachment); doContext.keepContainerAlive?.(); + // Wrapper heartbeats bypass container fetches, so this is the only thing renewing + // the sandbox sleep timer. A gap in this series is a container about to expire. + logger + .withTags({ logTag: 'sandbox_keepalive_renewed', sessionId }) + .withFields({ + wrapperRunId: attachment.wrapperRunId, + wrapperGeneration: attachment.wrapperGeneration, + sinceLastRenewalMs, + eventType, + }) + .debug('Sandbox sleep timer renewal requested from wrapper heartbeat'); } if (eventType !== 'heartbeat') { if (now - attachment.lastEventAtUpdate >= HEARTBEAT_DEBOUNCE_MS) {