From 36caa97367944592d36f4fb3a42f61ccacdb4037 Mon Sep 17 00:00:00 2001 From: ualtinok <94532+ualtinok@users.noreply.github.com> Date: Mon, 26 Oct 2026 23:14:56 +0100 Subject: [PATCH 1/5] mason: tag slow-bind warnings with the bind's session; drop last-session log fallback (#1008) The slow-bind warning ran on the frame loop outside any session scope and log_ctx fell back to LAST_SESSION, the last session that thread served, so operators were sent to an unrelated session. PendingBind now records the requesting session and the warning logs inside that session's scope. The LAST_SESSION fallback (87814581dc) existed only to avoid untagged watcher/gitignore lines on the assumption of one session per project. On threads that serve many sessions (request loop, frame loop, executor workers) it mislabels every unscoped line, and nothing depends on it: the CLI log readers already handle untagged lines. It is removed, so unscoped lines carry no session tag. Tests that asserted the fallback (session_prefix_format, set_session_direct, the falls-back/updates/none-does-not-clear tests and the integration slog_macros_prepend_session_tag case 2) are rewritten to the new contract on purpose: an unscoped line carries no session. Co-authored-by: alfonso-aft <289616620+alfonso-aft@users.noreply.github.com> (cherry picked from commit 040014761aeb857a7181bbd3d09f3b3c726081ed) --- .../release-notes/next/log-session-prefix.md | 1 + crates/aft/src/log_ctx.rs | 151 +++++++----------- crates/aft/src/subc/health.rs | 23 +-- crates/aft/src/subc/mod.rs | 76 +++++++++ crates/aft/tests/integration/log_ctx_test.rs | 11 +- 5 files changed, 156 insertions(+), 106 deletions(-) create mode 100644 .alfonso/release-notes/next/log-session-prefix.md diff --git a/.alfonso/release-notes/next/log-session-prefix.md b/.alfonso/release-notes/next/log-session-prefix.md new file mode 100644 index 0000000000..4c4d0b8e4b --- /dev/null +++ b/.alfonso/release-notes/next/log-session-prefix.md @@ -0,0 +1 @@ +- Log lines no longer carry the wrong session's id: slow-bind warnings name the bind's own session, and project-wide lines carry no session tag (#1008, thanks @iceteaSA). diff --git a/crates/aft/src/log_ctx.rs b/crates/aft/src/log_ctx.rs index fdc33ea8c1..5fa68d81f9 100644 --- a/crates/aft/src/log_ctx.rs +++ b/crates/aft/src/log_ctx.rs @@ -9,23 +9,20 @@ //! Background threads spawned during request handling (search-index pre-warm, //! semantic-index build) **must** capture the session id before spawning and //! re-install it on the new thread via [`set_session`] or [`with_session`]. +//! +//! A line logged outside any session scope carries no session tag. Threads +//! such as the request loop, the subc frame loop and executor workers serve +//! many sessions in turn, so "the last session this thread served" says +//! nothing about who owns a later between-request line; tagging with it sent +//! operators to the wrong session. Code that logs about a specific session +//! from such a thread (a pending bind, a background task) must enter that +//! session's scope with [`with_session`] first. use std::cell::RefCell; thread_local! { /// Current session id for log tagging. `None` means "no session context". static CURRENT_SESSION: RefCell> = const { RefCell::new(None) }; - - /// Most-recent non-None session id observed on this thread. Used as a - /// fallback for between-request log sites that have no inherent session - /// (filesystem watcher invalidation, gitignore rebuilds triggered by - /// the OS, etc.) so their lines still carry a session tag. - /// - /// This is best-effort: in a multi-session setup the tag may attribute - /// project-wide events to whichever session was active most recently. - /// That's acceptable because the vast majority of AFT users have one - /// active session per project and the alternative is an untagged line. - static LAST_SESSION: RefCell> = const { RefCell::new(None) }; } /// Set the current thread-local session id. @@ -33,11 +30,6 @@ thread_local! { /// Call this at the start of a background thread that captured the session id /// from the parent request loop. pub fn set_session(session: Option) { - if let Some(sid) = session.as_deref() { - LAST_SESSION.with(|s| { - *s.borrow_mut() = Some(sid.to_string()); - }); - } CURRENT_SESSION.with(|s| { *s.borrow_mut() = session; }); @@ -47,10 +39,6 @@ struct SessionGuard(Option); impl Drop for SessionGuard { fn drop(&mut self) { - // Restore CURRENT_SESSION directly (don't go through set_session, - // which would also overwrite LAST_SESSION — the guard's job is to - // restore the previous CURRENT_SESSION value, not to alter the - // last-session fallback). CURRENT_SESSION.with(|s| { *s.borrow_mut() = self.0.take(); }); @@ -75,21 +63,12 @@ pub fn current_session() -> Option { } /// Return the current session id prefix string, e.g. `"[ses_abcd1234] "`, -/// or an empty string if no session id has ever been observed on this thread. -/// -/// Resolution order: -/// 1. Current request's session (set via `with_session`). -/// 2. Most-recent session observed on this thread (fallback for -/// between-request log sites like watcher invalidation that have no -/// inherent session context). +/// or an empty string when no session scope is active on this thread. /// /// The stored session id may already carry the `ses_` prefix (OpenCode's /// real session IDs do); detect that and avoid double-prefixing. pub fn session_prefix() -> String { - let sid_opt = CURRENT_SESSION - .with(|s| s.borrow().clone()) - .or_else(|| LAST_SESSION.with(|s| s.borrow().clone())); - match sid_opt.as_deref() { + match current_session().as_deref() { Some(sid) if sid.starts_with("ses_") => format!("[{}] ", sid), Some(sid) => format!("[ses_{}] ", sid), None => String::new(), @@ -108,22 +87,18 @@ fn write_session_message( message: std::fmt::Arguments<'_>, ) -> std::fmt::Result { CURRENT_SESSION.with(|current| { - LAST_SESSION.with(|last| { - let current = current.borrow(); - let last = last.borrow(); - if let Some(sid) = current.as_deref().or(last.as_deref()) { - writer.write_str(if sid.starts_with("ses_") { - "[" - } else { - "[ses_" - })?; - writer.write_str(sid)?; - writer.write_str("] ")?; - } - Ok(()) - }) + if let Some(sid) = current.borrow().as_deref() { + writer.write_str(if sid.starts_with("ses_") { + "[" + } else { + "[ses_" + })?; + writer.write_str(sid)?; + writer.write_str("] ")?; + } + Ok(()) })?; - // Release the session borrows before user-provided Display implementations + // Release the session borrow before user-provided Display implementations // run; formatting a message may itself change the logging context. writer.write_fmt(message) } @@ -277,17 +252,14 @@ mod tests { } } - /// Reset both thread-locals so each test starts from a clean slate. - /// Rust runs tests on a thread pool — without this helper a previous - /// test in the same thread could leak its LAST_SESSION value into - /// the next one. + /// Reset the thread-local so each test starts from a clean slate. + /// Rust runs tests on a thread pool, and a test that panics inside + /// `set_session` (rather than `with_session`) could otherwise leak its + /// session into the next test on the same thread. fn reset_session_state() { CURRENT_SESSION.with(|s| { *s.borrow_mut() = None; }); - LAST_SESSION.with(|s| { - *s.borrow_mut() = None; - }); } #[test] @@ -328,12 +300,7 @@ mod tests { assert_eq!(session_prefix(), "[ses_abcd1234] "); }); - // After exiting with_session, CURRENT is None but LAST_SESSION - // still carries "abcd1234" — the prefix falls back to it. - assert_eq!(session_prefix(), "[ses_abcd1234] "); - - // Truly empty starting state: no prefix. - reset_session_state(); + // Once the scope has ended there is no session context, so no prefix. assert_eq!(session_prefix(), ""); } @@ -354,46 +321,48 @@ mod tests { CURRENT_SESSION.with(|s| { assert_eq!(s.borrow().as_deref(), Some("direct")); }); + assert_eq!(session_prefix(), "[ses_direct] "); set_session(None); CURRENT_SESSION.with(|s| { assert!(s.borrow().is_none()); }); - // LAST_SESSION still remembers it for the fallback. - LAST_SESSION.with(|s| { - assert_eq!(s.borrow().as_deref(), Some("direct")); - }); + assert_eq!(session_prefix(), ""); } - /// Regression: between-request log sites (filesystem watcher - /// invalidation, gitignore rebuilds) run outside a `with_session` - /// scope but should still carry a session tag derived from the most - /// recent active session on this thread. Without the LAST_SESSION - /// fallback these lines appeared untagged in the plugin log. + /// A line logged after a session scope ends, on a thread that served that + /// session, carries no session tag. Threads like the request loop and the + /// subc frame loop serve many sessions in turn, so tagging an unscoped + /// line with the previous session (as an earlier fallback did) attributed + /// project-wide or other-session events to whichever session ran last. #[test] - fn session_prefix_falls_back_to_last_session_after_with_session_exits() { + fn unscoped_line_after_scope_ends_carries_no_session() { reset_session_state(); - // Simulate a request handled on this thread. with_session(Some("ses_first".to_string()), || { - assert_eq!(session_prefix(), "[ses_first] "); + assert_eq!( + format_session_message(format_args!("inside")), + "[ses_first] inside" + ); }); - // CURRENT_SESSION is now None, but a between-request log site - // should still get a tag from LAST_SESSION. assert!(current_session().is_none()); - assert_eq!(session_prefix(), "[ses_first] "); + assert_eq!( + format_session_message(format_args!("invalidated 1 files")), + "invalidated 1 files" + ); } + /// A thread that served session A and then logs about session B inside + /// B's scope tags the line with B only. #[test] - fn last_session_updates_with_each_with_session_call() { + fn scoped_line_carries_its_own_session_not_the_previous_one() { reset_session_state(); - with_session(Some("ses_first".to_string()), || {}); - assert_eq!(session_prefix(), "[ses_first] "); - - with_session(Some("ses_second".to_string()), || {}); - // Newer session wins as the fallback. - assert_eq!(session_prefix(), "[ses_second] "); + with_session(Some("ses_A".to_string()), || {}); + let line = with_session(Some("ses_B".to_string()), || { + format_session_message(format_args!("pending bind")) + }); + assert_eq!(line, "[ses_B] pending bind"); } #[test] @@ -410,17 +379,19 @@ mod tests { ); } + /// `with_session(None, ...)` (synthetic or system requests with no + /// session id) runs its closure with no session tag, even nested inside + /// a real session's scope, and restores that scope afterwards. #[test] - fn with_session_none_does_not_clear_last_session() { + fn with_session_none_runs_untagged_and_restores_outer_scope() { reset_session_state(); - with_session(Some("ses_real".to_string()), || {}); - assert_eq!(session_prefix(), "[ses_real] "); - - // A subsequent `with_session(None, ...)` call (which can happen - // for synthetic / system requests with no session_id) must not - // erase the fallback tag from earlier real traffic. - with_session(None, || {}); - assert_eq!(session_prefix(), "[ses_real] "); + with_session(Some("ses_real".to_string()), || { + with_session(None, || { + assert_eq!(session_prefix(), ""); + }); + assert_eq!(session_prefix(), "[ses_real] "); + }); + assert_eq!(session_prefix(), ""); } } diff --git a/crates/aft/src/subc/health.rs b/crates/aft/src/subc/health.rs index 3f49ba4b69..23a1e3362a 100644 --- a/crates/aft/src/subc/health.rs +++ b/crates/aft/src/subc/health.rs @@ -1641,16 +1641,19 @@ pub(super) fn warn_slow_pending_binds( in_flight_writer: None, reader_admissions_while_promoted_writer_waited: 0, }); - crate::slog_warn!( - "{}", - pending_bind_breadcrumb( - *route, - &pending.bind_root_id, - age, - &pending.configure_request_id, - &snapshot, - ) - ); + let breadcrumb = pending_bind_breadcrumb( + *route, + &pending.bind_root_id, + age, + &pending.configure_request_id, + &snapshot, + ); + // The frame loop serves every session, so tag the line with the + // session that requested this bind rather than whatever scope (if + // any) the thread happens to be in. + crate::log_ctx::with_session(pending.session.clone(), || { + crate::slog_warn!("{breadcrumb}"); + }); } } diff --git a/crates/aft/src/subc/mod.rs b/crates/aft/src/subc/mod.rs index b709cee33f..1659f9681c 100644 --- a/crates/aft/src/subc/mod.rs +++ b/crates/aft/src/subc/mod.rs @@ -1473,6 +1473,10 @@ struct PendingBind { /// removed, running configures return at their next checkpoint) instead of /// only marking bookkeeping. cancellation: crate::executor::JobCancellation, + /// Session that requested this bind. Periodic warnings about the bind run + /// on the frame loop, which serves every session, so they log inside this + /// session's scope to carry the right session tag. + session: Option, } struct RouteBindCompletion { @@ -8246,6 +8250,7 @@ async fn handle_control_request( scopes.bind(&route_identity); } let configure_session = route_identity.session.clone(); + let bind_session = configure_session.clone(); let root_was_live = live_roots.contains_key(&bind_root_id); metrics.mark_frame_loop_wait( "executor.scheduler/register_actor", @@ -8334,6 +8339,7 @@ async fn handle_control_request( ver: frame.header.ver, flags: frame.header.flags, cancellation: configure_cancellation, + session: Some(bind_session), }, ); @@ -19437,6 +19443,7 @@ mod tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation: crate::executor::JobCancellation::new(), + session: None, }, )]); let mut installed_route_epochs = HashMap::from([(route.channel, route.epoch)]); @@ -19570,6 +19577,7 @@ mod tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation: crate::executor::JobCancellation::new(), + session: None, }, )]); let mut installed_route_epochs = HashMap::from([(route.channel, route.epoch)]); @@ -19625,6 +19633,7 @@ mod tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation: crate::executor::JobCancellation::new(), + session: None, }; let young = route_key(9, 1); let held = route_key(10, 1); @@ -19667,6 +19676,70 @@ mod tests { assert!(!pending_binds[&young].deadline_reported); } + /// The frame loop serves every session. After it has served session A, + /// the slow-bind warning for a bind that session B requested must carry + /// B's tag, and one for a bind with no session must carry no tag; neither + /// may carry A's. + #[test] + fn slow_pending_bind_warning_carries_the_bind_session_not_the_last_served() { + let (_dir, root) = test_root("route-bind-slow-warn-session"); + let pending_bind = |corr: u64, session: Option<&str>| PendingBind { + bind_root_id: root.clone(), + inserted_new_actor: false, + cancelled: false, + configure_request_id: format!("subc-bind-{corr}"), + started_at: Instant::now() + .checked_sub(DISPATCH_PATH_BIND_WARN_AFTER + Duration::from_secs(1)) + .expect("monotonic clock is older than the bind age"), + warned_half_deadline: false, + deadline_reported: false, + corr, + ver: PROTOCOL_VERSION, + flags: control_flags(), + cancellation: crate::executor::JobCancellation::new(), + session: session.map(str::to_string), + }; + let owned = route_key(352, 1); + let unowned = route_key(353, 1); + let mut pending_binds = HashMap::from([ + (owned, pending_bind(352, Some("ses_B"))), + (unowned, pending_bind(353, None)), + ]); + let executor = Executor::new(); + + let ((), lines) = crate::logging::capture_log_lines(|| { + log_ctx::with_session(Some("ses_A".to_string()), || { + crate::slog_info!("serving session A"); + }); + warn_slow_pending_binds(&mut pending_binds, &executor); + }); + + assert_eq!( + lines.first().map(String::as_str), + Some("INFO [ses_A] serving session A") + ); + let owned_line = lines + .iter() + .find(|line| line.contains("route 352@1")) + .unwrap_or_else(|| panic!("no warning for route 352: {lines:?}")); + let unowned_line = lines + .iter() + .find(|line| line.contains("route 353@1")) + .unwrap_or_else(|| panic!("no warning for route 353: {lines:?}")); + assert!( + owned_line.starts_with("WARN [ses_B] subc attach: "), + "{owned_line}" + ); + assert!( + unowned_line.starts_with("WARN subc attach: "), + "{unowned_line}" + ); + assert!( + !lines[1..].iter().any(|line| line.contains("ses_A")), + "{lines:?}" + ); + } + /// A bind whose deadline passes while it waits behind a reader on its root /// is refused with its own retryable code, and the message names the /// reader's job, its tool and how long it has run, so whoever retries the @@ -19728,6 +19801,7 @@ mod tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation: bind_token, + session: None, }, )]); let mut installed_route_epochs = HashMap::from([(route.channel, route.epoch)]); @@ -19922,6 +19996,7 @@ mod tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation, + session: None, }, )]); let mut installed = HashMap::from([(route.channel, route.epoch)]); @@ -20166,6 +20241,7 @@ mod tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation, + session: None, }, )]); let mut installed = HashMap::from([(route.channel, route.epoch)]); diff --git a/crates/aft/tests/integration/log_ctx_test.rs b/crates/aft/tests/integration/log_ctx_test.rs index aec5c0aa11..b2a5ffc2ee 100644 --- a/crates/aft/tests/integration/log_ctx_test.rs +++ b/crates/aft/tests/integration/log_ctx_test.rs @@ -87,13 +87,12 @@ fn slog_macros_prepend_session_tag() { ); }); - // Case 2: Without explicit session id — verify LAST_SESSION fallback. - // session_prefix() falls back to the most recently set session id so that - // between-request log lines (filesystem watcher invalidation, gitignore - // matcher rebuilds) still carry a session tag. This thread had Case 1 - // set "abcd1234", so the fallback should return that. + // Case 2: Without a session scope there is no tag, even though this + // thread served "abcd1234" in Case 1: an unscoped line is not + // attributed to whichever session the thread served last. aft::log_ctx::with_session(None, || { let prefix = aft::log_ctx::session_prefix(); - assert_eq!(prefix, "[ses_abcd1234] "); + assert_eq!(prefix, ""); }); + assert_eq!(aft::log_ctx::session_prefix(), ""); } From 6f98506039e2bd7578675bb58ef5556852bfe614 Mon Sep 17 00:00:00 2001 From: ualtinok <94532+ualtinok@users.noreply.github.com> Date: Mon, 26 Oct 2026 23:39:31 +0100 Subject: [PATCH 2/5] mason: tag per-session subc frame-loop warnings with their own session (#1008) The stuck-pending-watch scan, the scope-workdir comparison and three bash handoff/deadline warnings run on shared subc runtime or blocking-pool threads outside any session scope but each concerns one known session. Log each inside that session's scope so it carries the right tag instead of none. Co-authored-by: alfonso-aft <289616620+alfonso-aft@users.noreply.github.com> (cherry picked from commit 446bfd98451dececbf84805f1268cc4f340843cb) --- crates/aft/src/subc/bash.rs | 29 ++++++++++++++++--------- crates/aft/src/subc/health.rs | 20 +++++++++++------- crates/aft/src/subc/mod.rs | 40 +++++++++++++++++++---------------- 3 files changed, 53 insertions(+), 36 deletions(-) diff --git a/crates/aft/src/subc/bash.rs b/crates/aft/src/subc/bash.rs index 9b26ddfa70..e3f257a835 100644 --- a/crates/aft/src/subc/bash.rs +++ b/crates/aft/src/subc/bash.rs @@ -785,12 +785,15 @@ fn detach_held_bash_sync(target: drain::BashDetachTarget, cancelled: bool) { // process alive until the daemon's scope.describe response confirms the run ended; the // command's normal hard timeout still applies while confirmation waits. } else if let Err(error) = target.registry.promote(&target.task_id, &target.session_id) { - crate::slog_warn!( - "subc attach: bash background handoff failed task_id={:?} session={:?} error={:?}", - target.task_id, - target.session_id, - error - ); + // Runs on a shared blocking-pool thread; tag with the task's session. + crate::log_ctx::with_session(Some(target.session_id.clone()), || { + crate::slog_warn!( + "subc attach: bash background handoff failed task_id={:?} session={:?} error={:?}", + target.task_id, + target.session_id, + error + ); + }); } else if cancelled { // The caller saw only the cancellation; name the still-running task // on the session's next bash call. @@ -2383,7 +2386,10 @@ pub(super) fn submit_deferred_bash( let reply = await_runon_launch_reply(spawn_ctx.bash_background().clone(), &session_id, &response, capture_deadline, &cancel, &claim, server_completion, Some(capture_reply_deadline), background_runon).await.unwrap_or(response); foreground_runon_reply(reply, foreground_runon_deadline, background_runon, &cancel, foreground_runon_timeout, startup_window, worker_session, format_context.bash_watch_available.unwrap_or(worker_session)) }; - crate::slog_warn!("bash startup reply deadline channel={} corr={corr} elapsed_ms={} admitted={} code={} steps={}", route.channel, received_at.elapsed().as_millis(), admitted.load(Ordering::Relaxed), response.data.get("code").and_then(Value::as_str).unwrap_or("promoted"), startup_steps.format_steps()); + // This task runs on the shared subc runtime outside any session scope. + crate::log_ctx::with_session(Some(session_id.to_string()), || { + crate::slog_warn!("bash startup reply deadline channel={} corr={corr} elapsed_ms={} admitted={} code={} steps={}", route.channel, received_at.elapsed().as_millis(), admitted.load(Ordering::Relaxed), response.data.get("code").and_then(Value::as_str).unwrap_or("promoted"), startup_steps.format_steps()); + }); let result = (!cancel.connection.is_cancelled() && !cancel.route.is_cancelled() && claim.try_claim_for_wait_task()).then(|| bash_result_from_response(response, &format_context)); send_bash_deferred_completion(&completion_tx, &task_metrics, route, corr, flags, ver, root_for_task.clone(), request_id.clone(), result, false).await; answered_startup = true; @@ -3592,9 +3598,12 @@ async fn send_ready_bash_result( .get("message") .and_then(Value::as_str) .unwrap_or(&result.text); - crate::slog_warn!( - "subc attach: late bash result discarded after handoff task_id={task_id:?} session={session_id:?} error={error:?}" - ); + // Runs on the shared subc runtime; tag with the task's session. + crate::log_ctx::with_session(Some(session_id.to_string()), || { + crate::slog_warn!( + "subc attach: late bash result discarded after handoff task_id={task_id:?} session={session_id:?} error={error:?}" + ); + }); } else if claim.claimed_by_module_loop() { send_bash_deferred_completion( completion_tx, diff --git a/crates/aft/src/subc/health.rs b/crates/aft/src/subc/health.rs index 23a1e3362a..9523921937 100644 --- a/crates/aft/src/subc/health.rs +++ b/crates/aft/src/subc/health.rs @@ -1173,14 +1173,18 @@ impl DispatchPathMetrics { continue; } logged.insert(key, now); - crate::slog_warn!( - "subc bg wake: pending watch remains unacked root={} session={} task={} watch={} age_ms={}", - root.as_path().display(), - session, - task_id, - watch_id, - age_ms - ); + // One scan covers every session's watches, so log each inside + // its own session's scope to tag it with that session. + crate::log_ctx::with_session(Some(session.clone()), || { + crate::slog_warn!( + "subc bg wake: pending watch remains unacked root={} session={} task={} watch={} age_ms={}", + root.as_path().display(), + session, + task_id, + watch_id, + age_ms + ); + }); } } logged.retain(|_, last| { diff --git a/crates/aft/src/subc/mod.rs b/crates/aft/src/subc/mod.rs index 1659f9681c..be5d44bd76 100644 --- a/crates/aft/src/subc/mod.rs +++ b/crates/aft/src/subc/mod.rs @@ -7789,24 +7789,28 @@ fn log_scope_workdir_comparison( stamp: &subc_protocol::scope::ScopeStamp, result: io::Result>, ) { - match result { - Ok(Some((project_root, workdir))) => crate::slog_info!( - "subc scope workdir differs: project_root={} workdir={} session={} project_id={}", - project_root.display(), - workdir.display(), - identity.session, - stamp.project_id.as_deref().unwrap_or("none"), - ), - Ok(None) => {} - Err(error) => crate::slog_info!( - "subc scope workdir comparison skipped: project_root={} workdir={} session={} project_id={} reason={}", - identity.project_root.display(), - stamp.workdir.as_deref().unwrap_or("none"), - identity.session, - stamp.project_id.as_deref().unwrap_or("none"), - error, - ), - } + // Runs on the shared frame-loop runtime, so tag the line with the bind's + // own session explicitly. + crate::log_ctx::with_session(Some(identity.session.to_string()), || { + match result { + Ok(Some((project_root, workdir))) => crate::slog_info!( + "subc scope workdir differs: project_root={} workdir={} session={} project_id={}", + project_root.display(), + workdir.display(), + identity.session, + stamp.project_id.as_deref().unwrap_or("none"), + ), + Ok(None) => {} + Err(error) => crate::slog_info!( + "subc scope workdir comparison skipped: project_root={} workdir={} session={} project_id={} reason={}", + identity.project_root.display(), + stamp.workdir.as_deref().unwrap_or("none"), + identity.session, + stamp.project_id.as_deref().unwrap_or("none"), + error, + ), + } + }); } /// Channel-0 control requests: RouteBind plus the cached health probe. From 8750bb2bfb8b1b049790824ecf6e8ab4a6959e28 Mon Sep 17 00:00:00 2001 From: ualtinok <94532+ualtinok@users.noreply.github.com> Date: Mon, 26 Oct 2026 23:56:45 +0100 Subject: [PATCH 3/5] mason: keep the scope-workdir comparison line untagged (#1008) scope_workdir_mismatch_logs_once_and_preserves_project_root pins this line as untagged and its body already names the session. With the last-session fallback removed it can no longer carry a wrong session, so the wrap from the previous commit is reverted rather than changing that test. Co-authored-by: alfonso-aft <289616620+alfonso-aft@users.noreply.github.com> (cherry picked from commit 0258b9505df5cdb6f2838376c7f7da0702f27892) --- crates/aft/src/subc/mod.rs | 40 +++++++++++++++++--------------------- 1 file changed, 18 insertions(+), 22 deletions(-) diff --git a/crates/aft/src/subc/mod.rs b/crates/aft/src/subc/mod.rs index be5d44bd76..1659f9681c 100644 --- a/crates/aft/src/subc/mod.rs +++ b/crates/aft/src/subc/mod.rs @@ -7789,28 +7789,24 @@ fn log_scope_workdir_comparison( stamp: &subc_protocol::scope::ScopeStamp, result: io::Result>, ) { - // Runs on the shared frame-loop runtime, so tag the line with the bind's - // own session explicitly. - crate::log_ctx::with_session(Some(identity.session.to_string()), || { - match result { - Ok(Some((project_root, workdir))) => crate::slog_info!( - "subc scope workdir differs: project_root={} workdir={} session={} project_id={}", - project_root.display(), - workdir.display(), - identity.session, - stamp.project_id.as_deref().unwrap_or("none"), - ), - Ok(None) => {} - Err(error) => crate::slog_info!( - "subc scope workdir comparison skipped: project_root={} workdir={} session={} project_id={} reason={}", - identity.project_root.display(), - stamp.workdir.as_deref().unwrap_or("none"), - identity.session, - stamp.project_id.as_deref().unwrap_or("none"), - error, - ), - } - }); + match result { + Ok(Some((project_root, workdir))) => crate::slog_info!( + "subc scope workdir differs: project_root={} workdir={} session={} project_id={}", + project_root.display(), + workdir.display(), + identity.session, + stamp.project_id.as_deref().unwrap_or("none"), + ), + Ok(None) => {} + Err(error) => crate::slog_info!( + "subc scope workdir comparison skipped: project_root={} workdir={} session={} project_id={} reason={}", + identity.project_root.display(), + stamp.workdir.as_deref().unwrap_or("none"), + identity.session, + stamp.project_id.as_deref().unwrap_or("none"), + error, + ), + } } /// Channel-0 control requests: RouteBind plus the cached health probe. From f85b04e290f7f9fcfee7cede9b822d9af3143436 Mon Sep 17 00:00:00 2001 From: ualtinok <94532+ualtinok@users.noreply.github.com> Date: Tue, 27 Oct 2026 00:04:44 +0100 Subject: [PATCH 4/5] search-quality descriptor for log-session-prefix; reword the release note Co-authored-by: alfonso-aft <289616620+alfonso-aft@users.noreply.github.com> --- .alfonso/release-notes/next/log-session-prefix.md | 2 +- .../slice-descriptors/land-log-session-prefix.json | 8 ++++++++ 2 files changed, 9 insertions(+), 1 deletion(-) create mode 100644 benchmarks/aft-search/slice-descriptors/land-log-session-prefix.json diff --git a/.alfonso/release-notes/next/log-session-prefix.md b/.alfonso/release-notes/next/log-session-prefix.md index 4c4d0b8e4b..b090c2d7fe 100644 --- a/.alfonso/release-notes/next/log-session-prefix.md +++ b/.alfonso/release-notes/next/log-session-prefix.md @@ -1 +1 @@ -- Log lines no longer carry the wrong session's id: slow-bind warnings name the bind's own session, and project-wide lines carry no session tag (#1008, thanks @iceteaSA). +Log lines no longer carry the wrong session id: slow-bind warnings name the bind's own session, and lines not tied to a session carry no session tag (#1008, thanks @iceteaSA). diff --git a/benchmarks/aft-search/slice-descriptors/land-log-session-prefix.json b/benchmarks/aft-search/slice-descriptors/land-log-session-prefix.json new file mode 100644 index 0000000000..ebd574711e --- /dev/null +++ b/benchmarks/aft-search/slice-descriptors/land-log-session-prefix.json @@ -0,0 +1,8 @@ +{ + "targeted_mechanism": "none", + "kind": "harness", + "slice_class": "non_ranking", + "fixtures": [ + "harness-goldens" + ] +} From 46b12ad48b5b454388c727c6cbe25e6364e5afd2 Mon Sep 17 00:00:00 2001 From: ualtinok <94532+ualtinok@users.noreply.github.com> Date: Tue, 27 Oct 2026 09:07:51 +0100 Subject: [PATCH 5/5] Fill the bind session on PendingBind records added on main since this branch Co-authored-by: alfonso-aft <289616620+alfonso-aft@users.noreply.github.com> --- crates/aft/src/subc/a0_egress.rs | 3 +++ crates/aft/src/subc/mod.rs | 1 + crates/aft/src/subc/prepared_bind_tests.rs | 1 + 3 files changed, 5 insertions(+) diff --git a/crates/aft/src/subc/a0_egress.rs b/crates/aft/src/subc/a0_egress.rs index e070d0bcd0..009e4c0028 100644 --- a/crates/aft/src/subc/a0_egress.rs +++ b/crates/aft/src/subc/a0_egress.rs @@ -854,6 +854,7 @@ mod fixup_tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation: JobCancellation::new(), + session: None, }, ); ControlCompletion::AckWritten(RouteBindCompletion { @@ -979,6 +980,7 @@ mod fixup_tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation: JobCancellation::new(), + session: None, }, )]); expire_overdue_route_binds( @@ -1206,6 +1208,7 @@ mod ordering_tests { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation: JobCancellation::new(), + session: None, }, )]); let mut routes = HashMap::new(); diff --git a/crates/aft/src/subc/mod.rs b/crates/aft/src/subc/mod.rs index 1659f9681c..a1d326a297 100644 --- a/crates/aft/src/subc/mod.rs +++ b/crates/aft/src/subc/mod.rs @@ -19684,6 +19684,7 @@ mod tests { fn slow_pending_bind_warning_carries_the_bind_session_not_the_last_served() { let (_dir, root) = test_root("route-bind-slow-warn-session"); let pending_bind = |corr: u64, session: Option<&str>| PendingBind { + ack_publication: None, bind_root_id: root.clone(), inserted_new_actor: false, cancelled: false, diff --git a/crates/aft/src/subc/prepared_bind_tests.rs b/crates/aft/src/subc/prepared_bind_tests.rs index 97b390f9ad..e3b29fa0f5 100644 --- a/crates/aft/src/subc/prepared_bind_tests.rs +++ b/crates/aft/src/subc/prepared_bind_tests.rs @@ -36,6 +36,7 @@ async fn bind_publication_rejects_missing_or_mismatched_applied_snapshot() { ver: PROTOCOL_VERSION, flags: control_flags(), cancellation: JobCancellation::new(), + session: None, }, )]); let mut routes = HashMap::new();