[Bug]: Thread snapshot HTTP handlers have no server-side timeout; cold-open herd times out at 6s and floods relay logs with context-canceled warnings #17765

Activity

1. josephv123 commented on Oct 15, 2026

   

   josephv123

   on Oct 15, 2026

   Contributor

   More actions

   Consolidated independent reproduction of the shared-writer part of this issue. Verified source at e536bfd33bc3c351997141d93790df75eeded7b9; the relevant projection/SQLite files are unchanged from the original audit at ec1313c8f8333292506f05a355bb72d308a455d8.

   A tiny synthetic WAL database with one thread and one completed tool item is enough: a worker connection takes BEGIN IMMEDIATE, signals that it holds the lock, and releases it after 3,000 ms. The main process then schedules a 1 ms heartbeat and calls the production getThreadSnapshotWindow method. The control wraps that exact method in T3's existing NodeSqliteClient.readOnly helper. No provider, relay, real history or large fixture is needed.

   Retained Node 24.21.0, Linux, alternating two rounds:

   Arm	Snapshot time	1 ms heartbeat actually fired after
   Default, round 1	3,046.7 ms	3,046.8 ms
   Reader control, round 1	37.4 ms	1.2 ms
   Reader control, round 2	4.6 ms	0.7 ms
   Default, round 2	3,041.2 ms	3,041.3 ms

   Re-running the same portable synthetic probe during consolidation under Node 26.10.0 gave 3,047.3 ms versus 1.33 ms heartbeat delay. Both returned the same one-item snapshot. The first reader use includes worker startup.

   The causal path is:

   • getThreadSnapshotWindow uses sql.withTransaction without readOnly.
   • NodeSqliteClient routes unmarked work to the synchronous writer, whose transaction uses BEGIN IMMEDIATE.
   • Sqlite.ts sets a 5,000 ms busy timeout. The native synchronous wait prevents an Effect timeout or unrelated JS callback from running until it returns.

   Minimal experimental sequence for a checkout-level regression test:

   seed via T3 migrations + ProjectionStore.apply(thread.created, turn-item.updated)
   worker: open same temporary WAL DB; BEGIN IMMEDIATE; signal held
   main after held: setTimeout(heartbeat, 1); call getThreadSnapshotWindow
   worker: ROLLBACK after 3000 ms
   repeat with identical read effect wrapped in NodeSqliteClient.readOnly
   

   The complete checkout probe is included below. The worker hold is an experimental input, not a measured production lock frequency. No multi-second stall appeared in the retained production trace windows, so this is a controlled root-cause reproduction, not a claim that every slow cold-open has this cause. No live database was modified.

   Complete checkout-level reproduction (temporary synthetic database only)

   Install this checkout's normal development dependencies, save the following as snapshot-contention.mjs, and run from the repository root with Node 24:

   node /path/to/snapshot-contention.mjs synthetic results.json 3000 2

   The script imports production services from the current working directory. It uses a worker to release the experimental write lock independently of the blocked main loop and removes its synthetic fixture on completion. Do not substitute a live database path for synthetic.

   import {createRequire} from 'node:module';
   const repo=process.env.T3_AUDIT_REPO??process.cwd();
   const req=createRequire(path.join(repo,'apps/server/package.json'));
   const Effect=await import(req.resolve('effect/Effect'));
   const Layer=await import(req.resolve('effect/Layer'));
   const Tracer=await import(req.resolve('effect/Tracer'));
   const Deferred=await import(req.resolve('effect/Deferred'));
   const Fiber=await import(req.resolve('effect/Fiber'));
   const Stream=await import(req.resolve('effect/Stream'));
   const SqlClient=await import(req.resolve('effect/sql/SqlClient'));
   const ManagedRuntime=await import(req.resolve('effect/ManagedRuntime'));
   const DateTime=await import(req.resolve('effect/DateTime'));
   const NodeServices=await import(req.resolve('@effect/platform-node/NodeServices'));
   const NodeSqlite=await import(path.join(repo,'packages/shared/src/nodeSqliteClient.ts'));
   const Store=await import(path.join(repo,'apps/server/src/orchestration-v2/ProjectionStore.ts'));
   const Wire=await import(path.join(repo,'apps/server/src/orchestration-v2/WireProjection.ts'));
   const History=await import(path.join(repo,'apps/server/src/orchestration-v2/threadHistoryPaging.ts'));
   const SqlitePersistence=await import(path.join(repo,'apps/server/src/persistence/Sqlite.ts'));
   function openRuntime(filename){
    if(filename.includes('/.t3/userdata/'))throw new Error('Use a copied database only');
    return ManagedRuntime.make(Store.layer.pipe(Layer.provideMerge(NodeSqlite.layer({filename,readerWorker:true,checkpointWorker:false}))));
   }
   
   import {Worker} from 'node:worker_threads';
   import {DatabaseSync} from 'node:sqlite';
   import {once} from 'node:events';
   import {performance} from 'node:perf_hooks';
   import fs from 'node:fs';
   import os from 'node:os';
   import path from 'node:path';
   
   let filename=process.argv[2];const output=process.argv[3];
   const holdMs=Number(process.argv[4]??350),rounds=Number(process.argv[5]??6);
   const synthetic=!filename||filename==='synthetic';
   if(synthetic){
    filename=path.join(fs.mkdtempSync(path.join(os.tmpdir(),'t3-snapshot-contention-')),'statev2.sqlite');
    const seed=ManagedRuntime.make(Store.layer.pipe(Layer.provideMerge(SqlitePersistence.layerFromPath(filename)),Layer.provide(NodeServices.layer)));
    try{await seed.runPromise(Effect.gen(function*(){
     const p=yield*Store.ProjectionStoreV2,at=yield*DateTime.now;
     const threadId='audit:thread';
     yield*p.apply({id:'audit:event:create',type:'thread.created',threadId,occurredAt:at,payload:{id:threadId,projectId:'audit:project',title:'Synthetic audit thread',providerInstanceId:'codex',modelSelection:{instanceId:'codex',model:'audit-model'},runtimeMode:'full-access',interactionMode:'default',branch:null,worktreePath:null,activeProviderThreadId:null,lineage:{parentThreadId:null,relationshipToParent:null,rootThreadId:threadId},forkedFrom:null,createdBy:'user',creationSource:'web',createdAt:at,updatedAt:at,archivedAt:null,deletedAt:null,settledOverride:null,settledAt:null,lastVisitedAt:null}});
     yield*p.apply({id:'audit:event:item',type:'turn-item.updated',threadId,occurredAt:at,payload:{id:'audit:item',type:'command_execution',threadId,runId:null,nodeId:null,providerThreadId:null,providerTurnId:null,nativeItemRef:null,parentItemId:null,ordinal:1,status:'completed',title:'Synthetic command',input:'true',output:'ok',exitCode:0,startedAt:at,completedAt:at,updatedAt:at}});
    }));}finally{await seed.dispose();}
   }
   const c=new DatabaseSync(filename,{readOnly:true});
   const t=c.prepare(`SELECT t.thread_id,count(*) items FROM orchestration_v2_projection_threads t JOIN orchestration_v2_projection_turn_items i USING(thread_id) WHERE t.deleted_at IS NULL GROUP BY t.thread_id ORDER BY items LIMIT 1`).get();c.close();
   const runtime=openRuntime(filename);
   const results=[];
   let sqlRecords=[];
   const tracer=Tracer.make({span(o){const s=new Tracer.NativeSpan(o),end=s.end.bind(s);s.end=(at,exit)=>{end(at,exit);if(s.name==='sqlite'||s.name==='sql.transaction')sqlRecords.push({name:s.name,ms:Number(at-s.startTime)/1e6,connection:s.attributes.get('db.connection'),lock_wait_ms:s.attributes.get('db.lock_wait_ms'),query:s.attributes.get('db.query.text')});};return s;}});
   const workerCode=`const {parentPort,workerData}=require('node:worker_threads');const{DatabaseSync}=require('node:sqlite');const db=new DatabaseSync(workerData.filename);db.exec('PRAGMA busy_timeout=5000');parentPort.on('message',async m=>{if(m==='hold'){db.exec('BEGIN IMMEDIATE');parentPort.postMessage('held');setTimeout(()=>{db.exec('ROLLBACK');parentPort.postMessage('released');},workerData.holdMs);}if(m==='close'){db.close();parentPort.close();}});parentPort.postMessage('ready');`;
   const blocker=new Worker(workerCode,{eval:true,workerData:{filename,holdMs}});
   try{
    await once(blocker,'message');
    await runtime.runPromise(Effect.gen(function*(){const sql=yield* SqlClient.SqlClient;yield* sql`PRAGMA busy_timeout=5000`;yield* sql`PRAGMA journal_mode=WAL`;}));
    for(let round=0;round<rounds;round++)for(const mode of round%2?['reader-control','default']:['default','reader-control']){
     const held=once(blocker,'message');blocker.postMessage('hold');const [msg]=await held;if(msg!=='held')throw new Error('Expected held');
     const release=once(blocker,'message');
     const start=performance.now();let heartbeatMs;
     const heartbeat=new Promise(resolve=>setTimeout(()=>{heartbeatMs=performance.now()-start;resolve();},1));
     let op=Effect.gen(function*(){return yield* (yield* Store.ProjectionStoreV2).getThreadSnapshotWindow(t.thread_id,{rowLimit:77,userTurnLimit:10});});
     if(mode==='reader-control')op=NodeSqlite.readOnly(op);
     sqlRecords=[];
     const snap=await runtime.runPromise(op.pipe(Effect.withTracer(tracer)));const snapshotMs=performance.now()-start;
     await heartbeat;await release;
     const row={round,mode,hold_ms:holdMs,synthetic,snapshot_ms:snapshotMs,heartbeat_ms:heartbeatMs,retained_items:snap.projection.turnItems.length,sql:sqlRecords};results.push(row);
     console.log(JSON.stringify({...row,sql:undefined}));
    }
    if(output)fs.writeFileSync(output,JSON.stringify(results,null,2));
   }finally{
    blocker.postMessage('close');await once(blocker,'exit');await runtime.dispose();
    if(synthetic)fs.rmSync(path.dirname(filename),{recursive:true,force:true});
   }
