Skip to content

[Hackathon] fix(create-batch): rounding remaining wait budget down causes premature timeouts #480

Open

Description

@luckyzd

Verified against (commit SHA or released version)

988c035 (public main rechecked 2026-10-17; package 0.14.0), Node.js v22.23.2, macOS

Discord Username / User ID

luckyzd.

What does this improvement do?

Preserve the remaining per-test wait budget in test create-batch --run --wait. runBatchRun currently floors the remaining milliseconds to whole seconds before starting its poller, discarding up to almost one second. An ordinary successful trigger can therefore make the command time out a test before the requested budget expires, even when that test completes inside the original budget.

Executed example: with --timeout 2, a 250 ms trigger response, and a run that completes 1.5 seconds after the first trigger attempt, the CLI stops at about 1.25 seconds with status: "timeout", exit 7. Roughly 750 ms of the two-second budget remains. Both a passing and a failing terminal result are missed. The run ID is retained; this report is about the incorrect timeout/verdict, not lost IDs.

This is a Season 4 hackathon issue-first submission. Evidence is an executed offline command-chain reproduction with real timers and documented long-poll behavior, not a hosted-service incident. No malformed responses, transport errors, signal interruption, clock mocking or real credentials are used. A transient rate-limit retry is covered separately; the baseline reproduces using only successful HTTP responses.

Details / implementation notes

Trigger and actual behavior

Use an ordinary valid frontend plan and run:

testsprite test create-batch --plans plans.jsonl --run --wait --timeout 2 --output json
  1. Batch creation succeeds.
  2. At the start of the trigger attempt, the CLI establishes a per-spec deadline of now + 2000 ms.
  3. The trigger returns an accepted run ID about 250 ms later. About 1750 ms remains.
  4. Math.floor(rem / 1000) || 1 converts that to 1 second. The poller starts a new one-second deadline and requests GET /runs/run_a?waitSeconds=1.
  5. The run will complete at t=1500 ms. The long poll legitimately returns running at about t=1250 ms because its requested one-second window expired.
  6. The shortened poll deadline has now expired, so the CLI exits 7 without observing the terminal result. A follow-up read of the same fixture run returns passed (or failed) with a finishedAt inside the original budget.

Actual result, irrelevant fields omitted:

{"results":[{"testId":"a","runId":"run_a","status":"timeout","error":{"code":"UNSUPPORTED","message":"Timed out after 2s waiting for run run_a.","exitCode":7}}]}

Expected: retain the original remaining time and observe a terminal result arriving within that budget. Passed should exit 0; failed should exit 1. An actually expired budget must still avoid further dispatch/polling. The same rounding can occur near the end of larger configured budgets; the short test values keep the reproduction quick.

Source and supported contract

The fix should preserve the original remaining deadline rather than restart the full timeout after retry. Passing fractional seconds or an absolute deadline can avoid both truncation and granting an extra second after expiration; final implementation should retain the existing no-poll-after-expiry guard.

Seven executed scenarios

All times below are relative to the member's first trigger request. The fixture delays a successful trigger by 250 ms. Timers and Date.now are real.

Scenario Budget Terminal at CLI stops at Actual outcome
Fast passed control 2 s 0.8 s ~0.8 s passed / exit 0
Passed inside original budget 2 s 1.5 s ~1.25 s timeout / exit 7
Failed inside original budget 2 s 1.5 s ~1.25 s timeout / exit 7, not failed
Larger-budget passed control 3 s 1.5 s ~1.5 s passed / exit 0
Two members: 0.8 s and 1.5 s, both pass 2 s each 0.8 / 1.5 s ~1.25 s passed + timeout / exit 1
First trigger 429, real 1 s Retry-After, then accepted 3 s 2.5 s ~2.25 s timeout / exit 7
Same retry with larger budget 4 s 2.5 s ~2.5 s passed / exit 0

The retry controls also assert that both attempts use the same per-test idempotency key. The script checks every result's test/run association and reads the fixture again after completion to verify the actual terminal status. Product source is unchanged. Build passed; existing test.create-batch-run.spec.ts and poll.spec.ts passed: 97 tests, 2 files, 4.23 seconds. Existing green tests do not cover this fractional remaining-budget case.

Duplicate check

Searched open and closed Issues/PRs for create-batch with timeout/early/deadline, remainingSeconds, Math.floor, throttle+deadline and floor+timeout, and read the related reports/review discussions.

No matching fractional-budget report was found. I will wait for maintainer acceptance and assignment before implementation or a PR. AI disclosure: Codex assisted with source review, reproduction and duplicate checking.

Self-contained executable reproduction

Build the pinned checkout with npm ci && npm run build. Save the script below outside the checkout and run node repro.mjs /absolute/path/to/testsprite-cli. It takes about 12 seconds, uses only in-process HTTP fixtures, and prints seven result envelopes and timing/request traces. Assertions capture the affected revision's current behavior, so a successful script exit means that the described behavior and controls were reproduced.

