[SLOP(claude-sonnet-4-5)] chore(logs): improve actor stop and envoy ping diagnostics

Author: NathanFlurry

CLAUDE.md

@@ -78,6 +78,10 @@ docker-compose up -d
 - We use Graphite for stacked PRs. Diff against the parent branch (`gt ls` to see the stack), not `main`.
 - To revert a file to the version before this branch's changes, checkout from the first child branch (below in the stack), not from `main` or the parent. Child branches contain the pre-this-branch state of files modified by branches further down the stack.
 
+### jj
+
+- Always invoke `jj diff` with `--git --color=never`. The jj-default format compresses unchanged context with `...` ellipses and uses a `<old> <new>:` line-number prefix that visually fuses with adjacent tokens, causing misreads (e.g. `tracing::debug!` → `tracing::info!` looked like a `debug!` → `debuginfo!` rename). The unified `diff --git` format has unambiguous `-`/`+` markers at column 0 and standard `@@` hunk headers.
+
 **Never push to `main` unless explicitly specified by the user.**
 
 ## Frontend Routing (TanStack Router)

engine/packages/pegboard-envoy/src/lib.rs

@@ -215,7 +215,14 @@ impl CustomServeTrait for PegboardEnvoyWs {
 				// flight kv requests from being completed immediately. This guarantees the invariant that an
 				// actor's KV is only being accessed from one place at a time.
 				if res.is_err() {
-					tracing::warn!(?res, "ping task failed, aborting ws_to_tunnel");
+					let now = util::timestamp::now();
+					let last_ping_ts = conn.last_ping_ts.load(std::sync::atomic::Ordering::SeqCst);
+					tracing::warn!(
+						?res,
+						envoy_key = %conn.envoy_key,
+						time_since_last_pong_ms = now - last_ping_ts,
+						"ping task failed, aborting ws_to_tunnel"
+					);
 					hard_abort_ws_to_tunnel.abort();
 				}
 

engine/packages/pegboard-envoy/src/ping_task.rs

@@ -32,19 +32,35 @@ pub async fn task(
 		// Check if the last ping is past the timeout threshold
 		let last_ping_ts = conn.last_ping_ts.load(Ordering::SeqCst);
 		let now = util::timestamp::now();
-		if now - last_ping_ts > ping_timeout_ms {
+		let gap_ms = now - last_ping_ts;
+		if gap_ms > ping_timeout_ms {
+			tracing::warn!(
+				envoy_key = %conn.envoy_key,
+				last_ping_ts,
+				now,
+				gap_ms,
+				threshold_ms = ping_timeout_ms,
+				"envoy ping timed out, closing connection"
+			);
 			return Err(WsError::TimedOut.build());
 		}
 
 		// Update ping
+		let last_rtt = conn.last_rtt.load(Ordering::Relaxed);
 		ctx.op(pegboard::ops::envoy::update_ping::Input {
 			namespace_id: conn.namespace_id,
 			envoy_key: conn.envoy_key.clone(),
 			update_lb: !conn.is_serverless,
-			rtt: conn.last_rtt.load(Ordering::Relaxed),
+			rtt: last_rtt,
 		})
 		.await?;
 
+		tracing::debug!(
+			gap_since_last_pong_ms = gap_ms,
+			last_rtt_ms = last_rtt,
+			"sending ping"
+		);
+
 		// Send ping to envoy
 		let ping_msg = versioned::ToEnvoy::wrap_latest(protocol::ToEnvoy::ToEnvoyPing(
 			protocol::ToEnvoyPing {

engine/packages/pegboard-envoy/src/ws_to_tunnel_task.rs

@@ -177,6 +177,17 @@ async fn handle_message(
 				metrics::PONG_MISSED_TOTAL
 					.with_label_values(&[ns_label.as_str(), pool_label])
 					.inc();
+				tracing::warn!(
+					rtt_ms = rtt,
+					slow_threshold_ms,
+					"slow pong"
+				);
+			}
+
+			// Independent high-rtt warning at a hard 500ms threshold so operators
+			// see latency spikes even when slow_threshold_ms is configured higher.
+			if rtt > 500 && u64::from(rtt) <= slow_threshold_ms {
+				tracing::warn!(rtt_ms = rtt, "high rtt pong");
 			}
 
 			conn.last_rtt.store(rtt, Ordering::SeqCst);

engine/sdks/rust/envoy-client/src/actor.rs

@@ -427,6 +427,12 @@ async fn begin_stop(
 	};
 
 	let reason_label = stop_actor_reason_label(&reason);
+	tracing::info!(
+		?reason,
+		?stop_code,
+		error = ?ctx.error,
+		"actor stopping"
+	);
 	crate::metrics::METRICS
 		.actor_stop_total
 		.with_label_values(&[reason_label])

engine/sdks/rust/envoy-client/src/connection/native.rs

@@ -204,7 +204,17 @@ async fn single_connection(
 			}
 			Err(e) => {
 				disconnect_reason = "error";
-				tracing::error!(?e, "websocket error");
+				let last_ping_ts = shared.last_ping_ts.load(std::sync::atomic::Ordering::Acquire);
+				let time_since_last_ping_ms = if last_ping_ts == 0 {
+					None
+				} else {
+					Some(crate::time::now_millis() - last_ping_ts)
+				};
+				tracing::error!(
+					?e,
+					?time_since_last_ping_ms,
+					"websocket error"
+				);
 				break;
 			}
 			_ => {}

engine/sdks/rust/envoy-client/src/envoy.rs

@@ -519,7 +519,29 @@ async fn envoy_loop(
 				fail_remote_sqlite_requests_with_shutdown(&mut ctx);
 
 				if !ctx.actors.is_empty() {
-					tracing::warn!("stopping all actors due to envoy lost threshold");
+					let threshold_source = if ctx.shared.protocol_metadata.try_lock()
+						.ok()
+						.and_then(|g| g.as_ref().map(|_| ()))
+						.is_some()
+					{
+						"metadata"
+					} else {
+						"fallback"
+					};
+					let time_since_close_ms = lost_timer_armed_at
+						.map(|t| t.elapsed().as_millis() as u64)
+						.unwrap_or(0);
+					let actor_count: u64 = ctx
+						.actors
+						.values()
+						.map(|gens| gens.len() as u64)
+						.sum();
+					tracing::warn!(
+						actor_count,
+						time_since_close_ms,
+						threshold_source,
+						"stopping all actors due to envoy lost threshold"
+					);
 					let mut evicted = 0u64;
 					for (_actor_id, gens) in &ctx.actors {
 						for (_g, entry) in gens {
@@ -681,7 +703,19 @@ fn handle_conn_close(ctx: &EnvoyContext, lost_timeout: Option<SleepFuture>) -> O
 			.unwrap_or(10_000)
 	};
 
-	tracing::debug!(ms = lost_threshold, "starting envoy lost timeout");
+	let source = if ctx
+		.shared
+		.protocol_metadata
+		.try_lock()
+		.ok()
+		.and_then(|guard| guard.as_ref().map(|m| m.envoy_lost_threshold))
+		.is_some()
+	{
+		"metadata"
+	} else {
+		"fallback"
+	};
+	tracing::info!(ms = lost_threshold, source, "starting envoy lost timeout");
 
 	Some(boxed_sleep(std::time::Duration::from_millis(
 		lost_threshold,