Record why a chaos docker command failed

Compose commands run with their output captured and with check set, so a failure raised a CalledProcessError and nothing ever looked at what the daemon had said. That exception reports the argv and the exit status and nothing else, so every scenario that died bringing its containers up left a runner log saying only that docker compose returned non-zero exit status 1, and the reason was captured and then discarded. In the run that prompted this work twelve scenarios failed that way and why they failed can no longer be established at all. Log the captured stderr and stdout before the error goes anywhere, keeping the tail of each so a verbose failure cannot fill the log file. A command that times out raises before its exit status is ever read, so that path records whatever it had emitted too, rather than leaving the same hole one shape over. Reproduced against both of the shapes this is meant to catch: an unusable network prefix now records the daemon's parse error, and a name already held by another container now records the conflict and names the container holding it. The success path logs nothing new, and a completed scenario's runner log is unchanged line for line.

The raising behaviour is deliberately untouched, since the abort flag and the exit code that came with it depend on it. The check is applied here rather than by subprocess so that a caller who passed check false gets the same record: both such callers are the compose down in teardown, which today can leave a mesh behind without saying so.

The same omission was costing the veth path its reasons. Failing ip commands had their stderr logged at debug, which the runner does not emit unless asked for verbose output, so a failed pair creation reached the log as nothing more than the names of the two interfaces it could not create. Raise that to a warning. The deletes issued to clear a stale pair are expected to fail and still say nothing.

testing/chaos/sim/docker_exec.py

@@ -7,6 +7,34 @@ import logging
 
 log = logging.getLogger(__name__)
 
+# `docker compose` renders its progress UI on stderr, so a failed command can
+# have hundreds of lines of captured output behind it. Log the tail: whatever
+# the daemon refused is the last thing it wrote.
+OUTPUT_TAIL_CHARS = 2000
+
+
+def _tail(text: str) -> str:
+    """Trim captured output to its last few KB for logging."""
+    text = text.strip()
+    if not text:
+        return "(empty)"
+    if len(text) <= OUTPUT_TAIL_CHARS:
+        return text
+    return "...\n" + text[-OUTPUT_TAIL_CHARS:]
+
+
+def _decode(output) -> str:
+    """Render captured output as text.
+
+    A timed-out command hands back what it had written as bytes, even when
+    the call asked for text, so the timeout path cannot assume either.
+    """
+    if output is None:
+        return ""
+    if isinstance(output, bytes):
+        return output.decode(errors="replace")
+    return output
+
 
 class DockerExecError(Exception):
     def __init__(self, container, cmd, returncode, stderr):
@@ -47,16 +75,50 @@ def docker_compose(
     timeout: int = 300,
     check: bool = True,
 ) -> subprocess.CompletedProcess:
-    """Run a docker compose command with the given compose file."""
+    """Run a docker compose command with the given compose file.
+
+    Output is captured, so a failure's stderr is logged here before anything
+    else sees it. `CalledProcessError` reports only the argv and the exit
+    status, and a `check=False` caller reads neither, so without this the one
+    place the daemon says what it objected to -- a container name already in
+    use, an unusable subnet, a missing image -- is captured and then thrown
+    away. Nothing about the success path changes.
+    """
     cmd = ["docker", "compose", "-f", compose_file] + args
     log.info("Running: %s", " ".join(cmd))
-    return subprocess.run(
-        cmd,
-        capture_output=True,
-        text=True,
-        timeout=timeout,
-        check=check,
-    )
+    try:
+        result = subprocess.run(
+            cmd,
+            capture_output=True,
+            text=True,
+            timeout=timeout,
+        )
+    except subprocess.TimeoutExpired as e:
+        # A timeout raises from inside communicate(), so the return-code
+        # branch below never runs and this is the only chance to say what
+        # the command had managed to emit. The partials arrive as bytes
+        # even under text=True.
+        log.error(
+            "%s timed out after %ds\nstderr: %s\nstdout: %s",
+            " ".join(cmd),
+            timeout,
+            _tail(_decode(e.stderr)),
+            _tail(_decode(e.stdout)),
+        )
+        raise
+    if result.returncode != 0:
+        log.error(
+            "%s exited %d\nstderr: %s\nstdout: %s",
+            " ".join(cmd),
+            result.returncode,
+            _tail(result.stderr),
+            _tail(result.stdout),
+        )
+        if check:
+            raise subprocess.CalledProcessError(
+                result.returncode, cmd, result.stdout, result.stderr
+            )
+    return result
 
 
 def is_container_running(container: str) -> bool:

testing/chaos/sim/veth.py

@@ -252,7 +252,11 @@ def _run_host(cmd: list[str], image: str, check: bool = True) -> bool:
             timeout=30,
         )
         if check and result.returncode != 0:
-            log.debug(
+            # Warning, not debug: the runner logs at INFO unless asked for
+            # -v, so at debug this never reached runner.log and the callers
+            # below report only that a pair could not be created. The
+            # check=False deletes are expected to fail and stay silent.
+            log.warning(
                 "ip cmd failed: %s -> %s",
                 " ".join(cmd),
                 result.stderr.strip(),