After updating to

0.15.2

, I'm seeing lots of log messages like

2022-06-28 10:55:16 -0400 - dagster - DEBUG - battery_data_job_local - 983e56f8-a69b-4edd-937b-0417012c2a37 - 296222 - STEP_WORKER_STARTED - Executing step "blah" in subprocess.

that don't seem to be respecting the

dagster.yaml

setting of:

python_logs:
  python_log_level: INFO

Yeah, this was me, I'll take a look at this

Thanks!

Which process output are you seeing them in exactly?

In the console. I'm running a job via

dagster.execute_pipeline

.

Roger

Ah bummer. I am seeing something different, but I'm also hacking around

DagsterLogHandler

to get console logging output the way I want (previous discussion on that), and maybe that's working <= 0.15.0 but not with

default_system_loggers

. So maybe this is a feature request and not a regression with this specific message's handling.

Ah, yeah, I think we would need to see your changes to evaluate that

Here's my extension for DagsterLogHandler which I patch in. I think the issue (for this setup) is that the "Executing step" message doesn't go through DagsterLogHandler, whereas most other messages do. And the

dagster.yaml

log level setting doesn't come into play either way. But https://github.com/dagster-io/dagster/pull/8648 looks like just what I'd need!

class _PatchedDagsterLogHandler(log_manager.DagsterLogHandler):
    """Customize DagsterLogHandler to get back original messages and add formatting."""

    def __init__(self, *args, **kwargs):
        self._customized_handler = logging.StreamHandler()
        # This handler's filter only affects console output, so the noisy messages
        # remain visible in the Dagit UI. (Also even if this filter edits the
        # messages' level in place, the Dagit UI and JSOn logger still sees them at
        # their original level, possibly because those loggers consume them first.)
        self._customized_handler.addFilter(NoisyLogsFilter())
        self._customized_handler.setFormatter(coloredlogs.ColoredFormatter(_FORMAT))
        self._customized_handler.setLevel(<http://logging.INFO|logging.INFO>)
 
        super().__init__(*args, **kwargs)

    def _convert_record(self, record: logging.LogRecord) -> logging.LogRecord:
        """Restores the LogRecord's original msg.

        This needs to override the existing DagsterLogHandler's behavior because it
        affects both our console output, and logs sent to OpenTelemetry / JSON.

        <https://github.com/dagster-io/dagster/issues/7642>
        """
        converted = super()._convert_record(record)
        if "STEP_FAILURE" in converted.msg:
            # Dagster packs exception info for step failures into
            # converted.dagster_meta['dagster_event'].event_specific_data.error
            # not standard exc_info, so just use the provided formatted msg.
            return converted

        # Dagster's log_manager.DagsterLogHandler overwrites the LogRecord's msg and
        # args fields in-place. Although the original getMessage() value is saved in
        # dagster_meta["orig_message"], the args and exc_info are lost.
        record.msg = record.dagster_meta["orig_message"]
        record.args = ()  # Dagster stores the result of getMessage(), not msg + args.
        record.exc_text = None  # Tell downstream formatters to reformat exc_info.
        return record

    def handle(self, record):
        """Passes records to our custom console handler.

        We use this instead of the Dagster framework @logger mechanism because Dagster
        re-logs the message to @loggers and they therefore lose the logger name,
        filename/lineno, etc. <https://github.com/dagster-io/dagster/issues/7890> By
        passing records to our handler's .handle() method we make all original
        attributes available for formatting.

        Dagster doesn't expose a way to add more handlers along side DagsterLogHandler,
        so adding a sub-handler here is just a way to hook into the log record stream.
        It also matches the pattern DagsterLogHandler uses, or dispatching log records
        to various other internal handlers and log records.
        """
        super().handle(record)
        # The level check is usually done before the handler gets the record.
        if self._customized_handler and (
            record.levelno >= self._customized_handler.level
        ):
            self._customized_handler.handle(record)

So I've learned that at least one of our executors relies on the pod logs to do its job 😕 specifically the celery_k8s_executor. So this may need to be a different setting than instance.python_log_level

Gocha. Well, I can't really balance that tradeoff, but we're not using Celery and do use console logs. (:

Hi @daniel @Mark Fickett does this issue affect all other launchers, or just Celery? With the docker launcher, I tried to set the log level to WARN

python_logs:
  python_log_level: WARN

and could still see the INFO logs coming out from the daemon process. I'm on 1.0.6. Thanks

Hi @daniel, revisiting this thread. The context is that I've held off updating past Dagster 0.15 because our team's typical workflow is to run the Dagster job via a

execute_job

call and view console logs, and the

default_system_loggers

DEBUG

output makes this too noisy to be usable. But I'd like to get up to date. Would you be OK with adding another setting such as

default_system_log_level

as a peer of

python_log_level

? Glad to help with a PR based on yours above, but I'm not sure where to find associated tests / docs / etc that would need updating as well. I was also trying to patch

default_system_loggers

or

LogManager

or

LogHandler

at runtime, but I'm not finding a time when my code is loaded and can do some patching before the log machinery is already set up and issuing step-start events.

i'm going to tag in @owen about the last idea about loggers, although I believe he's at coalesce so may be a bit slower to respond - if there was a way to workaround with config that sounds ideal though

I did try to set that

loggers

config and it didn't seem to have any effect. From spelunking in the code a bit, it looks like

default_system_loggers

doesn't look at any configs, and the multiprocess executor just calls

create_context_free_log_manager

which always uses the

default_system_loggers

. So if I'm following that right, with a multiprocess executor it just always installs the default system logger at DEBUG level and does not consult other loggers or configs, but I was hoping I'd missed something.

ah, ok - so it seems that it's just those STEP_WORKER_STARTED and RUN_START events that are logged at the very beginning of the process before the config is read in

OK, thanks. Is there anything I can do to help with that -- comment with use case on the PR, work up a minimal example, etc?

right, the breaking change would be configuring the log level to something other than DEBUG while using one of those executors

Awesome, thank you sir!