add debug logging for healthcheck and setup flows in coglet (#2828)

* add debug logging for healthcheck and setup flows in coglet

Add tracing::debug! calls throughout the healthcheck and setup code
paths to improve observability when debugging with RUST_LOG=debug or
COG_LOG_LEVEL=debug.

Healthcheck: log the full request lifecycle from HTTP handler through
service layer, orchestrator handle, event loop dispatch/coalescing,
worker handler invocation, and result distribution.

Setup: log orchestrator config, setup duration, timeout behavior,
health state transitions, setup result status, and setup log drain
sizes across orchestrator, worker, and Python entry point.

* demote healthcheck hot-path logging from debug to trace

The healthcheck endpoint is polled every few seconds by K8s probes.
Keep the happy-path lines at trace to avoid flooding debug logs, while
leaving the unhealthy/error/timeout paths and all setup lines at debug
where they are useful for diagnosing real issues.

Author: markphelps

crates/coglet-python/src/lib.rs

@@ -345,6 +345,10 @@ fn serve_subprocess(
     );
 
     let setup_timeout = read_setup_timeout();
+    debug!(
+        setup_timeout_secs = setup_timeout.map(|d| d.as_secs()),
+        is_train, "Orchestrator configuration"
+    );
     let orch_config = coglet_core::orchestrator::OrchestratorConfig::new(pred_ref)
         .with_num_slots(max_concurrency)
         .with_train(is_train)
@@ -369,27 +373,42 @@ fn serve_subprocess(
             let setup_service = Arc::clone(&service_clone);
             tokio::spawn(async move {
                 info!("Spawning worker subprocess");
+                let spawn_start = std::time::Instant::now();
                 match coglet_core::orchestrator::spawn_worker(orch_config, &mut setup_log_rx).await
                 {
                     Ok(ready) => {
-                        debug!("Worker ready, configuring service");
+                        let spawn_elapsed = spawn_start.elapsed();
+                        debug!(
+                            elapsed_ms = spawn_elapsed.as_millis() as u64,
+                            "Worker ready, configuring service"
+                        );
 
                         let num_slots = ready.handle.slot_ids().len();
+                        debug!(num_slots, "Setting up orchestrator on service");
 
                         setup_service
                             .set_orchestrator(ready.pool, Arc::new(ready.handle))
                             .await;
+                        debug!("Transitioning health to Ready");
                         setup_service.set_health(Health::Ready).await;
 
                         if let Some(s) = ready.schema {
+                            debug!("Setting OpenAPI schema on service");
                             setup_service.set_schema(s).await;
+                        } else {
+                            debug!("No OpenAPI schema provided by worker");
                         }
 
                         let mode = if is_train { "train" } else { "predict" };
                         info!(num_slots, mode, "Server ready");
 
                         // Drain final logs (includes "Server ready" above)
                         let final_logs = coglet_core::drain_accumulated_logs(&mut setup_log_rx);
+                        debug!(
+                            initial_logs_len = ready.setup_logs.len(),
+                            final_logs_len = final_logs.len(),
+                            "Drained setup logs"
+                        );
                         drop(setup_log_rx);
 
                         // Combine initial + final logs
@@ -401,7 +420,13 @@ fn serve_subprocess(
                         info!("Setup complete, now accepting requests");
                     }
                     Err(e) => {
-                        error!(error = %e, "Worker initialization failed");
+                        let spawn_elapsed = spawn_start.elapsed();
+                        error!(
+                            error = %e,
+                            elapsed_ms = spawn_elapsed.as_millis() as u64,
+                            "Worker initialization failed"
+                        );
+                        debug!("Transitioning health to SetupFailed");
                         setup_service.set_health(Health::SetupFailed).await;
                         setup_service
                             .set_setup_result(setup_result.failed(e.to_string()))

crates/coglet/src/orchestrator.rs

@@ -389,6 +389,7 @@ impl Orchestrator for OrchestratorHandle {
     }
 
     async fn healthcheck(&self) -> Result<HealthcheckResult, OrchestratorError> {
+        tracing::trace!("Healthcheck requested via orchestrator handle");
         let (response_tx, response_rx) = tokio::sync::oneshot::channel();
 
         // Send our channel to the event loop. If a healthcheck is already
@@ -403,11 +404,20 @@ impl Orchestrator for OrchestratorHandle {
         // If we time out, the healthcheck keeps running — our sender just gets a
         // silent failure when the event loop eventually broadcasts.
         match tokio::time::timeout(Duration::from_secs(10), response_rx).await {
-            Ok(Ok(result)) => Ok(result),
-            Ok(Err(_)) => Err(OrchestratorError::Protocol(
-                "healthcheck response channel dropped".to_string(),
-            )),
-            Err(_) => Ok(HealthcheckResult::unhealthy("healthcheck timed out")),
+            Ok(Ok(result)) => {
+                tracing::trace!(healthy = result.is_healthy(), "Healthcheck completed");
+                Ok(result)
+            }
+            Ok(Err(_)) => {
+                tracing::debug!("Healthcheck response channel dropped");
+                Err(OrchestratorError::Protocol(
+                    "healthcheck response channel dropped".to_string(),
+                ))
+            }
+            Err(_) => {
+                tracing::debug!("Healthcheck timed out after 10s");
+                Ok(HealthcheckResult::unhealthy("healthcheck timed out"))
+            }
         }
     }
 
@@ -564,15 +574,37 @@ pub async fn spawn_worker(
     };
 
     let (slot_ids, schema) = match config.setup_timeout {
-        Some(timeout) => match tokio::time::timeout(timeout, setup_fut).await {
-            Ok(Ok((slots, schema))) => (slots, schema),
-            Ok(Err(e)) => return Err(e),
-            Err(_) => return Err(OrchestratorError::SetupTimeout),
-        },
-        None => setup_fut.await?,
+        Some(timeout) => {
+            tracing::debug!(
+                timeout_secs = timeout.as_secs(),
+                "Waiting for setup with timeout"
+            );
+            match tokio::time::timeout(timeout, setup_fut).await {
+                Ok(Ok((slots, schema))) => {
+                    tracing::debug!(num_slots = slots.len(), "Setup completed within timeout");
+                    (slots, schema)
+                }
+                Ok(Err(e)) => {
+                    tracing::debug!(error = %e, "Setup failed");
+                    return Err(e);
+                }
+                Err(_) => {
+                    tracing::debug!(timeout_secs = timeout.as_secs(), "Setup timed out");
+                    return Err(OrchestratorError::SetupTimeout);
+                }
+            }
+        }
+        None => {
+            tracing::debug!("Waiting for setup with no timeout");
+            setup_fut.await?
+        }
     };
 
     let setup_logs = crate::setup_log_accumulator::drain_accumulated_logs(setup_log_rx);
+    tracing::debug!(
+        setup_logs_len = setup_logs.len(),
+        "Drained accumulated setup logs"
+    );
 
     tracing::debug!(num_slots = slot_ids.len(), "Worker ready");
 
@@ -786,6 +818,12 @@ async fn run_event_loop(
                         );
                     }
                     Some(Ok(ControlResponse::HealthcheckResult { id: _, status, error })) => {
+                        tracing::trace!(
+                            ?status,
+                            ?error,
+                            pending_count = pending_healthchecks.len(),
+                            "Received healthcheck result from worker"
+                        );
                         if pending_healthchecks.is_empty() {
                             tracing::warn!("Received healthcheck result but no pending requests");
                         } else {
@@ -795,6 +833,10 @@ async fn run_event_loop(
                                     HealthcheckResult::unhealthy(error.unwrap_or_else(|| "unhealthy".to_string()))
                                 }
                             };
+                            tracing::trace!(
+                                pending_count = pending_healthchecks.len(),
+                                "Distributing healthcheck result to pending callers"
+                            );
                             for tx in pending_healthchecks.drain(..) {
                                 let _ = tx.send(result.clone());
                             }
@@ -834,6 +876,7 @@ async fn run_event_loop(
                 if !in_flight {
                     healthcheck_counter += 1;
                     let hc_id = format!("hc_{}", healthcheck_counter);
+                    tracing::trace!(%hc_id, "Sending healthcheck request to worker");
 
                     let mut writer = ctrl_writer.lock().await;
                     if let Err(e) = writer.send(ControlRequest::Healthcheck { id: hc_id }).await {
@@ -843,6 +886,11 @@ async fn run_event_loop(
                             let _ = tx.send(result.clone());
                         }
                     }
+                } else {
+                    tracing::trace!(
+                        pending_count = pending_healthchecks.len(),
+                        "Healthcheck already in-flight, coalescing request"
+                    );
                 }
             }
 

crates/coglet/src/service.rs

@@ -258,6 +258,14 @@ impl PredictionService {
             None => (0, 0),
         };
 
+        tracing::trace!(
+            ?state,
+            available_slots,
+            total_slots,
+            setup_status = ?setup_result.as_ref().map(|r| r.status),
+            "Building health snapshot"
+        );
+
         HealthSnapshot {
             state,
             available_slots,
@@ -275,10 +283,19 @@ impl PredictionService {
             tracing::warn!("Attempted to set READY without orchestrator, ignoring");
             return;
         }
+        let previous = *self.health.read().await;
+        tracing::debug!(from = ?previous, to = ?health, "Health state transition");
         *self.health.write().await = health;
     }
 
     pub async fn set_setup_result(&self, result: SetupResult) {
+        tracing::debug!(
+            status = ?result.status,
+            started_at = %result.started_at,
+            completed_at = ?result.completed_at,
+            logs_len = result.logs.len(),
+            "Setting setup result"
+        );
         *self.setup_result.write().await = Some(result);
     }
 
@@ -349,9 +366,16 @@ impl PredictionService {
         &self,
     ) -> Result<HealthcheckResult, crate::orchestrator::OrchestratorError> {
         if let Some(ref state) = *self.orchestrator.read().await {
-            state.orchestrator.healthcheck().await
+            tracing::trace!("Dispatching healthcheck to orchestrator");
+            let result = state.orchestrator.healthcheck().await;
+            tracing::trace!(
+                healthy = result.as_ref().map(|r| r.is_healthy()).unwrap_or(false),
+                error = ?result.as_ref().ok().and_then(|r| r.error.as_ref()),
+                "Healthcheck result from orchestrator"
+            );
+            result
         } else {
-            // No orchestrator = not ready, return healthy (healthcheck not applicable)
+            tracing::debug!("No orchestrator configured, returning default healthy");
             Ok(HealthcheckResult::healthy())
         }
     }

crates/coglet/src/transport/http/routes.rs

@@ -99,27 +99,45 @@ fn generate_prediction_id() -> String {
 }
 
 async fn health_check(State(service): State<Arc<PredictionService>>) -> Json<HealthCheckResponse> {
+    tracing::trace!("Health check endpoint called");
     let snapshot = service.health().await;
+    tracing::trace!(
+        state = ?snapshot.state,
+        available_slots = snapshot.available_slots,
+        total_slots = snapshot.total_slots,
+        has_setup_result = snapshot.setup_result.is_some(),
+        "Health snapshot retrieved"
+    );
 
     // Run user healthcheck if ready (even when busy — healthcheck health
     // and slot availability are orthogonal concerns).
     let user_healthcheck_error = if snapshot.is_ready() {
         write_readiness_file();
 
         // Run user-defined healthcheck
+        tracing::trace!("Running user-defined healthcheck");
         match service.healthcheck().await {
-            Ok(result) if result.is_healthy() => None,
-            Ok(result) => result.error,
-            Err(e) => Some(format!("Healthcheck error: {}", e)),
+            Ok(result) if result.is_healthy() => {
+                tracing::trace!("User healthcheck passed");
+                None
+            }
+            Ok(result) => {
+                tracing::debug!(error = ?result.error, "User healthcheck reported unhealthy");
+                result.error
+            }
+            Err(e) => {
+                tracing::debug!(error = %e, "User healthcheck returned error");
+                Some(format!("Healthcheck error: {}", e))
+            }
         }
     } else {
+        tracing::trace!(state = ?snapshot.state, "Skipping user healthcheck (not ready)");
         None
     };
 
-    Json(HealthCheckResponse::from_snapshot(
-        snapshot,
-        user_healthcheck_error,
-    ))
+    let response = HealthCheckResponse::from_snapshot(snapshot, user_healthcheck_error);
+    tracing::trace!(status = ?response.status, "Health check response");
+    Json(response)
 }
 
 /// Write /var/run/cog/ready for K8s readiness probe.

crates/coglet/src/worker.rs

@@ -544,21 +544,31 @@ pub async fn run_worker<H: PredictHandler>(
 
     // Run setup
     tracing::info!("Worker starting setup");
+    let setup_start = std::time::Instant::now();
     let setup_result = handler.setup().await;
-    tracing::trace!("Setup handler returned");
+    let setup_elapsed = setup_start.elapsed();
+    tracing::debug!(
+        elapsed_ms = setup_elapsed.as_millis() as u64,
+        success = setup_result.is_ok(),
+        "Setup handler returned"
+    );
 
     // Unregister Python's setup sender, but keep log_forwarder running
     // The fd_redirect capture threads will continue sending subprocess logs
     if let Some(cleanup) = setup_cleanup {
-        tracing::trace!("Running cleanup (unregistering Python setup sender)");
+        tracing::debug!("Running cleanup (unregistering Python setup sender)");
         cleanup();
     }
     // Note: We DON'T drop setup_log_tx or wait for log_forwarder
     // The log_forwarder continues running to forward subprocess output throughout worker lifetime
 
     // Handle setup failure
     if let Err(e) = setup_result {
-        tracing::error!(error = %e, "Setup failed");
+        tracing::error!(
+            error = %e,
+            elapsed_ms = setup_elapsed.as_millis() as u64,
+            "Setup failed"
+        );
         let slot = slot_ids.first().copied().unwrap_or_else(SlotId::new);
         let mut w = ctrl_writer.lock().await;
         let _ = w
@@ -662,8 +672,14 @@ pub async fn run_worker<H: PredictHandler>(
                         break;
                     }
                     Some(Ok(ControlRequest::Healthcheck { id })) => {
-                        tracing::debug!(%id, "Healthcheck requested");
+                        tracing::trace!(%id, "Healthcheck requested, invoking handler");
                         let result = handler.healthcheck().await;
+                        tracing::trace!(
+                            %id,
+                            status = ?result.status,
+                            error = ?result.error,
+                            "Healthcheck handler returned"
+                        );
                         let mut w = ctrl_writer.lock().await;
                         let _ = w.send(ControlResponse::HealthcheckResult {
                             id,