Skip to content

Commit baec46d

Browse files
authored
fix(daemon): emit tracing around project lock acquire (#346) (#350)
Daemon state transitions to "Building" via OperationGuard *before* the per-project lock is taken. Without per-phase tracing, an indefinite stall on the lock looks identical to an indefinite stall inside the build itself — both surface to the user as "State: building" forever, with zero log lines telling them which phase is stuck. Emit a tracing::info before lock.lock().await, a tracing::warn at 10s if the lock is still being awaited, and a tracing::info on acquire with the actual wait time. With #348 now flushing daemon tracing to daemon.log, future hangs will localize within ~10s instead of being invisible. The 10s warn-threshold is well above normal lock contention (which should be sub-millisecond when no other build is running) but below the human-perceptible "is it hung?" window. After the warn fires the code continues to await the lock — this is observability, not a timeout, since silently dropping the lock and racing the holder would corrupt build outputs. Refs #346
1 parent f735366 commit baec46d

1 file changed

Lines changed: 37 additions & 1 deletion

File tree

  • crates/fbuild-daemon/src/handlers/operations

crates/fbuild-daemon/src/handlers/operations/build.rs

Lines changed: 37 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -143,10 +143,46 @@ pub async fn build(
143143
fbuild_core::DaemonState::Building,
144144
Some(format!("Building {}", project_dir_desc)),
145145
);
146+
// Daemon state goes to `Building` *before* the lock is taken
147+
// (the OperationGuard above). Without per-phase tracing, an
148+
// indefinite stall here looks identical to an indefinite
149+
// stall inside the build itself — both surface as
150+
// "State: building" forever. Emit a tracing event around the
151+
// lock acquire so daemon.log shows when the daemon is queued
152+
// behind another build vs. actually compiling. See #346
153+
// finding (2). The 10s warn-threshold is well above normal
154+
// contention but below any human-perceptible "is it hung?"
155+
// window, so a stuck lock surfaces in the log within seconds
156+
// instead of being invisible.
146157
let lock_wait_start = std::time::Instant::now();
147158
let lock = ctx.project_lock(&project_dir);
148-
let _lock_guard = lock.lock().await;
159+
tracing::info!("waiting for project lock on {}", project_dir_desc);
160+
const LOCK_WAIT_WARN: std::time::Duration = std::time::Duration::from_secs(10);
161+
let _lock_guard = {
162+
let acquire = lock.lock();
163+
match tokio::time::timeout(LOCK_WAIT_WARN, acquire).await {
164+
Ok(guard) => guard,
165+
Err(_) => {
166+
tracing::warn!(
167+
"project lock on {} not acquired within {}s — \
168+
another build is still holding it. Continuing \
169+
to wait; if this persists the daemon may be \
170+
stuck. Inspect ~/.fbuild/<env>/daemon/daemon.log \
171+
or run `fbuild daemon locks` to see who is \
172+
holding the lock.",
173+
project_dir_desc,
174+
LOCK_WAIT_WARN.as_secs(),
175+
);
176+
lock.lock().await
177+
}
178+
}
179+
};
149180
let lock_wait = lock_wait_start.elapsed();
181+
tracing::info!(
182+
"project lock acquired on {} after {} ms",
183+
project_dir_desc,
184+
lock_wait.as_millis()
185+
);
150186

151187
// Bridge: sync log lines → async NDJSON chunks
152188
let bridge_tx = async_tx.clone();

0 commit comments

Comments
 (0)