Skip to main content

max / makenotwork

Key each step log on its run id Log paths were `<app>/<version>/<target>/<step>.log`, which is not unique: re-running an app at a version it already built reopened the same file and appended, so one file held two runs' output with nothing marking the boundary. Name the file for the step run id instead, so a ledger row resolves to exactly one file and the earlier run stays readable. The run id only exists once the row does, so `log_ref` is written back inside the same transaction rather than guessed ahead of the insert. The log route gained a `?run_id=`, defaulting to the highest run present, and still serves a pre-fix unsuffixed file when nothing newer exists. Each log now opens with a header naming its run, and shell steps echo the command before running it: a gate that prints nothing when it passes (`cargo fmt --all --check`) was indistinguishable from one that never ran. Closes the bento log-append task.
Co-Authored-By
Claude Opus 5 (1M context) <noreply@anthropic.com>
Author: Max Johnson <me@maxj.phd> · 2026-08-05 13:55 UTC
Signed with PGP, not checked
Commit: c435c5cd75f37560675a71ba311253c1a32b2f50
Parent: 2cfee03
6 files changed, +223 insertions, -25 deletions
M bento/daemon/Cargo.lock +28
@@ -3496,3 +3496,31 @@
3496 3496 version = "1.0.21"
3497 3497 source = "registry+https://github.com/rust-lang/crates.io-index"
3498 3498 checksum = "b8848ee67ecc8aedbaf3e4122217aff892639231befc6a1b58d29fff4c2cabaa"
3499 +
3500 + [[patch.unused]]
3501 + name = "docengine"
3502 + version = "0.4.0"
3503 +
3504 + [[patch.unused]]
3505 + name = "synckit-client"
3506 + version = "0.6.0"
3507 +
3508 + [[patch.unused]]
3509 + name = "synckit-config"
3510 + version = "0.1.2"
3511 +
3512 + [[patch.unused]]
3513 + name = "supernote-push"
3514 + version = "0.1.0"
3515 +
3516 + [[patch.unused]]
3517 + name = "kberg"
3518 + version = "0.1.0"
3519 +
3520 + [[patch.unused]]
3521 + name = "painhours"
3522 + version = "0.1.0"
3523 +
3524 + [[patch.unused]]
3525 + name = "tagtree"
3526 + version = "0.4.0"
M bento/deploy/bento-daemon.toml.example +1 -1
@@ -22,7 +22,7 @@
22 22 # Collected artifacts land at <dist_root>/<app>/<version>/.
23 23 dist_root = "/home/max/Dist"
24 24
25 - # Per-step run logs: <logs_root>/<app>/<version>/<target>/<step>.log
25 + # Per-step run logs: <logs_root>/<app>/<version>/<target>/<step>.<run_id>.log
26 26 logs_root = "/home/max/.local/state/bento/logs"
27 27
28 28 # Optional: override the per-step wall-clock budget (seconds) for EVERY step,
M bento/daemon/src/config.rs +1 -1
@@ -17,7 +17,7 @@
17 17 /// Where collected artifacts land (`<dist_root>/<app>/<version>/`).
18 18 pub dist_root: PathBuf,
19 19 /// Root for per-step run logs
20 - /// (`<logs_root>/<app>/<version>/<target>/<step>.log`).
20 + /// (`<logs_root>/<app>/<version>/<target>/<step>.<run_id>.log`).
21 21 #[serde(default = "default_logs_root")]
22 22 pub logs_root: PathBuf,
23 23 /// Override the per-step wall-clock budget (in seconds) for EVERY step,
M bento/daemon/src/engine.rs +58 -10
@@ -304,15 +304,27 @@
304 304 chrono::Utc::now().to_rfc3339()
305 305 }
306 306
307 - /// `<logs_root>/<app>/<version>/<target-with-slash-as-dash>/<step>.log`.
308 - fn log_path(&self, step: Step) -> PathBuf {
307 + /// `<logs_root>/<app>/<version>/<target-with-slash-as-dash>/<step>.<run_id>.log`.
308 + ///
309 + /// The run id is in the filename because the rest of the key is not unique:
310 + /// re-running an app at a version it already built (a retry, or a rebuild of
311 + /// an already-published release) reopens the same path, and the old file
312 + /// appended to shows two runs' output with nothing marking the boundary. The
313 + /// step ledger records a run id per step, so keying the file on it makes a
314 + /// ledger row resolve to exactly one file and keeps the earlier run readable.
315 + fn log_path(&self, step: Step, run_id: StepRunId) -> PathBuf {
316 + self.log_dir()
317 + .join(format!("{}.{}.log", step.as_str(), run_id.0))
318 + }
319 +
320 + /// `<logs_root>/<app>/<version>/<target-with-slash-as-dash>/`.
321 + fn log_dir(&self) -> PathBuf {
309 322 let target_dir = self.target.to_string().replace('/', "-");
310 323 self.cfg
311 324 .logs_root
312 325 .join(self.app.as_str())
313 326 .join(self.version.to_string())
314 327 .join(target_dir)
315 - .join(format!("{}.log", step.as_str()))
316 328 }
317 329
318 330 /// Close the previous step (as `Ok`), open a new one: insert its DB row,
@@ -325,24 +337,36 @@
325 337 );
326 338 self.finish_step(Status::Ok)?;
327 339 let me = self.clone();
340 + let started = Self::now();
341 + let started_for_header = started.clone();
328 342 let run_id = self.rt.block_on(async move {
329 - let started = Self::now();
330 - let log_ref = me.log_path(step).to_string_lossy().into_owned();
331 343 // The step row and the target's current_step pointer are one logical
332 344 // state — write them atomically so a failure can't leave a `running`
333 345 // step row while current_step still names the previous step.
334 346 let mut tx = me.pool.begin().await.context("begin step tx")?;
347 + // log_ref names the run id, which only exists once the row does, so
348 + // the path is written back inside the same transaction rather than
349 + // guessed beforehand.
335 350 let id: i64 = sqlx::query_scalar(
336 - "INSERT INTO step_runs (target_run_id, step, status, log_ref, started_at)
337 - VALUES (?, ?, 'running', ?, ?) RETURNING id",
351 + "INSERT INTO step_runs (target_run_id, step, status, started_at)
352 + VALUES (?, ?, 'running', ?) RETURNING id",
338 353 )
339 354 .bind(me.target_run_id)
340 355 .bind(step.as_str())
341 - .bind(&log_ref)
342 356 .bind(&started)
343 357 .fetch_one(&mut *tx)
344 358 .await
345 359 .context("insert step_run")?;
360 + let log_ref = me
361 + .log_path(step, StepRunId(id))
362 + .to_string_lossy()
363 + .into_owned();
364 + sqlx::query("UPDATE step_runs SET log_ref = ? WHERE id = ?")
365 + .bind(&log_ref)
366 + .bind(id)
367 + .execute(&mut *tx)
368 + .await
369 + .context("set step_run log_ref")?;
346 370 sqlx::query("UPDATE target_runs SET current_step = ? WHERE id = ?")
347 371 .bind(step.as_str())
348 372 .bind(me.target_run_id)
@@ -356,8 +380,8 @@
356 380 // Live log: each chunk fans out as a StepLogChunk event keyed by run_id.
357 381 let events = self.events.clone();
358 382 let cb_run_id = run_id;
359 - let log = self.rt.block_on(LiveLog::open(
360 - self.log_path(step),
383 + let mut log = self.rt.block_on(LiveLog::open(
384 + self.log_path(step, run_id),
361 385 Box::new(move |seq, text| {
362 386 events::emit(
363 387 &events,
@@ -381,6 +405,23 @@
381 405 },
382 406 );
383 407
408 + // A log that names its own run: reading one tells you which ledger row
409 + // it belongs to without going back to the DB, and a file that somehow
410 + // does get appended to still shows where the second run began. Written
411 + // after `StepStart` so its chunk event cannot precede the step it
412 + // belongs to.
413 + let header = format!(
414 + "=== bento {app} {version} {target} step={step} run_id={run_id} started={started_for_header} ===\n",
415 + app = self.app.as_str(),
416 + version = self.version,
417 + target = self.target,
418 + step = step.as_str(),
419 + );
420 + self.rt.block_on(async {
421 + use ops_core::remote::LogSink as _;
422 + log.write_chunk(header.as_bytes()).await;
423 + });
424 +
384 425 *self.current.lock().unwrap() = Some(StepState {
385 426 run_id,
386 427 step,
@@ -557,12 +598,19 @@
557 598 let exec = self.exec(host)?;
558 599 let cur = self.current_step();
559 600 let step = OpStep::shell(action, cmd.to_string());
601 + // Echo the command before running it. Without this a log says what
602 + // happened but not what was asked, and a gate that prints nothing when
603 + // it passes (`cargo fmt --all --check`) is indistinguishable from a gate
604 + // that never ran.
605 + let echo = format!("$ [{host}] {cmd}\n");
560 606 // Bounded by the step's deadline and interruptible on supersession, so a
561 607 // hung command fails its step instead of running unbounded, and a
562 608 // superseded build stops mid-step rather than only at the next boundary.
563 609 let label = format!("{cur} command on `{host}`");
564 610 let out = self.run_bounded(&label, async move {
611 + use ops_core::remote::LogSink as _;
565 612 let mut guard = sink.lock().await;
613 + guard.write_chunk(echo.as_bytes()).await;
566 614 exec.run_streaming(&step, &mut *guard).await
567 615 })?;
568 616 let code = out.status.code().unwrap_or(-1);
M bento/daemon/src/routes.rs +107 -8
@@ -406,9 +406,61 @@
406 406 .collect()
407 407 }
408 408
409 + #[derive(Deserialize)]
410 + pub(crate) struct StepLogQuery {
411 + /// Which run of this step to serve. Omitted, the newest wins.
412 + run_id: Option<i64>,
413 + }
414 +
415 + /// The file holding `step`'s output in `dir`.
416 + ///
417 + /// Logs are named `<step>.<run_id>.log` so re-running an app at a version it
418 + /// already built writes a new file instead of appending to the old one. The URL
419 + /// carries no run id, so without `?run_id=` this picks the highest — the run a
420 + /// reader asking for "the build log" means. Files written before the run id
421 + /// entered the name (`<step>.log`) are still served when nothing newer exists.
422 + async fn resolve_step_log(
423 + dir: &std::path::Path,
424 + step: &str,
425 + run_id: Option<i64>,
426 + ) -> Option<std::path::PathBuf> {
427 + if let Some(id) = run_id {
428 + let exact = dir.join(format!("{step}.{id}.log"));
429 + return tokio::fs::try_exists(&exact).await.ok()?.then_some(exact);
430 + }
431 + let mut entries = tokio::fs::read_dir(dir).await.ok()?;
432 + let mut newest: Option<(i64, std::path::PathBuf)> = None;
433 + while let Ok(Some(e)) = entries.next_entry().await {
434 + let name = e.file_name();
435 + let Some(name) = name.to_str() else { continue };
436 + let Some(rest) = name
437 + .strip_prefix(step)
438 + .and_then(|r| r.strip_prefix('.'))
439 + .and_then(|r| r.strip_suffix(".log"))
440 + else {
441 + continue;
442 + };
443 + let Ok(id) = rest.parse::<i64>() else {
444 + continue;
445 + };
446 + if newest.as_ref().is_none_or(|(best, _)| id > *best) {
447 + newest = Some((id, e.path()));
448 + }
449 + }
450 + match newest {
451 + Some((_, path)) => Some(path),
452 + // Legacy name, from before the run id was part of it.
453 + None => {
454 + let legacy = dir.join(format!("{step}.log"));
455 + tokio::fs::try_exists(&legacy).await.ok()?.then_some(legacy)
456 + }
457 + }
458 + }
459 +
409 460 async fn get_step_log(
410 461 State(s): State<AppState>,
411 462 Path((app, version, target, step)): Path<(String, String, String, String)>,
463 + axum::extract::Query(q): axum::extract::Query<StepLogQuery>,
412 464 ) -> Result<axum::response::Response> {
413 465 fn safe(seg: &str) -> bool {
414 466 !seg.is_empty() && !seg.contains('/') && !seg.contains('\\') && seg != "." && seg != ".."
@@ -419,13 +471,10 @@
419 471 {
420 472 return Err(Error::NotFound);
421 473 }
422 - let path = s
423 - .cfg
424 - .logs_root
425 - .join(&app)
426 - .join(&version)
427 - .join(&target)
428 - .join(format!("{step}.log"));
474 + let dir = s.cfg.logs_root.join(&app).join(&version).join(&target);
475 + let path = resolve_step_log(&dir, &step, q.run_id)
476 + .await
477 + .ok_or(Error::NotFound)?;
429 478 // Stream the log in chunks rather than reading the whole (potentially large,
430 479 // verbose-build) file into memory.
431 480 let file = match tokio::fs::File::open(&path).await {
@@ -685,11 +734,11 @@
685 734 assert_eq!(resp.status(), StatusCode::NOT_FOUND);
686 735 }
687 736
737 + /// A log written before the run id entered the filename is still served.
688 738 #[tokio::test]
689 739 async fn step_log_streams_existing_file() {
690 740 let tmp = tempfile::tempdir().unwrap();
691 741 let state = test_state(tmp.path()).await;
692 - // Write a log at the path the route resolves.
693 742 let dir = state
694 743 .cfg
695 744 .logs_root
@@ -712,6 +761,56 @@
712 761 assert_eq!(body_string(resp).await, "compiling\nlinked\n");
713 762 }
714 763
764 + /// Two runs of the same app/version/target/step no longer share a file, so
765 + /// the route has to choose: newest by default, exact on `?run_id=`. The
766 + /// legacy unsuffixed file must lose to any run-id-keyed one, or a stale
767 + /// pre-fix log would outrank every run since.
768 + #[tokio::test]
769 + async fn step_log_picks_newest_run_and_honours_run_id() {
770 + let tmp = tempfile::tempdir().unwrap();
771 + let state = test_state(tmp.path()).await;
772 + let dir = state
773 + .cfg
774 + .logs_root
775 + .join("goingson")
776 + .join("0.4.1")
777 + .join("linux-x86_64");
778 + std::fs::create_dir_all(&dir).unwrap();
779 + std::fs::write(dir.join("build.log"), b"legacy\n").unwrap();
780 + std::fs::write(dir.join("build.55.log"), b"run 55\n").unwrap();
781 + std::fs::write(dir.join("build.201.log"), b"run 201\n").unwrap();
782 + // Same prefix, different step: must not be mistaken for a run of `build`.
783 + std::fs::write(dir.join("build_extra.9.log"), b"other\n").unwrap();
784 +
785 + let fetch = |uri: &'static str| {
786 + let app = router(state.clone());
787 + async move {
788 + app.oneshot(Request::builder().uri(uri).body(Body::empty()).unwrap())
789 + .await
790 + .unwrap()
791 + }
792 + };
793 +
794 + let resp = fetch("/logs/goingson/0.4.1/linux-x86_64/build").await;
795 + assert_eq!(resp.status(), StatusCode::OK);
796 + assert_eq!(
797 + body_string(resp).await,
798 + "run 201\n",
799 + "highest run id wins, and 201 must beat 55 numerically rather than lexically"
800 + );
801 +
802 + let resp = fetch("/logs/goingson/0.4.1/linux-x86_64/build?run_id=55").await;
803 + assert_eq!(resp.status(), StatusCode::OK);
804 + assert_eq!(body_string(resp).await, "run 55\n");
805 +
806 + let resp = fetch("/logs/goingson/0.4.1/linux-x86_64/build?run_id=999").await;
807 + assert_eq!(
808 + resp.status(),
809 + StatusCode::NOT_FOUND,
810 + "an unknown run id is a miss, not a silent fall back to the newest"
811 + );
812 + }
813 +
715 814 #[tokio::test]
716 815 async fn bad_request_body_is_a_json_error_envelope() {
717 816 let tmp = tempfile::tempdir().unwrap();
M bento/daemon/src/runner.rs +28 -5
@@ -1303,12 +1303,35 @@
1303 1303 // Artifact landed in dist_root and a step log was written.
1304 1304 let artifact = state.cfg.dist_root.join("demo/0.0.1/demo.bin");
1305 1305 assert!(artifact.exists(), "collect should copy the artifact");
1306 - let log = state
1307 - .cfg
1308 - .logs_root
1309 - .join("demo/0.0.1/linux-x86_64/build.log");
1306 + // Read the path off the ledger rather than rebuilding it: the log is
1307 + // named for its step run id, and the point of that is that the row
1308 + // resolves to exactly one file.
1309 + let (run_id, log_ref): (i64, String) = sqlx::query_as(
1310 + "SELECT id, log_ref FROM step_runs WHERE step = 'build' AND target_run_id IN \
1311 + (SELECT id FROM target_runs WHERE build_id = ?)",
1312 + )
1313 + .bind(build_id)
1314 + .fetch_one(&pool)
1315 + .await
1316 + .unwrap();
1317 + let log = std::path::PathBuf::from(&log_ref);
1318 + assert_eq!(
1319 + log,
1320 + state
1321 + .cfg
1322 + .logs_root
1323 + .join(format!("demo/0.0.1/linux-x86_64/build.{run_id}.log")),
1324 + "log path should be keyed on the step run id"
1325 + );
1310 1326 assert!(log.exists(), "build step log should exist");
1311 - assert!(std::fs::read_to_string(&log).unwrap().contains("compiling"));
1327 + let body = std::fs::read_to_string(&log).unwrap();
1328 + assert!(body.contains("compiling"));
1329 + assert!(
1330 + body.starts_with(&format!(
1331 + "=== bento demo 0.0.1 linux/x86_64 step=build run_id={run_id} "
1332 + )),
1333 + "log should open with a run header naming its run: {body}"
1334 + );
1312 1335 }
1313 1336
1314 1337 /// Multi-target fan-out, which is what the daemon exists for: every other