Skip to content

feat: stream model output to the debug log as it arrives - #587

Draft
knutdrand wants to merge 3 commits into
masterfrom
feat/stream-model-output
Draft

knutdrand wants to merge 3 commits into
masterfrom
feat/stream-model-output

Conversation

@knutdrand

Copy link
Copy Markdown
Contributor

What

run_command captured a model's stdout and stderr with communicate(), which blocks until the process exits, and ExternalModel.train() / .predict() discard the returned string on success. A model that ran for minutes was silent the whole time, and anything it logged was visible only if it failed.

This reads the pipe line by line and logs each line at debug level with a [model] prefix, so a long backtest reports progress as it goes.

Why it needs both halves

Streaming on this side is necessary but not sufficient: Python block-buffers stdout when it is not a terminal, so a model's log lines would still arrive in 4-8KB lumps, or all at once at exit. PYTHONUNBUFFERED is now set in the subprocess environment too. Either change alone leaves the output effectively unstreamed.

Behaviour preserved

  • The full output is still returned.
  • It is still embedded in the CommandLineException raised on a non-zero exit, so failures read exactly as before.
  • stderr is merged into stdout so the two streams keep the order the model produced them. They were concatenated into a single string here anyway, so nothing is lost; what improves is that interleaved output is no longer reordered into "all stdout, then all stderr".

Scope

Every runner that shells out goes through Runner._execute and so through this function, which covers uv, conda and renv. The docker path captures its logs separately (container.wait() then container.logs()) and is unchanged; it would need the equivalent stream=True treatment as a follow-up.

Debug level rather than info is deliberate: a 12-split backtest at n_iter 500 produces a lot of per-epoch output, which would bury chap's own logging if it were on by default. --run-config.debug opts in.

Tests

  • test_run_command_streams_output_to_debug_log asserts the lines are logged individually and in the order produced, across both streams.
  • test_run_command_unbuffers_subprocess_python asserts PYTHONUNBUFFERED actually reaches the subprocess.

make lint, make check and make test all pass (1462 passed, 122 skipped, 4 xfailed, 1 xpassed).

knutdrand and others added 3 commits September 10, 2026 22:22
run_command captured a model's stdout and stderr with communicate(), which
blocks until the process exits, and callers discard the returned string on
success. A model that ran for minutes was therefore silent throughout, and
anything it logged was visible only when it failed.

Read the pipe line by line instead and log each line at debug level, so a long
backtest reports progress as it goes. The output is still returned in full and
still embedded in the exception raised on a non-zero exit.

stderr is merged into stdout so the two streams keep the order the model
produced them; they were concatenated into a single string here anyway.

Set PYTHONUNBUFFERED in the subprocess environment as well: Python block-buffers
stdout when it is not a terminal, which would hold the output back until exit
and defeat the streaming.

Every runner that shells out goes through Runner._execute, so uv, conda and renv
all pick this up. The docker path captures its logs separately and is unchanged.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants