Skip to content

Commit e348e71

Browse files
committed
fix(server): order step lists and job logs by execution position
Three symptoms, one missing definition: nothing said what order a mixed manifest is in. - the whole-job concatenation sorted by step id, and a step id is a v4 UUID, so an unfiltered read emitted the log in random order (the mtime sort it replaced was at least an approximation) - the run projection copied the raw manifest, which is seeded-then- appended, so Set up job rendered after the declared steps despite runner_number 1 - the restore query ordered by kind as text, where 'synthetic' sorts before 'workflow', so a restart silently flipped the order a job detail showed — contradicting the comment claiming it came back as recorded StepRecord::sort_execution_order is now the single rule: the runner's reported number when known, the declared manifest position otherwise (biased after anything reported), step id only as a deterministic tie-break. Applied at the run projection, at the whole-job concatenation, and in both backends' restore queries. --step is unaffected: it still filters to declared steps and indexes workflow_index, so synthetic steps take no slot. Reported on #212 by Codex, CodeRabbit and Cubic.
1 parent 839daf5 commit e348e71

5 files changed

Lines changed: 176 additions & 15 deletions

File tree

‎crates/preloop-runner-server/src/lib_tests.rs‎

Lines changed: 93 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2893,6 +2893,99 @@ async fn step_manifests_survive_a_restart() {
28932893
);
28942894
}
28952895

2896+
/// Every surface showing a whole step list uses execution order.
2897+
///
2898+
/// The stored manifest is seeded with declared steps and then appends
2899+
/// synthetic ones as the runner reports them, so its raw order puts
2900+
/// `Set up job` last despite it running first. A step id is a v4 UUID, so it
2901+
/// cannot supply the order either.
2902+
#[tokio::test]
2903+
async fn step_lists_and_job_logs_follow_execution_order() {
2904+
let temp = tempfile::tempdir().unwrap();
2905+
let state = AppState::new(temp.path().to_path_buf()).await.unwrap();
2906+
let app = app(state.clone(), CancellationToken::new());
2907+
let (run_id, jobs) = three_step_run_for_log_filters(&app, &state).await;
2908+
let ids = workflow_step_ids(&state, run_id, "build").await;
2909+
let (plan_id, agent_job_id) = (jobs[0].1.clone(), jobs[0].2.clone());
2910+
2911+
// The runner reports `Set up job` first, then the declared steps at the
2912+
// offset positions the golden capture shows (declared step 1 is number 2).
2913+
let setup_id = uuid::Uuid::new_v4().to_string();
2914+
let report = |external_id: &str, number: u64, name: &str| {
2915+
serde_json::json!({
2916+
"external_id": external_id,
2917+
"number": number,
2918+
"name": name,
2919+
"status": 6,
2920+
"conclusion": 2
2921+
})
2922+
};
2923+
let response = request_json(
2924+
&app,
2925+
Method::POST,
2926+
"/twirp/github.actions.results.api.v1.WorkflowStepUpdateService/WorkflowStepsUpdate",
2927+
json!({
2928+
"workflow_run_backend_id": plan_id,
2929+
"workflow_job_run_backend_id": agent_job_id,
2930+
"steps": [
2931+
report(&setup_id, 1, "Set up job"),
2932+
report(&ids[0], 2, "Run echo one"),
2933+
report(&ids[1], 3, "Run echo two"),
2934+
report(&ids[2], 4, "Run echo three"),
2935+
]
2936+
}),
2937+
)
2938+
.await;
2939+
assert_eq!(response["ok"], true);
2940+
2941+
// The run record lists the synthetic setup step first.
2942+
let run = get_run_json(&app, &run_id.to_string()).await;
2943+
let names: Vec<&str> = run["jobs_list"][0]["steps"]
2944+
.as_array()
2945+
.unwrap()
2946+
.iter()
2947+
.map(|step| step["name"].as_str().unwrap_or_default())
2948+
.collect();
2949+
assert_eq!(
2950+
names,
2951+
vec![
2952+
"Set up job",
2953+
"Run echo one",
2954+
"Run echo two",
2955+
"Run echo three"
2956+
],
2957+
"the run record must show execution order, not seeded-then-appended"
2958+
);
2959+
2960+
// The whole-job log concatenates in the same order, even though the ids
2961+
// sort differently.
2962+
write_step_job_logs(
2963+
&temp,
2964+
&plan_id,
2965+
&agent_job_id,
2966+
&[
2967+
(ids[2].as_str(), "three\n"),
2968+
(ids[0].as_str(), "one\n"),
2969+
(setup_id.as_str(), "setup\n"),
2970+
(ids[1].as_str(), "two\n"),
2971+
],
2972+
)
2973+
.await;
2974+
let (status, body) = get_logs(&app, format!("/api/v1/runs/{run_id}/logs?job=build")).await;
2975+
assert_eq!(status, StatusCode::OK);
2976+
assert_eq!(
2977+
String::from_utf8_lossy(&body),
2978+
"setup\none\ntwo\nthree\n",
2979+
"whole-job output must follow execution order"
2980+
);
2981+
2982+
// `--step` still counts declared steps only, so setup takes no slot.
2983+
let (status, body) =
2984+
get_logs(&app, format!("/api/v1/runs/{run_id}/logs?job=build&step=1")).await;
2985+
assert_eq!(status, StatusCode::OK);
2986+
assert_eq!(body, b"one\n");
2987+
}
2988+
28962989
/// A completion reconciles the attempt that actually reported.
28972990
///
28982991
/// `job_requests` is keyed by monotonic request id, so picking the first match

