Skip to content

fix: keep failed CRISPR-Copies and Mutagenesis logs by failing the Job in post-job - #169

Open
matthewberry wants to merge 6 commits into
mjberry/fix/clean-pipefailfrom
mjberry/fix/crispr-mutagenesis-keep-logs
Open

matthewberry wants to merge 6 commits into
mjberry/fix/clean-pipefailfrom
mjberry/fix/crispr-mutagenesis-keep-logs

Conversation

@matthewberry

@matthewberry matthewberry commented Nov 5, 2026 •

Copy link
Copy Markdown
Collaborator

Stacked on #161 (itself stacked on #160). It relies on the postjob.py check #161 adds, which fails the Job when error exists. Merge #160 and #161 first.

Problem

When a CRISPR-Copies or Mutagenesis run fails, its log never reaches MinIO. Both commands end:

… 2>&1 | tee $JOB_OUTPUT_DIR/log) && ls …) || (touch $JOB_OUTPUT_DIR/error && false)

The && false makes the job container exit non-zero. In job.tpl.yaml, job is an init container and post-job (which uploads the output directory) is the pod's main container. Kubernetes starts main containers only after every init container succeeds, so post-job never runs, and log and error stay on the shared volume. The job is still marked error correctly; only the log is lost.

CLEAN had the same problem, and #161 fixed it.