2. juliusmarminge commented on Oct 21, 2026

   

   juliusmarminge

   on Oct 21, 2026 – with GitCafe Production

   Last edited by juliusmarminge

   Member

   More actions

   Tested current main 70e5e384da on Linux, Node 24.21.0, Chrome web via vp run dev, using isolated state. An existing populated stopped thread opened successfully. A larger synthetic projection fixture (100 stopped threads × 300 completed command items, 3 KB output/item; 125 MB SQLite file) also opened successfully in a fresh incognito profile. The sidebar contained 100 fixture rows, but opening it requested the selected conversation's snapshot, rather than a snapshot for every sidebar row.

   A browser-issued burst of 100 distinct bounded-snapshot HTTP requests with 6,000 ms abort deadlines returned 100 HTTP 200 responses in 145–1,513 ms. Opening a populated fixture through the UI returned HTTP 200 in 23 ms server-side:

   GET /api/orchestration/threads/triage%3A17765%3Athread%3A1/bounded
   http.span=23ms
   http.status=200
   

   The controlled writer-lock probe in the existing comment is separate evidence; these results do not disprove contention under that condition. The cloudflared/relay path was not verified.

   Please provide the current affected build, approximate database size/thread/item counts, the exact UI steps that mount multiple conversations during a cold open, and sanitized request timings showing the bounded requests timing out and falling back. Those details would distinguish the cold-open trigger from the independently demonstrated injected-lock stall. No database contents or credentials are needed.
3. juliusmarminge

   added

   needs more infoInitial triage showed no bug. Awaiting more infoInitial triage showed no bug. Awaiting more info

   on Oct 21, 2026