RFC: v3

[cademirch]

AI Disclaimer: I did use AI (claude) to draft this document. Feel free to skim! Most of the ideas/concepts here are my own or belong to those tagged. I have reviewed this substantially.

Related issues/PRs:

• logger-plugins#32 — Event dataclasses
• logger-plugins#49 — More log events / more logging information
• logger-plugins#44 — Refactor plugin base
• snakemake#3856 — Reasonable "quiet" option
• snakemake#2882 — --quiet settings not intuitive
• snakemake#2973 — --quiet no longer prints summary
• snakemake#2441 — More control on retry behaviour
• snakemake#2123 — Cluster retry get failure reason
• snakemake#226 — Keep track of external job IDs after completion
• slurm#65 — Dynamic resources depending on retry reason

---

Background

Snakemake's logging has been through a few iterations. The original system was a custom Logger singleton with a self.log_handler callback list and a monolithic text_handler method. Every log message was a dict with a level string — "job_info", "job_error", "shellcmd", "progress", etc. — and text_handler was a giant if/elif chain dispatching on those strings:

level = msg["level"]
if level == "job_info" and not self.is_quiet_about("rules"):
    ...
elif level == "job_error":
    ...
elif level == "shellcmd":
    if self.printshellcmds:
        ...
elif level == "job_finished" and not self.is_quiet_about("progress"):
    ...

When I refactored logging to use standard Python logging and added the logger plugin interface, I created the LogEvent enum by directly mapping these old level strings to enum values. "job_info" became LogEvent.JOB_INFO. "job_error" became LogEvent.JOB_ERROR. "shellcmd" became LogEvent.SHELLCMD. This was the pragmatic choice at the time — it preserved existing behavior and let me get the plugin interface shipped without rethinking everything at once. But in retrospect I should have taken the time to rethink the event boundaries — JOB_INFO and JOB_STARTED could have been unified, groups didn't need their own event types, and the emission pattern (building bespoke extra dicts with None as the message) was carried over from the old system when it didn't need to be.

PR #32 adds typed dataclasses for parsing LogRecord payloads, and @jlumpe has contributed significantly to the design (the LogEventData base class, from_record()/from_extra() defaults, alias handling) and raised the plugin base refactor discussion in #44. But the dataclasses are still organized around those same legacy event types.

This RFC proposes redesigning the event model now that we have a clearer picture of what plugins and monitoring tools actually need. Most of the issues below trace directly back to that 1:1 mapping I did from the old text_handler levels. Before moving forward — I want to gather thoughts and feedback.

---

Event model

The problem

The current event types mirror the old text_handler dispatch, not the domain. A job's lifecycle is split across JOB_INFO, JOB_STARTED, JOB_FINISHED, and JOB_ERROR — four types with different field shapes that plugins have to correlate. Groups add two more. Emission is scattered: Job.log_info() emits JOB_INFO, then a separate SHELLCMD for the command, then separate logger.info() calls for checkpoint notes. One conceptual moment ("this job is about to run") produces 3-4 log records.

Call sites build bespoke dicts (extra=dict(event=LogEvent.JOB_INFO, jobid=..., ...)) with inconsistent field names (jobid vs job_id, groupid vs group_id). Structured events get emitted with None as the message — the real content is in extra — which is why ColorizingTextHandler.emit() has a special guard against it. I carried this pattern over from the old system — it worked, but it means there's no standard way for a handler to get a useful string representation of an event without reimplementing the formatter's logic.

Proposed: 8 event types replacing 14

Replace 14 LogEvent values with 8, organized around domain concepts:

Current	Proposed	What changes
WORKFLOW_STARTED, RUN_INFO, RESOURCES_INFO, RULEGRAPH	WORKFLOW	One type, status field. Stats, resources, rulegraph are fields on the started event. needs_rulegraph goes away.
JOB_INFO, JOB_STARTED, JOB_FINISHED, JOB_ERROR	JOB	One type, status field. JOB_STARTED batch notification becomes a plain log message.
GROUP_INFO, GROUP_ERROR	(into JOB)	Jobs carry an optional group_id. No separate group events.
SHELLCMD from log_info	(into JOB)	Shell command is a field on JobDescription.
SHELLCMD from shell.__new__	SHELLCMD	Stays — actual runtime command execution.
DEBUG_DAG	DAG	DAG resolution at debug level + lifecycle at info level.
PROGRESS	PROGRESS	Unchanged.
ERROR	ERROR	Non-job exceptions.
(new)	DEPLOYMENT	Conda create, container pull, env module activate. ~20 currently unstructured calls.
(new)	STORAGE	File retrieve/upload/cleanup. ~10 currently unstructured calls.

