Store workflow output - #14062
Conversation
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #14062 +/- ##
==========================================
+ Coverage 91.85% 91.94% +0.09%
==========================================
Files 484 482 -2
Lines 33581 33721 +140
==========================================
+ Hits 30847 31006 +159
+ Misses 2734 2715 -19
Flags with carried forward coverage won't be shown. Click here to find out more.
|
There was a problem hiding this comment.
Pull request overview
This PR adds structured capture and persistence of workflow-job output (stdout/stderr) so that workflows hooked into experiment runs can be logged to <UPDATE_LOG_PATH>/<run_id>/workflows.log and appended to the experiment’s storage directory workflows.log. It introduces a dedicated status event for workflow output, and wires both CLI and GUI monitors to write these logs.
Changes:
- Capture stdout/stderr for internal and external workflow jobs (including failure cases) and surface per-invocation results.
- Introduce
RunModelWorkflowLogEventwith a stable log-entry format, write it to update-log output paths, and append it to experiment storage. - Add unit/UI tests and docs describing the new workflow logging behavior.
Reviewed changes
Copilot reviewed 17 out of 17 changed files in this pull request and generated 3 comments.
Show a summary per file
| File | Description |
|---|---|
src/ert/config/ert_script.py |
Adds thread-aware stdout/stderr capture proxy, plus ExternalScriptError handling to avoid ERT-internal stack traces for external job exit failures. |
src/ert/config/external_ert_script.py |
Writes subprocess stdout/stderr to current streams (so ErtScript capture can record it) and raises ExternalScriptError with an exit-code message. |
src/ert/workflow_runner.py |
Adds WorkflowJobResult and WorkflowRunner.jobResults() to preserve per-invocation output (including repeated job runs). |
src/ert/run_models/event.py |
Introduces RunModelWorkflowLogEvent with as_log_entry() and write_as_log() for update-log persistence. |
src/ert/run_models/run_model.py |
Emits workflow log events per job, buffers log entries until an experiment exists, and appends them to experiment storage. |
src/ert/storage/local_experiment.py |
Adds workflow_log_path and append_workflow_log() to persist workflow log entries alongside the experiment. |
src/ert/cli/monitor.py |
Writes workflow log events to <UPDATE_LOG_PATH>/<run_id>/workflows.log during CLI runs. |
src/ert/gui/experiments/run_dialog.py |
Writes workflow log events to the GUI output path. |
tests/ert/unit_tests/workflow_runner/test_workflow_runner.py |
Adds coverage for external-job stdout capture, exit-code error reporting, and per-invocation job results. |
tests/ert/unit_tests/workflow_runner/test_ert_script.py |
Adds coverage for stdout/stderr capture, failure behavior, and concurrent/threaded capture isolation. |
tests/ert/unit_tests/run_models/test_workflow_log_event.py |
New tests for RunModelWorkflowLogEvent log formatting and file append semantics. |
tests/ert/unit_tests/run_models/test_status_events_serialization.py |
Extends status-event serialization coverage to include RunModelWorkflowLogEvent. |
tests/ert/unit_tests/run_models/test_base_run_model.py |
Adds tests asserting workflow log event emission and storage persistence behavior across hooks/iterations. |
tests/ert/unit_tests/gui/experiments/test_run_dialog.py |
Adds GUI test to verify workflow log events are written to the output path. |
tests/ert/ui_tests/cli/test_cli.py |
Adds CLI UI test ensuring workflow output is written into the update log path. |
docs/ert/reference/workflows/complete_workflows.rst |
Documents that hooked workflow output is also written to update-log and experiment storage logs. |
docs/ert/reference/configuration/keywords.rst |
Documents the workflow log location/format under UPDATE_LOG_PATH, including storage-copy behavior and hook scope. |
Suppressed comments (1)
tests/ert/unit_tests/workflow_runner/test_ert_script.py:183
- Thread exceptions can be missed, and the join loop doesn’t assert that worker threads actually finished. Add an is_alive() assertion after each join so this test fails deterministically instead of leaking threads on failure paths.
for thread in threads:
thread.start()
for thread in threads:
thread.join(timeout=10)
69e54f9 to
53b84d8
Compare
Internal python workflow jobs never captured stdout, and only recorded stderr when they failed, so their output was lost. Tee the streams while the script runs so the output is both recorded and still shown in the terminal. External jobs now write the output of the subprocess to the current stdout and stderr instead of assigning it directly, so that both kinds of job are captured by the same mechanism. As a consequence a stack trace from a failing job is appended to, rather than replacing, whatever the job printed before it failed. This is a prerequisite for storing workflow output in a log file. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The workflow report is keyed by job name, so a workflow that runs the same job more than once only keeps the output of the last invocation. Add an ordered list of results alongside it, which is needed to report the output of all invocations. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Introduce a status event carrying the stdout and stderr of a single workflow job invocation, which appends it to a workflows.log file under the update log path. The event deliberately does not inherit RunModelEvent, since the PRE_EXPERIMENT hook runs before any ensemble exists and therefore has neither an iteration nor an ensemble id. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The stdout and stderr of workflows hooked into an experiment was only visible in the terminal, and lost as soon as it scrolled away. Send the output of every workflow job as a status event and append it to <UPDATE_LOG_PATH>/<run_id>/workflows.log, the same way update reports are written by the CLI monitor and the run dialog. The events are sent even when a job with STOP_ON_FAIL aborts the workflow, so that the output explaining the failure is kept. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> # Conflicts: # src/ert/run_models/run_model.py
When an external workflow job exits with a non-zero code, the stderr recorded for the job ended with a python stack trace through the ert internals that started the job. It says nothing about what went wrong in the job itself, and is now noise in the workflow log. Report only the executable and its exit code instead. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The workflow log was only written by the CLI monitor and the GUI run dialog, so it was lost whenever no consumer drained the status queue, and it was not kept together with the experiment it described. Write the same log entries from RunModel into the storage directory of the experiment. Entries from hooks that run before the experiment exists, such as PRE_EXPERIMENT, are buffered and flushed once an experiment is available. The status event is kept so the output can be streamed live to a frontend, and the update log copy is kept for backwards compatibility. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Workflow jobs run in a background thread, but the output was captured by replacing the process wide sys.stdout and sys.stderr. Output written by any other thread ended up in the log of whichever job happened to be running, and two jobs running at the same time captured each other. Route writes through a proxy that records them only for threads that are capturing, and that delegates the rest of the stream interface to the stream it replaced. Jobs asking for a file descriptor, an encoding or a binary buffer now see what they would have seen without capturing, where before they were met with an UnsupportedOperation. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Output from hooks that run before the experiment exists in storage was flushed from inside the loop over the workflows of the current hook. A configuration whose only hooked workflow is a PRE_EXPERIMENT one never entered that loop again, so its output was buffered and then dropped, contrary to what the documentation promises. Flush whenever run_workflows is given an experiment, whether or not the hook has any workflows of its own. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
LOAD_WORKFLOW takes an optional name to refer to the workflow by, but only the file it was read from was kept. The workflow log therefore named a workflow after its file, which is not what the user sees anywhere else. Keep the given name on the workflow, falling back to the file name when LOAD_WORKFLOW was used without one. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
A job runner reported that it was still running for the rest of its lifetime whenever the job it started raised, since the flag was only cleared on the path where the job returned. Rejected arguments left the runner in the same state. Clear the flag in a finally block covering the whole run. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The threads were joined with a timeout but the result was ignored, so a thread that never finished left the test asserting on half written output and reporting whatever it found. A stuck job is worse than a failed one here, since its capture block never exits and sys.stdout stays replaced for the rest of the session. Assert that each thread terminated, naming the consequence in the message. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Keep only what the signature does not already say, namely why the method can return without writing anything. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Drop a formatting test that only re-asserted what the two tests around it already covered, and add tests for three paths that were untested: that a new experiment run discards output left pending by the previous one, that appending to an experiment log accumulates and is refused by read-only storage, and that output still reaches storage when a workflow aborts on failure or the user cancels the run. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Workflow output was written both to the update log path by the CLI and GUI and to the experiment in storage by the run model, leaving two copies of the same content to keep in sync. The storage copy is the durable one: it lives with the data of the experiment it belongs to, no matter which frontend started the run. Drop the update log copy and the write_as_log helper behind it. The event itself stays, since it remains the only live channel to the frontend. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The workflow log was described under UPDATE_LOG_PATH, which no longer holds it. Move the description to the workflow reference, where the hooks that produce it are documented. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
11a454c to
74d8bfe
Compare
A cooperatively-cancelled internal job returns normally, so hasFailed() stays False and the job was indistinguishable from one that ran to completion. WorkflowJobResult and RunModelWorkflowLogEvent now carry a 'cancelled' flag alongside 'failed', and the persisted log entry status reflects it. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
03e0e55 to
598ec95
Compare
When several workflows are hooked to the same runtime (e.g. multiple HOOK_WORKFLOW ... POST_EXPERIMENT lines) and the experiment is cancelled while an earlier one is still running, run_workflows() raised UserCancelled immediately, breaking out of the loop before any later hooked workflow was even instantiated. Those workflows produced zero events and vanished from the workflow log/GUI instead of showing up as cancelled. Skip workflows that haven't started once cancellation is detected and emit a cancelled event for each of their jobs, then defer the UserCancelled raise until after the loop so all hooked workflows are still reported.
The bespoke workflows.log file only covered hooked workflows and duplicated information the logging system already handles well. Workflow job output (stdout/stderr, arguments, status) is now formatted into the message of a normal log record emitted through ert.workflow_runner, so it appears in ert-*.log regardless of whether the workflow was hooked to an experiment, run from the CLI, or run from the Tools menu. Job results are logged once, before stop_on_fail aborts the workflow, so the output of the job that stopped the workflow is no longer silently dropped. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Replace workflow_log_path/append_workflow_log with workflow_events_path/append_workflow_events, which appends one pre-serialized JSON line per event to workflow_events.jsonl. Storage stays free of any dependency on ert.run_models: it only ever receives strings to append. This file is not meant to be read by users directly (the ERT log now covers that); it exists so a later GUI can repopulate workflow output for older experiments. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
RunModel now serializes each RunModelWorkflowLogEvent with model_dump_json() and appends the resulting lines via append_workflow_events(), instead of writing pre-formatted log text. This only applies to workflows hooked to an experiment; CLI and Tools-menu workflows rely solely on the ERT logger. Document the new behaviour: workflow output goes to the ERT log for all three entry points, and workflow_events.jsonl is a GUI-backing file, not meant to be read directly. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Issue
Resolves #13320
Approach
Create new events for workflows, capture output to create events and write to log and storage seperately. Events follow the DataEvent pattern and will be consumed to frontend in a later PR.
Writes logs to Ert Logs for all workflowruns (hooked, CLI and through tools) and writes events to storage for hooked workflows.
Creates a CaptureProxy for thread-aware capture, write is recorded only if writing thread has an active capture flagged. Also needed for internal job print capture.
(Screenshot of new behavior in GUI if applicable)
git rebase -i main --exec 'just rapid-tests')When applicable
merge screenshot-PR in ert-testdata before merging this PR.