‎crates/preloop-runner-server/src/models.rs‎

Lines changed: 30 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -143,6 +143,36 @@ impl StepRecord {
143143
.collect()
144144
}
145145

146+
/// Sort key placing a step in execution order.
147+
///
148+
/// `runner_number` is the runner's own 1-based timeline position and counts
149+
/// every step it ran, so it is the truth once reported. Until then a
150+
/// declared step falls back to its manifest position, biased past any
151+
/// reported number so freshly seeded steps trail what has actually run.
152+
/// A step id is a v4 UUID and sorts randomly, so it is only the final
153+
/// tie-break for determinism.
154+
fn execution_key(&self) -> (u32, usize, &str) {
155+
match self.runner_number {
156+
Some(number) => (number, 0, self.id.as_str()),
157+
None => (
158+
u32::MAX,
159+
self.workflow_index.unwrap_or(usize::MAX),
160+
self.id.as_str(),
161+
),
162+
}
163+
}
164+
165+
/// Order records as the job executed them.
166+
///
167+
/// The in-memory manifest is seeded with declared steps and then appends
168+
/// synthetic ones as the runner reports them, so its raw order puts
169+
/// `Set up job` after the workflow steps despite it running first. A
170+
/// restore adds a third order again. Every surface that shows a whole
171+
/// step list goes through this instead.
172+
pub(crate) fn sort_execution_order(steps: &mut [Self]) {
173+
steps.sort_by(|left, right| left.execution_key().cmp(&right.execution_key()));
174+
}
175+
146176
/// Locate a step by stable identity, and by nothing else.
147177
///
148178
/// Display names repeat legitimately — two steps may both be named `Test`

‎crates/preloop-runner-server/src/runs.rs‎

Lines changed: 49 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -2104,7 +2104,10 @@ pub(crate) fn latest_attempt_steps(
21042104
.filter(|request| request.run_id == run_id && request.job_id == *job_id)
21052105
.max_by_key(|request| request.request_id)
21062106
.map(|request| request.agent_job_id)?;
2107-
inner.job_steps.get(&agent_job_id).cloned()
2107+
let mut steps = inner.job_steps.get(&agent_job_id).cloned()?;
2108+
// The stored vector is seeded-then-appended, so it is not execution order.
2109+
StepRecord::sort_execution_order(&mut steps);
2110+
Some(steps)
21082111
}
21092112

21102113
pub(crate) async fn get_run(
@@ -2353,6 +2356,9 @@ async fn resolve_job_logs(
23532356
results_dir: &std::path::Path,
23542357
fallback_blocks: Vec<Vec<u8>>,
23552358
workflow_step_ids: Option<&[String]>,
2359+
// Every id the attempt's manifest knows, in execution order, used only to
2360+
// order the whole-job concatenation.
2361+
execution_step_ids: Option<&[String]>,
23562362
prefer_steps: bool,
23572363
) -> Result<JobLogs, ApiError> {
23582364
let merged = match tokio::fs::read(results_dir.join("job-logs.txt")).await {
@@ -2409,9 +2415,19 @@ async fn resolve_job_logs(
24092415
)));
24102416
}
24112417
}
2412-
// Only for the unfiltered read, where this is a concatenation order and
2413-
// not a step selector. `--step` goes through `workflow` below.
2414-
step_files.sort_by(|left, right| left.0.cmp(&right.0));
2418+
// Concatenation order comes from the manifest, which knows what ran when.
2419+
// A step id is a v4 UUID, so sorting by it emitted the whole-job log in
2420+
// random order; blobs the manifest does not know keep a stable tail.
2421+
let position = |id: &str| {
2422+
execution_step_ids
2423+
.and_then(|ids| ids.iter().position(|known| known == id))
2424+
.unwrap_or(usize::MAX)
2425+
};
2426+
step_files.sort_by(|left, right| {
2427+
position(&left.0)
2428+
.cmp(&position(&right.0))
2429+
.then_with(|| left.0.cmp(&right.0))
2430+
});
24152431