Change

  • In both command builders, the fallback is now || touch $JOB_OUTPUT_DIR/error, without && false. A failed run writes error and exits 0; the template then touches finished, and post-job uploads error, finished and log.
  • postjob.py (from fix: a failed CLEAN run was reported as completed with no results #161) then exits 1 because error exists, so the Job fails and the watcher marks the job error, as before.
  • pipefail is unchanged in both.
  • After this, a word search for tee across app/ and chart/ finds only these two commands and CLEAN, all using the same pattern.

Testing

  • tests/test_clean_job_exit_code.py is renamed to tests/test_tool_job_exit_code.py and parametrized over CLEAN, CRISPR-Copies and Mutagenesis. For each tool it renders the real job template with that tool's real command, using the known-good payloads from tests/test_tool_registry.py, and runs the job container's script with a stand-in python:
    • Tool exits 1, or is killed with SIGKILL: the container exits 0, with error, finished and log in the output directory.
    • Tool succeeds: the container exits 0, with finished, log and the result file, and no error.
  • With && false restored in both builders, the four CRISPR-Copies and Mutagenesis failure cases fail.
  • Full suite in the Dockerfile.test image: 636 passed.
  • Not run against the real tool images or on the cluster.

Deploy note

Same as #161: post-job always runs moleculemaker/mmli-backend:main (hardcoded in job.tpl.yaml). A backend running these commands against a :main image without #161's postjob.py check would mark failed runs completed. Don't deploy this branch until :main has that check.

The backend's init container is hardcoded to :main too. So job_log.py and the scripts' new entry points take effect only once :main has them. Until then, a setup failure leaves only the fixed line in the log.

Added after review

  • Mutagenesis joins with && (539f2a7). Its command started set -o pipefail; . In the template's ls -al ${JOB_INPUT_DIR} && <command> && … chain, the ; let the tool run, without pipefail, after an earlier step failed. A new test, run for all three tools, checks that the tool doesn't run when there's no input directory.
  • CRISPR-Copies keeps the log when its setup step fails (cd66c36). fetch_organism.py and convert_annotations.py run as the crispr-copies prejob_command in the backend's init container. A failure there failed that container, so neither the tool nor post-job ran and nothing was uploaded.
    • New app/job_log.py: run_with_job_log() adds a file handler for $JOB_OUTPUT_DIR/log to the script's own logger only, and logs an uncaught exception with its traceback before exiting 1. Both scripts use it when run as scripts, not when imported.
    • prejob_command captures no output. On failure it appends a fixed line to log, touches error and exits 0. It's changed in chart/values.yaml, app/cfg/config.yaml and local.config.yaml.
    • The fallback covers only the two setup scripts (759cf29, from review). The value is wrapped in { …; } because the template splices it into … && ./prejob.py && … && <prejob_command>. Without the group, a failed MinIO input sync also hit the fallback and was logged as a setup-script failure.
    • The CRISPR-Copies command skips the tool when error exists, and appends to log (tee -a).
    • Then post-job uploads the log, and fix: a failed CLEAN run was reported as completed with no results #161's check fails the Job.
  • An earlier attempt leaked secrets: e1eacb7, reverted in 518fdfc. It tee'd the scripts' raw output into the log. Both scripts import config, which logs app_config with secret.yaml merged in, so every run's log carried the MinIO keys, the database password and the hCaptcha secret. It was never merged or deployed. That's why job_log.py attaches its handler to each script's own logger and nothing captures raw output.

Testing (setup step)

  • The real prejob_command and scripts, run with marker secrets:
    • a failed GFF3 conversion leaves its reason and the fixed line in the log, and no secrets;
    • a successful run writes no secrets.
  • The rendered init and job containers, run in order, with stand-in scripts that write their own message and also print output that must stay out of the log:
    • a failed fetch or convert keeps its message and skips the tool;
    • a successful or failed tool run keeps the setup messages too.
  • run_with_job_log: an uncaught exception is logged with its traceback, and another logger's message stays out.
  • A failed prejob.py: the init container fails, nothing writes error, and the log says nothing about the setup scripts. The harness stops after a failed init container, as the pod does. This test failed before 759cf29.
  • Each earlier version fails the tests:
    • e1eacb7's tee: 6 tests fail, including both secret checks;
    • the original command: 3 fail;
    • no handler in the converter: 1 fails;
    • the old tool command: 4 fail.
  • A test checks that the chart's prejob_command matches app/cfg/config.yaml.
  • Full suite: 648 passed.

Still not covered

  • A crash before a setup script sets up its logger, such as a failed import, leaves only the fixed line in the log. The traceback is in the pod log only.
  • A failure in prejob.py itself (the MinIO input sync) still fails the init container before anything writes log. So does anything that kills a whole container, like an OOM kill or the deadline.
  • What the scripts themselves log goes into the log. I reviewed their messages (the accession, NCBI URLs, file names, and exception text), not every exception a dependency could raise.

…b in post-job

Both commands ended `|| (touch error && false)`, so a failed run exited the `job`
container non-zero. That container is an init container, so post-job never ran and the
log and `error` never reached MinIO.

Apply the same change #161 made for CLEAN: write `error` and exit 0, so post-job
uploads the outputs and then fails the Job on `error`.

The CLEAN exit-code test now covers all three tools, using the known-good CRISPR-Copies
and Mutagenesis payloads from test_tool_registry.py, and is renamed to match.

@matthewberry matthewberry left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I found no blocking problems.

Checked

  • The diff: only the two command builders and their comments change, plus the test file, which is renamed and extended to cover all three tools. postjob.py is unchanged from #161.
  • A failed run is still marked error:
    • postjob.py exits 1 after the upload whenever error exists.
    • Jobs are created with backoffLimit: 0 (kubejob_service.py:892) and restartPolicy: Never, so a failing post-job ends the Job without a retry.
    • _derive_phase maps a failed Job to ERROR.
    • Nothing in app/ depends on which container failed. The only reader of container status is the image-digest lookup.
  • Failed runs now upload finished, log and error: I grepped app/ for code that reads the finished or error files. Only postjob.py does. Both result routes read only their own output CSV, so a failed run still returns 404 from them, as before. I didn't check the CRISPR-Copies or Mutagenesis frontends.
  • Tests:
    • test_tool_job_exit_code.py and test_postjob_exit_code.py pass in the Dockerfile.test image (13 passed).
    • With && false restored in both builders, exactly the four CRISPR-Copies and Mutagenesis failure cases fail. That matches the description.
  • The tee claim: a word search for tee across app/ and chart/, skipping comments, finds only these two commands and CLEAN.
  • #162: this PR doesn't touch clean_service.py, so I don't expect a conflict. I didn't test the merge.

Notes, not for this PR

  • Deploy order is the main risk: post-job always runs mmli-backend:main. If this branch is deployed before :main has #161's postjob.py check, failed runs will be marked completed. The description already says this.
  • #163: failed CRISPR-Copies and Mutagenesis runs will now put log, error and finished in the v1 artifact listing. #163 hides those by default.
  • Leaving these out is reasonable: the Mutagenesis ; join and failures in CRISPR-Copies' fetch_organism.py step both predate this PR.

Not verified: the real tool images, and a run on the cluster. That's the same gap the description states.

@matthewberry

Copy link
Copy Markdown
Collaborator Author

Closing the two gaps the review left open. Neither needs a change here.

  • Frontends: I fetched crispr-copies-frontend (eb80673) and mutagenesis-frontend (9ba1bbf) and searched each main for reads of finished, error or log, anything under /out/, MinIO, presigned URLs, and /artifacts. There are none. Every 'error' match is UI state (a file-upload status or an alert's severity), not a job output file. So uploading those files on a failed run changes nothing in either frontend.
  • Merge with fix: reject CLEAN submissions with no sequences #162: git merge-tree of this branch and fix: reject CLEAN submissions with no sequences #162's merges cleanly.

…ops it

The command started `set -o pipefail; `. The job template runs it inside
`ls -al ${JOB_INPUT_DIR} && <command> && ...`, so the `;` ended that chain: if listing
the input directory failed, the tool still ran, and without pipefail. CRISPR-Copies and
CLEAN already join with `&&`.

New test: for each tool, with no input directory the tool must not run. It fails for
Mutagenesis with the `;` restored.
@matthewberry

Copy link
Copy Markdown
Collaborator Author

Following up on the review's note about the Mutagenesis ; join: fixed in 539f2a7 rather than left out.

  • The command now starts set -o pipefail && , like CRISPR-Copies and CLEAN. In the template's ls -al ${JOB_INPUT_DIR} && <command> && … chain, the ; had let the tool run, without pipefail, after an earlier step failed.
  • New test_the_tool_does_not_run_when_an_earlier_step_fails, parametrized over all three tools: with no input directory, the chain must stop before the tool runs. It fails only for Mutagenesis with the ; restored.
  • test_tool_job_exit_code.py: 12 passed in the Dockerfile.test image.

fetch_organism.py and convert_annotations.py run as the crispr-copies prejob_command in
the backend's init container. A failure there failed that container, so the job
container and post-job never ran and the traceback reached no one.

- prejob_command now tees the setup scripts' output to `log` and touches `error` on
  failure, exiting 0 (in chart/values.yaml, app/cfg/config.yaml and
  local.config.yaml).
- The CRISPR-Copies command skips the tool when `error` already exists, and appends
  to `log` (tee -a) so the setup output is kept on every path.
- post-job then uploads `log` and `error`, and #161's check fails the Job.

Tests run the rendered init container and then the job container, sharing one output
directory: a failed fetch or convert keeps its traceback and skips the tool; a
successful or failed tool run keeps the setup output too. Reverting either the
prejob_command or the command fails four of them. A further test checks the chart's
prejob_command matches app/cfg/config.yaml.
@matthewberry

Copy link
Copy Markdown
Collaborator Author

Following up on the review's note about CRISPR-Copies' fetch_organism.py failures: fixed in e1eacb7 too.

  • Setup step: prejob_command (fetch_organism.py && convert_annotations.py, in the backend's init container) now tees its output to log and touches error on failure, then exits 0. It's changed in chart/values.yaml, app/cfg/config.yaml and local.config.yaml.
  • Tool command: it skips the tool when error already exists, and appends to log with tee -a, so the setup output isn't overwritten.
  • Result: post-job uploads the traceback, and fix: a failed CLEAN run was reported as completed with no results #161's check fails the Job.

Tests: these run the rendered init container, then the job container, against one output directory:

  • a failed fetch or convert keeps its traceback, and the tool doesn't run;
  • a successful or failed tool run also keeps the setup output.

Reverting either the prejob_command or the command makes four of them fail. Another test checks that the chart's prejob_command matches app/cfg/config.yaml. Full suite: 644 passed.

Still not covered: a failure in prejob.py itself (the MinIO input sync), or anything that kills a whole container. The PR description now lists both.

Reverts e1eacb7. The setup scripts (fetch_organism.py, convert_annotations.py) import
config, which logs the merged app_config, including secret.yaml's MinIO keys, database
password and hCaptcha secret, at import. The init container mounts secret.yaml, so
tee'ing the scripts' output into $JOB_OUTPUT_DIR/log put those secrets in the job log
on every CRISPR-Copies run, and post-job uploads that log to MinIO, where
/v1/jobs/{id}/artifacts/log serves it.

Reproduced in the Dockerfile.test image with marker secrets: all four reached
out/log on a successful run. The setup-step fix needs to write only the scripts' own
messages to the log.
@matthewberry

Copy link
Copy Markdown
Collaborator Author

Correction to my previous comment: the setup-step change in e1eacb7 leaked secrets, so I've reverted it in 518fdfc. The Mutagenesis join fix (539f2a7) stays.

What went wrong

  • fetch_organism.py and convert_annotations.py both import config.
  • At import, config.py logs the merged app_config, which includes secret.yaml's values. The init container mounts that file.
  • So tee'ing the scripts' output into $JOB_OUTPUT_DIR/log put the MinIO access and secret keys, the database password and the hCaptcha secret into the job log. This happened on every CRISPR-Copies run, not just failed ones.
  • post-job uploads that log to MinIO, and /v1/jobs/{id}/artifacts/log serves it.

Reproduced in the Dockerfile.test image with marker secrets: all four reached out/log on a successful run (exit 0, no error).

Status: none of this was merged or deployed. The branch's tree is now identical to 539f2a7, and the full suite passes (639).

Next: the setup-step fix will be redone so that only the scripts' own messages reach the log, not their raw output.

…secrets

fetch_organism.py and convert_annotations.py run as the crispr-copies prejob_command
in the backend's init container. A failure there failed that container, so the job
container and post-job never ran and nothing was uploaded.

The reverted e1eacb7 tee'd the scripts' raw output into the job log. That output
includes config.py's import-time log of app_config with secret.yaml merged in, so it
published the MinIO keys, database password and hCaptcha secret. This version writes
only the scripts' own messages:

- app/job_log.py: run_with_job_log() adds a file handler for $JOB_OUTPUT_DIR/log to the
  script's own logger only, and logs an uncaught exception with its traceback before
  exiting 1. Both scripts use it when run as scripts (not on import).
- prejob_command captures no output. On failure it appends a fixed line to the log and
  touches `error`, exiting 0 (chart/values.yaml, app/cfg/config.yaml,
  local.config.yaml).
- The CRISPR-Copies command skips the tool when `error` exists and appends to the log
  (tee -a), as in e1eacb7.

Tests run the real prejob_command and scripts with marker secrets: a failed GFF3
conversion leaves its reason in the log and no secrets, and so does a successful run.
The pod-level tests now use stand-in scripts that also print output that must stay
out of the log. Putting back e1eacb7's tee fails six tests; the original command
three; dropping the handler one; the old tool command four.
@matthewberry

Copy link
Copy Markdown
Collaborator Author

The CRISPR-Copies setup-step fix is redone in cd66c36, without the leak from e1eacb7.

How it works

  • Nothing captures the scripts' raw output. New app/job_log.py adds a file handler for $JOB_OUTPUT_DIR/log to each script's own logger only. So config.py's import-time dump of app_config, and anything other modules log, never reach the file.
  • Crashes are logged. An uncaught exception is logged with its traceback before the script exits 1.
  • prejob_command appends a fixed line to the log on failure, touches error and exits 0.
  • The tool command skips the tool when error exists and appends to the log with tee -a, as before.

Tests

  • The real prejob_command and scripts, run with marker secrets: a failed GFF3 conversion leaves its reason in the log and no secrets, and so does a successful run.
  • Putting e1eacb7's tee back fails six tests, including both secret checks. The original command, a missing handler and the old tool command each fail their own tests too.
  • Full suite: 647 passed.

Gap: a crash before a script sets up its logger, such as a failed import, leaves only the fixed line in the log. The PR description lists this and the other remaining gaps.

@matthewberry matthewberry left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed at cd66c36. One finding to fix before merge; everything else I checked holds up.

Finding: if the MinIO input sync fails, the log blames the wrong script, and the description gets this case wrong

The rendered init container script is:

mkdir -p … && mkdir -p … && ./prejob.py && pwd && ls -al ${JOB_INPUT_DIR} && (python fetch_organism.py && python convert_annotations.py) || (echo 'CRISPR-Copies setup step failed …' >> log; touch error)

In bash, && and || have equal precedence and group left to right. So the new || (…) applies to the whole chain, not just the setup step. A failure in prejob.py, mkdir or ls also lands in the fallback.

Reproduced in the Dockerfile.test image, using this PR's harness with the stand-in prejob.py changed to exit 1:

  • The init container exits 0.
  • The output directory holds error and log.
  • The log contains only "CRISPR-Copies setup step failed (fetch_organism.py or convert_annotations.py)."
  • The job container skips the tool and exits 0 with error, finished and log.

The job still ends up marked error, so job status is unaffected. Two things are wrong, though:

  • The log blames the wrong script. The sync's own output isn't in the log, and the message names two scripts that never ran.
  • The description says the opposite. Under "Still not covered" it says a prejob.py failure "still fails the init container before anything writes log". That's false.

Why the tests miss it: _run_crispr_pod hardcodes prejob.py to exit 0, and _run_real_setup_step runs prejob_command on its own, outside the template.

Suggested fix: wrap the whole value as one group, { (… && …) || (…; touch …); }, in all three config files. Then add a pod test where prejob.py fails and the init container exits non-zero. If the current behavior is actually preferred, change the message so it doesn't name those two scripts, and correct the description instead.

Checked and cleared

  • Rendering: the folded YAML renders the new prejob_command as one line, and the quoting survives.
  • Tests: test_tool_job_exit_code.py and test_postjob_exit_code.py pass at cd66c36 (24 passed). I did not rerun the full suite.
  • No secrets from other modules: the file handler goes on __main__'s logger, the logger both scripts use when run directly, and nothing logs to a child of it. So config.py's app_config dump can't reach the file.
  • Messages are logged before exiting: both scripts' sys.exit(1) paths call log.error first. Neither uses sys.exit("message").
  • Exception text: the scripts log MinIO S3Errors and CalledProcessErrors. Their text (bucket and object names, the datasets command line) contains no credentials. Arbitrary exceptions from other dependencies I didn't check; the description already says so.
  • File permissions: CRISPR-Copies' securityContext is runAsUser: 0, which applies to every container in the pod. So the job container's tee -a can write to the root-owned log the init container created.
  • Merges: a git merge-tree against #162 (1e00d2c) is still clean after cd66c36, which the earlier check predated. Other open PRs touching these config files: #171, #164 and #132. I didn't merge-test those.
  • Prior review notes: the Mutagenesis ; join and the frontend gap were both addressed in follow-ups. The secret leak was caught and reverted before anything was merged.

Note, not blocking

The init container image is hardcoded to mmli-backend:main, like post-job. So job_log.py and the scripts' new entry point only take effect once :main has them. Until then a failure leaves just the fixed line in the log. The existing "don't deploy before :main has #161" note covers the risky ordering, but this is worth one more sentence in the description.

Review on #169: the template splices prejob_command into
`mkdir ... && ./prejob.py && pwd && ls ... && <prejob_command>`. bash groups `&&` and
`||` left to right, so the new `|| (echo ...; touch error)` applied to the whole chain:
a failed MinIO input sync (prejob.py) let the init container exit 0 and logged that
fetch_organism.py or convert_annotations.py had failed.

Wrap the value in `{ ...; }` in all three config files, so a prejob.py failure fails
the init container as before.

The pod harness now stops after a failed init container, as the pod does, and takes a
prejob.py body. New test: a failed input sync fails the init container, writes no
`error` and logs nothing about the setup scripts. It failed before this change.
@matthewberry

Copy link
Copy Markdown
Collaborator Author

Thanks, confirmed and fixed in 759cf29.

  • Reproduced: I added a pod test where prejob.py exits 1. At cd66c36 the init container exited 0, as you found.
  • The fix: the value is now wrapped in { …; } in chart/values.yaml, app/cfg/config.yaml and local.config.yaml, so the fallback covers only fetch_organism.py and convert_annotations.py. A failed input sync fails the init container as it did before this PR.
  • Tests: _run_crispr_pod now takes a prejob.py body and, like the pod, doesn't run the job container after a failed init. The new test_a_failed_input_sync_still_fails_the_init_container checks for a non-zero exit, no error, and nothing about the setup scripts in the log. It fails at cd66c36 and passes now.
    • The existing setup-failure tests still pass, so the fallback still covers the two scripts.
    • Targeted tests: 25 passed. Full suite: 648 passed.
  • Description: the "Still not covered" line about prejob.py is accurate again, and a test now pins it.
  • Your deploy note: added. The init container is hardcoded to :main, so job_log.py takes effect only once :main has it. Until then a setup failure leaves just the fixed line in the log.

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.

1 participant