@@ -154,6 +154,8 @@ const MAX_CONTAINER_INACTIVITY_MS = 6 * 60 * 60 * 1000;
154154const CONTAINER_INACTIVITY_MARGIN_MS = 15 * 60 * 1000 ;
155155const READY_TIMEOUT_MS = 90_000 ;
156156const READY_RETRY_MS = 100 ;
157+ /** While a start waits for readiness, log its progress this often. */
158+ const READY_PROGRESS_LOG_MS = 30_000 ;
157159/** A command's output kept in this object's memory, per stream. */
158160const MAX_OUTPUT_BYTES = 8 * 1024 * 1024 ;
159161/** The largest file read in one call (one RPC result). */
@@ -322,18 +324,77 @@ export class OrbContainerController {
322324 ) ;
323325 }
324326
325- /** The container accepts `exec` once it has started. */
327+ /**
328+ * The container accepts `exec` once it has started. Logs progress while it
329+ * waits, so a stalled start shows whether one probe hung
330+ * (`currentAttemptMs`) or probes kept failing (`attempts`, `lastFailure`).
331+ */
326332 async #waitReady( operation : string ) {
327- const deadline = this . #now( ) + READY_TIMEOUT_MS ;
333+ const startedAt = this . #now( ) ;
334+ const deadline = startedAt + READY_TIMEOUT_MS ;
328335 let lastFailure : unknown ;
329- while ( this . #now( ) < deadline ) {
330- try {
331- const process = await this . #container. exec ( [ "true" ] ) ;
332- if ( ( await process . exitCode ) === 0 ) return ;
333- } catch ( cause ) {
334- lastFailure = cause ;
336+ let attempts = 0 ;
337+ let attemptStartedAt = startedAt ;
338+ let slowestAttemptMs = 0 ;
339+ const progress = ( outcome : "waiting" | "ready" | "timed_out" ) => ( {
340+ event : "orb_container_ready_wait" ,
341+ outcome,
342+ sandboxId : this . #sandboxId,
343+ operation,
344+ elapsedMs : this . #now( ) - startedAt ,
345+ attempts,
346+ slowestAttemptMs,
347+ currentAttemptMs : this . #now( ) - attemptStartedAt ,
348+ running : this . #container. running ,
349+ ...( lastFailure === undefined
350+ ? { }
351+ : {
352+ lastFailure :
353+ lastFailure instanceof Error
354+ ? lastFailure . message
355+ : String ( lastFailure ) ,
356+ } ) ,
357+ } ) ;
358+ const watchdog = setInterval (
359+ ( ) =>
360+ orbContainerLogger . warn (
361+ "Orb container is not ready yet." ,
362+ progress ( "waiting" ) ,
363+ ) ,
364+ READY_PROGRESS_LOG_MS ,
365+ ) ;
366+ try {
367+ while ( this . #now( ) < deadline ) {
368+ attempts += 1 ;
369+ attemptStartedAt = this . #now( ) ;
370+ try {
371+ const process = await this . #container. exec ( [ "true" ] ) ;
372+ if ( ( await process . exitCode ) === 0 ) {
373+ slowestAttemptMs = Math . max (
374+ slowestAttemptMs ,
375+ this . #now( ) - attemptStartedAt ,
376+ ) ;
377+ orbContainerLogger . info (
378+ "Orb container is ready." ,
379+ progress ( "ready" ) ,
380+ ) ;
381+ return ;
382+ }
383+ } catch ( cause ) {
384+ lastFailure = cause ;
385+ }
386+ slowestAttemptMs = Math . max (
387+ slowestAttemptMs ,
388+ this . #now( ) - attemptStartedAt ,
389+ ) ;
390+ await sleep ( READY_RETRY_MS ) ;
335391 }
336- await sleep ( READY_RETRY_MS ) ;
392+ orbContainerLogger . error (
393+ "Orb container did not become ready." ,
394+ progress ( "timed_out" ) ,
395+ ) ;
396+ } finally {
397+ clearInterval ( watchdog ) ;
337398 }
338399 throw failure (
339400 operation ,
@@ -349,8 +410,51 @@ export class OrbContainerController {
349410 state : OrbWorkspaceState ,
350411 idleMs : number ,
351412 fresh = false ,
413+ lockWaitMs = 0 ,
352414 ) : Promise < "paused" | "created" > {
353415 const now = this . #now( ) ;
416+ const snapshot = state . snapshot ;
417+ const details = {
418+ event : "orb_container_start" ,
419+ sandboxId : this . #sandboxId,
420+ source : snapshot === undefined ? "image" : "snapshot" ,
421+ ...( snapshot === undefined
422+ ? { }
423+ : {
424+ snapshotId : snapshot . id ,
425+ snapshotSize : snapshot . size ,
426+ snapshotAgeMs : now - snapshot . refreshedAt ,
427+ } ) ,
428+ instance : state . instance ,
429+ fresh,
430+ lockWaitMs,
431+ } ;
432+ orbContainerLogger . info ( "Orb container start requested." , details ) ;
433+ try {
434+ const residency = await this . #startContainer( state , idleMs , fresh , now ) ;
435+ orbContainerLogger . info ( "Orb container started." , {
436+ ...details ,
437+ outcome : "started" ,
438+ durationMs : this . #now( ) - now ,
439+ } ) ;
440+ return residency ;
441+ } catch ( cause ) {
442+ orbContainerLogger . error ( "Orb container start failed." , {
443+ ...details ,
444+ outcome : "error" ,
445+ durationMs : this . #now( ) - now ,
446+ error : cause instanceof Error ? cause . message : String ( cause ) ,
447+ } ) ;
448+ throw cause ;
449+ }
450+ }
451+
452+ async #startContainer(
453+ state : OrbWorkspaceState ,
454+ idleMs : number ,
455+ fresh : boolean ,
456+ now : number ,
457+ ) : Promise < "paused" | "created" > {
354458 const snapshot = state . snapshot ;
355459 if ( snapshot === undefined ) {
356460 const image = this . #image( ) ;
@@ -401,7 +505,9 @@ export class OrbContainerController {
401505 readonly instance : CloudflareContainerInstance ;
402506 readonly idleMs : number ;
403507 } ) : Promise < OrbOpenResult > {
508+ const requestedAt = this . #now( ) ;
404509 return this . #exclusive( async ( ) => {
510+ const lockWaitMs = this . #now( ) - requestedAt ;
405511 let state = await this . #load( ) ;
406512 let fresh = false ;
407513 if ( state === undefined ) {
@@ -438,7 +544,12 @@ export class OrbContainerController {
438544 : { processesStartedAt : state . startedAt } ) ,
439545 } ;
440546 }
441- const residency = await this . #start( state , input . idleMs , fresh ) ;
547+ const residency = await this . #start(
548+ state ,
549+ input . idleMs ,
550+ fresh ,
551+ lockWaitMs ,
552+ ) ;
442553 const started = await this . #load( ) ;
443554 return {
444555 kind : "ready" ,
0 commit comments