Seven-case real-timer reproduction
import assert from 'node:assert/strict';
import {mkdtemp,writeFile,rm} from 'node:fs/promises';
import {tmpdir} from 'node:os';
import {join,resolve} from 'node:path';
import {pathToFileURL} from 'node:url';
import {createRequire} from 'node:module';

// Offline HTTP fixture with actual timers: emulate documented long polling,
// returning at min(waitSeconds, completion). Commander/client/poller unchanged.
const root=resolve(process.argv[2]??'work/testsprite-cli');
const require=createRequire(join(root,'package.json'));
const {Command}=require('commander');
const {createTestCommand}=await import(pathToFileURL(join(root,'dist/commands/test.js')));
const temp=await mkdtemp(join(tmpdir(),'testsprite-early-timeout-'));
const delay=ms=>new Promise(resolve=>setTimeout(resolve,Math.max(0,ms)));
const json=(body,status=200,headers={})=>new Response(JSON.stringify(body),{status,headers:{'content-type':'application/json',...headers}});
const scenarios=[
 {name:'fast-run-control',timeout:2,finishMs:800,verdict:'passed',expectedExit:0},
 {name:'budget-not-exhausted-pass',timeout:2,finishMs:1500,verdict:'passed',expectedExit:7},
 {name:'budget-not-exhausted-fail',timeout:2,finishMs:1500,verdict:'failed',expectedExit:7},
 {name:'larger-budget-control',timeout:3,finishMs:1500,verdict:'passed',expectedExit:0},
 {name:'two-member-batch',timeout:2,finishMs:1500,verdict:'passed',count:2,expectedExit:1},
 {name:'after-rate-retry',timeout:3,finishMs:2500,verdict:'passed',retry:true,expectedExit:7},
 {name:'retry-larger-budget-control',timeout:4,finishMs:2500,verdict:'passed',retry:true,expectedExit:0},
];
const results=[];
try{
 for(const s of scenarios){
  const ids=s.count===2?['a','b']:['a'];
  const plans=join(temp,s.name+'.jsonl');
  await writeFile(plans,ids.map(id=>JSON.stringify({projectId:'project',type:'frontend',name:'Case '+id,planSteps:[{type:'action',description:'Open home '+id}]})).join('\n')+'\n');
  const stdout=[],stderr=[],trace=[],starts=new Map(),attempts=new Map(),completedAt=new Map();
  let exitAt=0;
  const deps={env:{TESTSPRITE_API_KEY:'sk-user-offline-fixture',TESTSPRITE_API_URL:'https://mock.example.com'},credentialsPath:join(temp,'absent'),stdout:x=>stdout.push(x),stderr:x=>stderr.push(x),
   fetchImpl:async(input,init={})=>{
    const u=new URL(typeof input==='string'?input:input.url??input.href);assert.equal(u.hostname,'mock.example.com');
    const path=u.pathname.replace('/api/cli/v1',''),method=init.method??'GET';
    const event={method,path,query:Object.fromEntries(u.searchParams),at:Date.now()};trace.push(event);
    if(path==='/projects/project/env')return json({environments:[{name:'default',url:'https://example.com',isDefault:true,isTemporary:false}]});
    if(path==='/tests/batch'&&method==='POST')return json({results:ids.map((id,specIndex)=>({specIndex,testId:id,status:'created'})),summary:{total:ids.length,created:ids.length,failed:0}});
    const trigger=/^\/tests\/(a|b)\/runs$/.exec(path);
    if(trigger&&method==='POST'){
     const id=trigger[1],attempt=(attempts.get(id)??0)+1;attempts.set(id,attempt);
     if(!starts.has(id))starts.set(id,Date.now());
     event.attempt=attempt;event.idempotencyKey=new Headers(init.headers).get('idempotency-key');
     if(s.retry&&attempt===1)return json({error:{code:'RATE_LIMITED',message:'Run trigger rate limit exceeded: 60 triggers per minute per key.',nextAction:'Wait.',requestId:'fixture',details:{retryAfterSeconds:1}}},429,{'retry-after':'1'});
     await delay(250);
     const finishMs=s.count===2&&id==='a'?800:s.finishMs;
     completedAt.set(id,starts.get(id)+finishMs);
     return json({runId:'run_'+id,status:'queued',enqueuedAt:new Date(starts.get(id)).toISOString(),codeVersion:'v1',targetUrl:'https://example.com'});
    }
    const poll=/^\/runs\/run_(a|b)$/.exec(path);
    if(poll){
     const id=poll[1],start=starts.get(id),finish=completedAt.get(id);
     assert.ok(start&&finish);const waitSeconds=Number(u.searchParams.get('waitSeconds')??0);
     await delay(Math.min(Math.max(0,finish-Date.now()),waitSeconds*1000));
     const terminal=Date.now()>=finish,status=terminal?(s.count===2&&id==='a'?'passed':s.verdict):'running';
     event.returnAt=Date.now();event.status=status;
     return json({runId:'run_'+id,testId:id,projectId:'project',userId:'fixture',status,source:'cli',createdAt:new Date(start).toISOString(),startedAt:new Date(start+250).toISOString(),finishedAt:terminal?new Date(finish).toISOString():null,codeVersion:'v1',targetUrl:'https://example.com',createdFrom:'cli',failedStepIndex:status==='failed'?0:null,failureKind:status==='failed'?'assertion':null,error:null,videoUrl:null,stepSummary:{total:1,completed:terminal?1:0,passedCount:status==='passed'?1:0,failedCount:status==='failed'?1:0}});
    }
    throw Error('Unexpected fixture route '+method+' '+path);
   }};
  const args=['--output','json','test','create-batch','--plans',plans,'--run','--wait','--timeout',String(s.timeout),'--max-concurrency','2'];
  let exitCode=0,error;
  try{await new Command('testsprite').option('--output <mode>').addCommand(createTestCommand(deps)).parseAsync(args,{from:'user'});}
  catch(e){exitCode=e.exitCode??1;error={name:e.name,code:e.code,message:e.message,exitCode:e.exitCode};}
  exitAt=Date.now();assert.equal(exitCode,s.expectedExit,s.name+': '+JSON.stringify(error));
  const payload=JSON.parse(stdout.join('\n'));assert.equal(payload.results.length,ids.length);
  const timings=ids.map(id=>({testId:id,elapsedMs:exitAt-starts.get(id),budgetMs:s.timeout*1000,fixtureCompletionMs:completedAt.get(id)-starts.get(id),remainingAtExitMs:starts.get(id)+s.timeout*1000-exitAt}));
  for(const row of payload.results){
   assert.equal(row.runId,'run_'+row.testId);
   const affected=s.expectedExit!==0&&!(s.count===2&&row.testId==='a');
   assert.equal(row.status,affected?'timeout':'passed');
   if(affected){const timing=timings.find(t=>t.testId===row.testId);assert.ok(timing.remainingAtExitMs>400,JSON.stringify(timing));assert.ok(timing.elapsedMs<timing.fixtureCompletionMs);assert.ok(timing.fixtureCompletionMs<timing.budgetMs);}
  }
  if(s.retry){const triggers=trace.filter(x=>x.method==='POST'&&x.path.endsWith('/runs'));assert.equal(triggers.length,2);assert.equal(triggers[0].idempotencyKey,triggers[1].idempotencyKey);}
  // Read the same fixture after its real terminal instant, proving the eventual
  // status and run ID rather than relying only on a scheduled completion time.
  await delay(Math.max(...completedAt.values())-Date.now()+5);
  const observed=[];
  for(const id of ids){const response=await deps.fetchImpl('https://mock.example.com/api/cli/v1/runs/run_'+id);const row=await response.json();assert.equal(row.status,s.count===2&&id==='a'?'passed':s.verdict);observed.push({runId:row.runId,status:row.status,finishedAt:row.finishedAt});}
  results.push({name:s.name,args,exitCode,error,timings,payload,observed,trace,stderr});
 }
 console.log(JSON.stringify({baseline:'988c0355bb05631e9c6c1785e443937ff2a88c0e',node:process.version,scope:'offline real-timer long-poll fixture, not hosted observation',results},null,2));
}finally{await rm(temp,{recursive:true,force:true});}

