Skip to content

fix: logging None in shellcmd context causes error#4064

Merged
johanneskoester merged 3 commits intomainfrom
fix/logging-none-and-cmd
Mar 13, 2026
Merged

fix: logging None in shellcmd context causes error#4064
johanneskoester merged 3 commits intomainfrom
fix/logging-none-and-cmd

Conversation

@tedil
Copy link
Copy Markdown
Contributor

@tedil tedil commented Mar 12, 2026

Resolves #4063

In shell.py we have this line:

        if not context.get("is_shell") and jobid is not None:
            logger.info(None, extra=dict(event=LogEvent.SHELLCMD, cmd=cmd))

which logs with msg=None; we can either not do that, or make the downstream logging functions deal with this better. Seems to be triggered in slurm executor contexts, not sure about local executor.

(Ideally, the logging message should also be some kind of TypedDict to be able to spot and trace such issues more easily, but that is for a later PR I'd say)

QC

  • The PR contains a test case for the changes or the changes are already covered by an existing test case.
  • The documentation (docs/) is updated to reflect the changes or this is not necessary (e.g. if the change does neither modify the language nor the behavior or functionalities of Snakemake).

Summary by CodeRabbit

  • Bug Fixes

    • Prevent empty, "None", or missing formatted shell-command messages from being emitted in both plain and colorized logging, and prefer explicit command text when available to improve log clarity.
  • Tests

    • Added a unit test covering shell-command logging edge cases to ensure robust handling of missing or empty messages.

@coderabbitai
Copy link
Copy Markdown
Contributor

coderabbitai bot commented Mar 12, 2026

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info
⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

Run ID: 3a6916a3-1af3-4f69-8dcf-c666a77714ea

📥 Commits

Reviewing files that changed from the base of the PR and between c73dbb7 and ddb42b2.

📒 Files selected for processing (1)
  • tests/test_logging.py
🚧 Files skipped from review as they are similar to previous changes (1)
  • tests/test_logging.py

📝 Walkthrough

Walkthrough

A bug fix that prevents TypeError crashes when logging shell commands with None messages. The fix adds defensive None/empty string checks in the logging formatter and emit paths to consistently skip empty or "None" formatted messages.

Changes

Cohort / File(s) Summary
Logging Handler
src/snakemake/logging.py
Modified format_shellcmd to prefer cmd then msg, defaulting to empty string. Updated emit and colorizing output paths to treat None, the literal "None", or empty strings as non-emittable, skipping further processing.
Test Coverage
tests/test_logging.py
Added test_issue4063 which emits a SHELLCMD log with a None message via a ColorizingTextHandler to verify logging no longer raises TypeError and that error handling path is exercised.

Estimated code review effort

🎯 2 (Simple) | ⏱️ ~12 minutes

🚥 Pre-merge checks | ✅ 4 | ❌ 1

❌ Failed checks (1 warning)

Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 57.14% which is insufficient. The required threshold is 80.00%. Write docstrings for the functions missing them to satisfy the coverage threshold.
✅ Passed checks (4 passed)
Check name Status Explanation
Title check ✅ Passed The title 'fix: logging None in shellcmd context causes error' directly describes the main issue being addressed: preventing TypeError when None is logged in a shell command context.
Description check ✅ Passed The PR description references issue #4063, explains the root cause (logger.info(None, ...)), and confirms both test coverage and documentation handling through checked QC boxes.
Linked Issues check ✅ Passed The PR addresses the core requirement from issue #4063: preventing crashes when shell() is called inside run directives by handling None log messages in the logging handler.
Out of Scope Changes check ✅ Passed All changes in logging.py and test_logging.py are directly scoped to fixing the None message logging issue; no extraneous modifications detected.

✏️ Tip: You can configure your own custom pre-merge checks in the settings.

✨ Finishing Touches
  • 📝 Generate docstrings (stacked PR)
  • 📝 Generate docstrings (commit on current branch)
🧪 Generate unit tests (beta)
  • Create PR with unit tests
  • Post copyable unit tests in a comment
  • Commit unit tests in branch fix/logging-none-and-cmd
📝 Coding Plan
  • Generate coding plan for human review comments

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands and usage tips.

@cademirch cademirch requested review from cademirch March 12, 2026 09:55
@cademirch
Copy link
Copy Markdown
Contributor

lmk when this is ready

@tedil tedil marked this pull request as ready for review March 13, 2026 09:20
@tedil tedil requested a review from johanneskoester as a code owner March 13, 2026 09:20
@tedil
Copy link
Copy Markdown
Contributor Author

tedil commented Mar 13, 2026

lmk when this is ready

I think now is a good time, simply added a unit test to trigger that code path, fails on main, doesn't fail here.

Copy link
Copy Markdown
Contributor

@coderabbitai coderabbitai bot left a comment

Choose a reason for hiding this comment

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

🧹 Nitpick comments (1)
tests/test_logging.py (1)

104-136: Consider adding explicit assertion and ensuring cleanup.

The test correctly exercises the bug scenario, but the success condition is implicit. Additionally, if an exception occurs before removeHandler, the handler remains attached to the global logger which could affect other tests.

Suggested improvements for robustness
 def test_issue4063():
     # since it's difficult to replicate the exact conditions,
     # we'll do a unit test of the relevant logging code instead of a full workflow run.
     # the issue was that if the logger is configured with printshellcmds=True,
     # shell.py calls logger.info(None, extra={"event": LogEvent.SHELLCMD, "cmd": ...}),
     # which causes a crash because the default formatter expects the first argument to be a string message.
     from snakemake.logging import ColorizingTextHandler
     from snakemake.logging import DefaultFormatter
     from snakemake.logging import DefaultFilter
 
     handler = ColorizingTextHandler(stream=sys.stdout)
     formatter = DefaultFormatter(quiet=set(), show_failed_logs=False)
     handler.setFormatter(formatter)
 
     log_filter = DefaultFilter(
         quiet=set(), debug_dag=False, dryrun=False, printshellcmds=True
     )
     handler.addFilter(log_filter)
 
     # make the logging error a hard error
     def handle_logging_error(record):
         raise sys.exc_info()[1]
 
     handler.handleError = handle_logging_error
 
     test_logger = logging.getLogger("foo")
     test_logger.setLevel(logging.INFO)
     test_logger.addHandler(handler)
 
-    test_logger.info(
-        None, extra={"event": LogEvent.SHELLCMD, "cmd": "echo 'bar'"}
-    )
-    test_logger.removeHandler(handler)
+    try:
+        # This should not raise - the fix ensures None messages are handled gracefully
+        test_logger.info(
+            None, extra={"event": LogEvent.SHELLCMD, "cmd": "echo 'bar'"}
+        )
+    finally:
+        test_logger.removeHandler(handler)
🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed.

In `@tests/test_logging.py` around lines 104 - 136, The test test_issue4063
currently relies on implicit success and may leave the ColorizingTextHandler
attached if an error occurs; wrap the logging call in a try/finally inside
test_issue4063 so you always call test_logger.removeHandler(handler) in the
finally block, and add an explicit assertion (e.g., assert handler not in
test_logger.handlers or assert no exception was raised) after the logging call
to make the success condition explicit; reference the ColorizingTextHandler,
DefaultFormatter, DefaultFilter, and test_logger variables when applying the
change.
🤖 Prompt for all review comments with AI agents
Verify each finding against the current code and only fix it if needed.

Nitpick comments:
In `@tests/test_logging.py`:
- Around line 104-136: The test test_issue4063 currently relies on implicit
success and may leave the ColorizingTextHandler attached if an error occurs;
wrap the logging call in a try/finally inside test_issue4063 so you always call
test_logger.removeHandler(handler) in the finally block, and add an explicit
assertion (e.g., assert handler not in test_logger.handlers or assert no
exception was raised) after the logging call to make the success condition
explicit; reference the ColorizingTextHandler, DefaultFormatter, DefaultFilter,
and test_logger variables when applying the change.

ℹ️ Review info
⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

Run ID: 10b43440-2869-4c0a-974e-04b70e120b3b

📥 Commits

Reviewing files that changed from the base of the PR and between e9f2e1c and c73dbb7.

📒 Files selected for processing (2)
  • src/snakemake/logging.py
  • tests/test_logging.py

@github-actions
Copy link
Copy Markdown
Contributor

Please format your code with pixi run format

Copy link
Copy Markdown
Contributor

@cademirch cademirch left a comment

Choose a reason for hiding this comment

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

thanks for fixing this

(Ideally, the logging message should also be some kind of TypedDict to be able to spot and trace such issues more easily, but that is for a later PR I'd say)

Yes I agree. Overall the logger and its interface still needs quite a bit of further refinement 😅

@tedil
Copy link
Copy Markdown
Contributor Author

tedil commented Mar 13, 2026

Please format your code with pixi run format

do we not have pre-commit hooks? gnarf

@johanneskoester
Copy link
Copy Markdown
Contributor

Never came around to do this, but feel free to add them.

@johanneskoester johanneskoester enabled auto-merge (squash) March 13, 2026 10:36
@johanneskoester johanneskoester merged commit d0652cd into main Mar 13, 2026
60 checks passed
@johanneskoester johanneskoester deleted the fix/logging-none-and-cmd branch March 13, 2026 12:50
johanneskoester pushed a commit that referenced this pull request Mar 13, 2026
🤖 I have created a release *beep* *boop*
---


##
[9.17.0](v9.16.3...v9.17.0)
(2026-03-13)


### Features

* Allow storing snakemake metadata in files or databases
([#4012](#4012))
([dd75f31](dd75f31))
* Allow to specify comparison command per-unit test
([#3956](#3956))
([b88171c](b88171c))
* job table orderd topological when run is started
([#4018](#4018))
([75cf506](75cf506))
* lambda functions for priority in rules
([#3253](#3253))
([d2aa226](d2aa226))
* Make on... directive of modules accessible
([#4050](#4050))
([e9f2e1c](e9f2e1c))


### Bug Fixes

* adjust conda tests to not fail on apple silicon; fix
[#4040](#4040)
([#4049](#4049))
([f5b0142](f5b0142))
* allow "--containerize apptainer" to output apptainer format instead of
dockerfile ([#4030](#4030))
([f5cac30](f5cac30))
* apptainer command not recognized when singularity is absent
([#4010](#4010))
([b8162e2](b8162e2))
* capture stderr when tests fail
([#3995](#3995))
([97d74ba](97d74ba))
* **docs:** make Data-dependent conditional execution a complete example
([#4043](#4043))
([3a1d7f2](3a1d7f2))
* don't build the DAG when running unlock. Fixes
[#4000](#4000) and
[#198](#198)
([#4007](#4007))
([acf79fd](acf79fd))
* Ensure pixi tasks may be run as advertised
([#4046](#4046))
([88253c2](88253c2))
* fix checkpoint handling corner cases
([#3870](#3870) and
[#3559](#3559))
([#4015](#4015))
([63f4257](63f4257))
* issue 3642
([#4054](#4054))
([76e6fc2](76e6fc2))
* issue 3815
([#4026](#4026))
([b0eec96](b0eec96))
* logging None in shellcmd context causes error
([#4064](#4064))
([d0652cd](d0652cd))
* lookup function returns default value for empty DataFrame queries
([#4056](#4056))
([f71de97](f71de97))
* make `cache: omit-software` a rule specific property
([#4085](#4085))
([034a9e7](034a9e7))
* reduce number of tests leaving temporary files behind
([#4033](#4033))
([a3a1c97](a3a1c97))
* regression in dynamic resource handling
([#4038](#4038))
([f2c554a](f2c554a))
* somewhat shorter announce message
([#4080](#4080))
([57efc71](57efc71))


### Performance Improvements

* switch reretry with tenacity; decouple container classes (with Python
3.7 compat for old scripts) from rest of the codebase (enabling moving
to newer python versions)
([#4032](#4032))
([ffb19e7](ffb19e7))


### Documentation

* Add AI-assisted contributions policy to contributing guidelines
([#4051](#4051))
([dd70526](dd70526))
* **codebase:** Update & simplify plugin architecture section
([#4052](#4052))
([176cf63](176cf63))
* Correct workflow.source_path() description in documentation
([#4036](#4036))
([45883c5](45883c5))
* fixed wrong code example for collect() function
([#4037](#4037))
([5c85ed8](5c85ed8))
* Minor docs improvements
([#4089](#4089))
([29ea226](29ea226))
* switch to sphinx_design for tabs
([#3976](#3976))
([9674614](9674614))
* typo in the migration table breaking a pip install command
([#4024](#4024))
([66f9dda](66f9dda))

---
This PR was generated with [Release
Please](https://github.com/googleapis/release-please). See
[documentation](https://github.com/googleapis/release-please#release-please).
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.

shell inside run causes error during logging

3 participants