feat: test-sleep recipe streams logs; add --timestamps to docker logs

logging was a black box: the test recipe emitted one line then
'tail -f /dev/null' blocked silently, so there was nothing to verify.

- test-sleep now runs an infinite heartbeat: timestamp + hostname +
  monotonic counter, every 2s. Each line is timestamped so users can
  see the cadence when they run 'logs' or 'logs --follow'.
- 'docker logs' now uses --timestamps (added in Docker 19.03) so
  messages are tagged with their UTC timestamp regardless of recipe.
- Extracted logs_tail_cmd and logs_follow_cmd as pub(crate) helpers so
  the command format can be unit tested directly.
- Three new tests pin the docker logs command shape: --timestamps is
  present, --tail=100 in tail mode, -f in follow mode, --filter
  uses both sm121.recipe and sm121.rank labels.

recipes/test-sleep/recipe.toml

@@ -1,10 +1,19 @@
 engine = "vllm"
-name = "Test Idle Container"
+name = "Test Heartbeat Container"
 docker_image = "alpine:latest"
 model = "noop"
 port = 8000
 
-entrypoint = ["sh", "-c", "'echo \"[$(hostname)] test-idle ready\" && tail -f /dev/null'"]
+# Heartbeat loop: prints a timestamped line every 2s with UTC time and
+# the container hostname so you can tell logs from different nodes apart.
+#
+# Use it to verify the logging pipeline:
+#   cargo run serve --recipe test-sleep     # spins up the cluster
+#   cargo run logs --recipe test-sleep      # last 100 lines per node
+#   cargo run logs --recipe test-sleep --follow   # live stream from head
+#
+# Each line looks like:  10:42:13 [n0] heartbeat 42
+entrypoint = ["sh", "-c", "i=0; while true; do echo \"$(date -u +%H:%M:%S) [$(hostname)] heartbeat $i\"; i=$((i+1)); sleep 2; done"]
 
 args = []
 

src/docker/mod.rs

@@ -59,6 +59,24 @@ pub async fn serve(
     Ok(())
 }
 
+/// Builds the `docker logs` shell command used to fetch the last `tail`
+/// lines of the container for `recipe_name` on a specific `rank`.
+pub(crate) fn logs_tail_cmd(recipe_name: &str, rank: u32, tail: usize) -> String {
+    format!(
+        "docker ps -q --filter \"label=sm121.recipe={}\" --filter \"label=sm121.rank={}\" | xargs -r docker logs --timestamps --tail={} 2>&1",
+        recipe_name, rank, tail
+    )
+}
+
+/// Builds the `docker logs -f` shell command used to follow the head
+/// container of `recipe_name` in real time.
+pub(crate) fn logs_follow_cmd(recipe_name: &str) -> String {
+    format!(
+        "docker ps -q --filter \"label=sm121.recipe={}\" --filter \"label=sm121.rank=0\" | xargs -r docker logs -f --timestamps",
+        recipe_name
+    )
+}
+
 /// Shows Docker logs for a recipe across all nodes (or follows head node).
 pub async fn show_logs(
     config: &Config,
@@ -70,13 +88,9 @@ pub async fn show_logs(
     if follow {
         let head_node = cluster.nodes.first().context("No nodes in cluster")?;
         info!("📜 Following logs for '{}' (head node)...", head_node.name);
-        let cmd = format!(
-            "docker ps -q --filter \"label=sm121.recipe={}\" --filter \"label=sm121.rank=0\" | xargs -r docker logs -f",
-            recipe_name
-        );
+        let cmd = logs_follow_cmd(recipe_name);
         run_ssh_follow(config, head_node, cmd, dry_run).await?;
     } else {
-        let flag = "--tail=100";
         info!(
             "📜 Логи кластера '{}' ({} узлов):",
             cluster.name,
@@ -84,10 +98,7 @@ pub async fn show_logs(
         );
         let mut handles = Vec::new();
         for node in &cluster.nodes {
-            let cmd = format!(
-                "docker ps -q --filter \"label=sm121.recipe={}\" --filter \"label=sm121.rank={}\" | xargs -r docker logs {} 2>&1",
-                recipe_name, node.rank, flag
-            );
+            let cmd = logs_tail_cmd(recipe_name, node.rank, 100);
             let config = config.clone();
             let node = node.clone();
             let dry = dry_run;

src/docker/tests.rs

@@ -309,3 +309,37 @@ fn custom_init_port() {
     assert!(cmd.contains("--master-port 29500"));
     assert!(cmd.contains("--master-addr 1"));
 }
+
+// ── Logs command format ───────────────────────────────────────
+
+#[test]
+fn logs_tail_cmd_format() {
+    let cmd = super::logs_tail_cmd("test-sleep", 0, 100);
+    assert!(cmd.contains("docker ps -q"));
+    assert!(cmd.contains("--filter \"label=sm121.recipe=test-sleep\""));
+    assert!(cmd.contains("--filter \"label=sm121.rank=0\""));
+    assert!(cmd.contains("xargs -r docker logs"));
+    assert!(cmd.contains("--timestamps"));
+    assert!(cmd.contains("--tail=100"));
+    assert!(cmd.ends_with(" 2>&1"));
+}
+
+#[test]
+fn logs_tail_cmd_per_rank() {
+    let cmd0 = super::logs_tail_cmd("glm51", 0, 100);
+    let cmd2 = super::logs_tail_cmd("glm51", 2, 100);
+    assert!(cmd0.contains("label=sm121.rank=0"));
+    assert!(cmd2.contains("label=sm121.rank=2"));
+    assert!(!cmd0.contains("label=sm121.rank=2"));
+}
+
+#[test]
+fn logs_follow_cmd_format() {
+    let cmd = super::logs_follow_cmd("test-sleep");
+    assert!(cmd.contains("xargs -r docker logs -f"));
+    assert!(cmd.contains("--timestamps"));
+    // Follow targets the head node only (rank=0).
+    assert!(cmd.contains("--filter \"label=sm121.rank=0\""));
+    // Follow should not include --tail (we want a live stream from now).
+    assert!(!cmd.contains("--tail"));
+}