Confirmations

  • I have searched existing issues and this is not a duplicate.
  • I have provided my Discord identity above for reward coordination.

Activity

  1. zeshi-du commented on Oct 20, 2026

    @zeshi-du
    Contributor

    Thanks @luckyzd. Confirmed: in runBatchRun the remaining budget is floored to whole seconds (1s when under one) before polling, so up to a second of --timeout is lost, or occasionally overshot. It is a real incorrect timeout, so we're accepting it (low priority).

    Scope:

    • Change only that conversion; keep the "budget already expired, don't poll" guard as is.
    • Carry the fractional remainder through (fractional seconds work with the poller as is, or add an optional ms option). Leave the poller's whole-second long-poll rounding and timeout messages alone.
    • No exit code or other-caller behaviour changes.

    Tests: a mock-based test that fails before the fix (run finishing inside the original budget, passed and failed), plus one confirming an expired budget still doesn't poll.

    This touches the same function as your #485, so land them together or coordinate order. Don't touch rerun paths or rename anything; the command surface is being restructured. Claim it with /assign.

  2. added
    acceptedTriaged and accepted — a PR for this will be reviewed
    and removed
    needs-triageNew issue/PR awaiting first triage
    on Oct 20, 2026
  3. luckyzd commented on Oct 20, 2026

    @luckyzd
    Author

    /assign

  4. testsprite-hob commented on Oct 20, 2026

    @testsprite-hob

    Assigned to @luckyzd. Thanks for taking this on. (1 more slot available.)

    Your open assigned issues (2/3):

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

acceptedTriaged and accepted — a PR for this will be reviewedhackathonCLI hackathon submissionsin-progressAssigned and actively being worked on

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions