diff --git a/testing/chaos/sim/docker_exec.py b/testing/chaos/sim/docker_exec.py index 2d8781b..fcd328c 100644 --- a/testing/chaos/sim/docker_exec.py +++ b/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: diff --git a/testing/chaos/sim/veth.py b/testing/chaos/sim/veth.py index 13b7bd5..a60a25f 100644 --- a/testing/chaos/sim/veth.py +++ b/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(),