DEPLOYMENT and STORAGE address #49 — structured info about environments, storage operations, etc. that are currently just logger.info() strings no plugin can parse.

Event structure

All events inherit from LogEventData, which carries a workflow_id field. This gets stamped automatically by EventPromotingFilter so call sites don't need to pass it — every event is associated with the workflow run that produced it.

Complex events use nested dataclasses. Simpler events (DagEvent, ShellCmdEvent, ProgressEvent) are flat.

JobEvent has identity fields (job_id, rule_name, group_id, status) plus two optional nested objects:

• JobDescription — static info: inputs, outputs, wildcards, resources, shellcmd, benchmark data, etc. Populated on info, finished, and error so each event is self-contained.
• JobResult — execution result from the executor: exit code, failure mode, external job ID, execution environment.

WorkflowEvent has identity + status plus:

• WorkflowDescription — job count stats, resources, rulegraph, host info. Populated on started.

DeploymentEvent is designed around the new snakemake-interface-software-deployment-plugins. SDM plugins have clear lifecycle phases (pin → cache → deploy → activate → remove) and a common_settings.provides value identifying the provider. DeploymentEvent uses these directly:

@dataclass
class DeploymentEvent(LogEventData):
    provider: str = ""      # from common_settings.provides: "conda", "container", etc.
    action: str = ""        # "pin", "cache", "deploy", "activate", "remove", "check"
    spec: Optional[str] = None
    detail: Optional[str] = None

Forward-compatible with any future SDM plugin — a monitoring tool sees provider="conda", action="deploy" and can render it however it wants.

ErrorEvent is for non-job exceptions logged through print_exception(). Snakemake's exception hierarchy already carries workflow context (RuleException has .rule, .lineno, .filename, etc.) but print_exception() flattens it all into a formatted string. ErrorEvent extracts the fields plugins actually need:

@dataclass
class ErrorEvent(LogEventData):
    message: str = ""
    exception_type: str = ""
    rule_name: Optional[str] = None
    snakefile: Optional[str] = None
    lineno: Optional[int] = None
 
    @classmethod
    def from_exception(cls, ex, linemaps=None): ...

from_exception() lives in snakemake core (it knows about RuleException vs WorkflowError). The dataclass lives in the interface package. message carries the full formatted output from format_exception_to_string(). I'm intentionally keeping this minimal — things like affected files or nested exception trees are in the message and can be promoted to typed fields later if plugin authors need them.

Event emission

With the redesign, every event dataclass gets a __str__ returning a useful one-liner, and call sites just use standard logger methods:

logger.info(job.to_event(JobStatus.INFO))
logger.info(DagEvent(action="building"))
logger.error(ErrorEvent.from_exception(ex, linemaps))
logger.debug(DagEvent(action="resolving", rule="align"))

An EventPromotingFilter on the logger detects when record.msg is a LogEventData instance, copies it to record.event_data, and stamps the workflow_id:

class EventPromotingFilter(logging.Filter):
    def __init__(self, workflow_id=None):
        self.workflow_id = workflow_id
 
    def filter(self, record):
        if isinstance(record.msg, LogEventData):
            record.event_data = record.msg
            if self.workflow_id and not record.msg.workflow_id:
                record.msg.workflow_id = self.workflow_id
        return True

Added once during LoggerManager setup. Handlers and handler-level filters see record.event_data already populated. record.getMessage() returns the __str__ output. No special methods on the dataclass — just standard logging.

Job.log_info(), Job.log_error(), and Job.get_log_error_info() (~75 lines) collapse into Job.to_event(status, **overrides). GroupJob.to_events() delegates to each child's to_event() with group_id set. The Job builds the data, the caller decides when and at what level to log it.

---

Structured executor data

See snakemake/snakemake-interface-common/issues/95 for more details.

In brief: JobResult is a new dataclass in snakemake-interface-common that executors populate with structured execution results — exit code, failure mode, external job ID, execution environment. BenchmarkData is a companion type that BenchmarkRecord exports to, giving plugins typed access to resource usage through the logger. Both flow through JobEvent: event.result for executor data, event.description.benchmark for profiling data.