24162432
if !step_files.is_empty() {
24172433
let workflow = workflow_step_ids.filter(|ids| !ids.is_empty()).map(|ids| {
@@ -2590,21 +2606,31 @@ pub(crate) async fn get_run_logs(
25902606
}
25912607
});
25922608
// The attempt's own manifest, keyed by the agent job id that
2593-
// also names this request's results directory. Declared steps
2594-
// only: a synthetic "Set up job" record must not occupy a
2595-
// `--step` slot. The broker message is deliberately not
2596-
// consulted — it is broker delivery state that a restart or a
2597-
// retirement can drop, while the manifest is run state.
2598-
let workflow_step_ids = inner
2599-
.job_steps
2600-
.get(&request.agent_job_id)
2609+
// also names this request's results directory. The broker
2610+
// message is deliberately not consulted — it is broker
2611+
// delivery state that a restart or a retirement can drop,
2612+
// while the manifest is run state.
2613+
//
2614+
// Two views: declared steps in workflow order decide `--step`,
2615+
// because a synthetic "Set up job" record must not occupy a
2616+
// slot; every id in execution order decides the whole-job
2617+
// concatenation, where synthetic output belongs in place.
2618+
let manifest = inner.job_steps.get(&request.agent_job_id);
2619+
let workflow_step_ids = manifest
26012620
.map(|records| {
26022621
StepRecord::workflow_steps(records)
26032622
.into_iter()
26042623
.map(|step| step.id.clone())
26052624
.collect::<Vec<_>>()
26062625
})
26072626
.filter(|ids| !ids.is_empty());
2627+
let execution_step_ids = manifest
2628+
.map(|records| {
2629+
let mut ordered = records.clone();
2630+
StepRecord::sort_execution_order(&mut ordered);
2631+
ordered.into_iter().map(|step| step.id).collect::<Vec<_>>()
2632+
})
2633+
.filter(|ids| !ids.is_empty());
26082634
(
26092635
request.plan_id.clone(),
26102636
request.agent_job_id.to_string(),
@@ -2614,14 +2640,23 @@ pub(crate) async fn get_run_logs(
26142640
.map(|(_, block)| block.to_vec())
26152641
.collect::<Vec<_>>(),
26162642
workflow_step_ids,
2643+
execution_step_ids,
26172644
)
26182645
})
26192646
.collect::<Vec<_>>();
26202647
(shared.state.state_dir.clone(), sources)
26212648
};
26222649

26232650
let mut merged = Vec::new();
2624-
for (plan_id, agent_job_id, job_label, fallback_blocks, workflow_step_ids) in sources {
2651+
for (
2652+
plan_id,
2653+
agent_job_id,
2654+
job_label,
2655+
fallback_blocks,
2656+
workflow_step_ids,
2657+
execution_step_ids,
2658+
) in sources
2659+
{
26252660
let results_dir = state_dir
26262661
.join("replay")
26272662
.join("results")
@@ -2631,6 +2666,7 @@ pub(crate) async fn get_run_logs(
26312666
&results_dir,
26322667
fallback_blocks,
26332668
workflow_step_ids.as_deref(),
2669+
execution_step_ids.as_deref(),
26342670
query.step.is_some(),
26352671
)
26362672
.await?;

‎crates/preloop-runner-server/src/store.rs‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1417,7 +1417,8 @@ impl SqliteStore {
14171417
"SELECT agent_job_id, step_id, kind, workflow_index, runner_number,
14181418
context_name, name_blob, conclusion, started_at_us, finished_at_us
14191419
FROM job_steps
1420-
ORDER BY agent_job_id, kind, workflow_index, step_id",
1420+
ORDER BY agent_job_id, COALESCE(runner_number, 2147483647),
1421+
COALESCE(workflow_index, 2147483647), step_id",
14211422
)?;
14221423
for row in step_stmt.query_map([], |row| {
14231424
Ok((

‎crates/preloop-runner-server/src/store_pg.rs‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -624,7 +624,8 @@ impl Store for PgStore {
624624
"SELECT agent_job_id, step_id, kind, workflow_index, runner_number,
625625
context_name, name_blob, conclusion, started_at_us, finished_at_us
626626
FROM job_steps
627-
ORDER BY agent_job_id, kind, workflow_index, step_id",
627+
ORDER BY agent_job_id, COALESCE(runner_number, 2147483647),
628+
COALESCE(workflow_index, 2147483647), step_id",
628629
&[],
629630
)
630631
.await?;

0 commit comments

Comments
 (0)