The key motivation beyond logging: structured failure data unblocks failure-aware retries (#2441, #2123, slurm#65), and persisting external job IDs addresses #226.

---

Verbosity

The problem

The current Quietness system is something I inherited from the old text_handler's is_quiet_about() method and mapped more or less directly. It doesn't map to what users expect — --quiet rules suppresses errors, --quiet progress suppresses the job stats summary. (#3856, #2882, #2973)

Proposed: numeric scale

Status: needs further discussion. I'm not fully settled on the details yet. The general direction:

Level	Flag	Shows
0	--silent	Errors only
1	--quiet / -q	+ progress, workflow summary, job finish one-liners
2	(default)	+ full job info, deployment, storage, DAG status
3	--verbose / -v	+ all plain info messages, shell commands
4	--debug	+ debug-level DAG resolution, internal state

VerbosityFilter would replace DefaultFilter. Old --quiet [rules|progress|all] deprecated with a warning. The details need more thought — particularly around how this interacts with subprocess/remote execution and what users actually expect from --quiet.

Compact formatting is out of scope for this effort. I'm working on a rich logging plugin in parallel — that's where formatting concerns belong, in the plugin, not baked into core.

---

Plugin base refactor (#44)

The problem

The current LogHandlerBase is itself a logging.Handler subclass, so plugin authors can't inherit from StreamHandler or FileHandler without constructor conflicts. @jlumpe raised this in #44 and #37.

Proposed: factory pattern

Replace LogHandlerBase with a base class that creates a handler from a factory method rather than being one itself. Plugins that just need a custom formatter on a FileHandler can do exactly that. Backwards compatibility via a shim wrapping old-style plugins. This pairs naturally with the event model changes — both are breaking, so we do them together in v3.

[jlumpe]

First of all, thanks for creating this RFC. I can see how trying to maintain a 1:1 mapping to how the old logging system worked is problematic, and agree it's probably worth it to take some extra time right now to think about how to reorganize all the events in a way that makes more sense. Making an RFC like this is a great way to plan that out and promote/organize discussion on the topic.

Here are some thoughts/questions in no particular order.

• Having the dataclass instances themselves be the log messages instead of dumping everything into extra is a nice design. Adding the __str__() methods should make it all work with standard logging machinery. In this case, is setting the event_data attribute needed?
• How much of an issue is backwards compatibility? It seems like many of these changes would/could break 3rd party logging plugins, but it also seems like there aren't many of those out there?
• Good job collapsing multiple events into a single WORKFLOW event, that was somewhat annoying before.
• Is there still a 1:1 mapping between the event enum and the event data classes, or is the enum meant to be a general category? If the former, it seems like the job started, finished, and error events could still carry very different attributes.
• The verbosity question seems like it is mostly limited in scope to how the default log handler works, which could be made mostly independent of these larger architectural changes (although you may want to make the logic reusable by alternate log handlers/plugins).

Another thought - is the Python standard library logging system generally the right tool for this job? There are a few ways that Snakemake's usage of it differs from standard or does not use its primary features:

• The hierarchical system of having multiple loggers registered by name, with propagating events that are possibly handled or filtered differently based on where they came from, is unused. The workflow uses a single global logger and emits all events from it. Especially since all handlers (including from plugins) are registered on that same logger, you can't even catch events from 3rd party libraries, so the system is essentially completely independent of anything else.
• The standard system is primarily intended for text-based logging. If we're expecting most plugin loggers to be inspecting all of these extra attributes they are already going to be very specialized, and so it's less likely they'll need to rely on any of the standard library logging functions or classes.

This might be too complex a change, but removing the dependence on Python's logging system might just look like attaching a list of handler classes or callbacks to the LoggerManager instance (and giving it another method to emit records). You could still have a handler that forwards those events to the standard Python logger (for backwards compatibility, or for implementing simple text-based loggers) but it wouldn't form the core of the system.

[cademirch]

Thanks for the thoughts @jlumpe

Will give this a full response later, but wanted to address a few things quickly!

The hierarchical system of having multiple loggers registered by name, with propagating events that are possibly handled or filtered differently based on where they came from, is unused.

I think this could be in scope for these changes. I have thought a lot about using hierarchal loggers snakemake.workflow/dag/job etc. We could even build these loggers for their specific event/domain?

The workflow uses a single global logger and emits all events from it

I would like to get away from this eventually. Even getting rid of loggermanager and just using logging.dictconfig. This is achievable I think.

Another thought - is the Python standard library logging system generally the right tool for this job? There are a few ways that Snakemake's usage of it differs from standard or does not use its primary features

I do agree in that we are largely abusing the logging library in ways that it was probably not intended. However, given that we've built up this logging-plugin-interface we may be committed towards this. Though this does bring up this discussion of monitoring vs logging again and I think now its worth considering this distinction again. My previous stance was that logging and monitoring are largely the same, and I think that is true in the sense of outcome: seeing what your workflows are doing/how they are failing. But the mechanisms that enable logging vs monitoring are maybe in conflict? And by trying to fit both into standard library logging we get a bit of a mess? In any case, I'd appreciate your thoughts on this and perhaps any existing solutions or libraries we can use or draw inspiration from.

[tedil]

I completely agree with @jlumpe; I think moving to a simple event bus architecture that loggers and monitors can both subscribe to is the right move (i.e., ditching the default Python logging module as the core router).
A default text logger could just call __str__ on the dataclasses it receives, while a monitoring plugin would take the structured data and do whatever it needs to do.

If we really don't want to ditch standard Python logging, making use of hierarchical loggers seems like a reasonable fallback to me.

One minor thing: I'd love to use this refactor as an opportunity to establish a consistent naming scheme for all attributes. For example, lineno is a bit of a legacy term that doesn't fit the naming pattern of the rest of the fields. I'd much rather have explicitly named fields that follow the same pattern, like line_number in this case.

[cademirch]

I completely agree with @jlumpe; I think moving to a simple event bus architecture that loggers and monitors can both subscribe to is the right move (i.e., ditching the default Python logging module as the core router).
A default text logger could just call str on the dataclasses it receives, while a monitoring plugin would take the structured data and do whatever it needs to do.

If we really don't want to ditch standard Python logging, making use of hierarchical loggers seems like a reasonable fallback to me.

I'm open to this but am hesitant because I can't quite envision what this would look like in practice. If a logger is not the core router then what would be?

In any case, I do think sticking with stdlib logging is the way forward, as I think we can get to something really good with it by ironing out the kinks of the current event system. And I think the core idea that has emerged in this discussion is Snakemake pushes logs/events and plugins consume them and do as they please. The current version of the logger interface is a good proof of this idea, but does need some work still, namely the typed interface on the plugin side, but also cleaning up the events and attributes themselves.

Out of curiosity, I looked into how other projects handle structured logging on top of stdlib. OpenTelemetry's Python SDK uses setLogRecordFactory() to inject trace context into every LogRecord at creation time, and their LoggingHandler explicitly preserves non-string record.msg objects to keep structured data intact. Sentry's LoggingIntegration extracts structured data from LogRecord attributes in their handlers to build Sentry events.

Concretely, I think two pieces address the typed-interface concern:

1. Use setLogRecordFactory() to make event_data a first-class field on every LogRecord from creation
2. Provide an EventHandlerBase class in the interface package with no-op default implementations of on_job_event, on_workflow_event, etc. and a dispatch_event(record) method that handles the type-based routing. Plugin authors subclass it alongside any logging.Handler, override only the event methods they care about, and call dispatch_event from emit. Roughly:

# In the interface package
class EventHandlerBase:
    def dispatch_event(self, record: logging.LogRecord) -> None:
        event = get_event(record)
        match event:
            case None:
                self.on_plain_message(record)
            case JobEvent():
                self.on_job_event(event)
            case WorkflowEvent():
                self.on_workflow_event(event)
            case DeploymentEvent():
                self.on_deployment_event(event)
            case ErrorEvent():
                self.on_error_event(event)
    
    # No-op defaults — override the ones you care about
    def on_job_event(self, event: JobEvent) -> None: ...
    def on_workflow_event(self, event: WorkflowEvent) -> None: ...
    def on_deployment_event(self, event: DeploymentEvent) -> None: ...
    def on_error_event(self, event: ErrorEvent) -> None: ...
    def on_plain_message(self, record: logging.LogRecord) -> None: ...

# In a plugin — composes with any stdlib Handler
class MyConsoleHandler(EventHandlerBase, logging.StreamHandler):
    def __init__(self, stream=sys.stderr):
        logging.StreamHandler.__init__(self, stream)
    
    def emit(self, record):
        self.dispatch_event(record)
    
    def on_job_event(self, event: JobEvent):
        if event.status == JobStatus.FINISHED:
            self.stream.write(f"✓ {event.rule_name} (job {event.job_id})\n")
        elif event.status == JobStatus.ERROR:
            self.stream.write(f"✗ {event.rule_name}: {event.result.error_type}\n")
    
    def on_workflow_event(self, event: WorkflowEvent):
        if event.status == WorkflowStatus.STARTED:
            self.stream.write(f"Starting workflow with {event.description.total_job_count} jobs\n")

3. For plugin authors who want full control, the interface package also exposes a lower-level get_event(record) utility that just returns the typed event (or None). they can use it directly in their own Handler subclass without going through EventHandlerBase

I also agree on hierarchal loggers! I think that would be good to use. And eventually getting rid of the global logger manager in favor of dict config.