Dagster log handler re-logs messages to @loggers so they can't use module/lineno/filename

[markfickett]

Summary

In a @logger as described at https://docs.dagster.io/concepts/logging/loggers#customizing-loggers and using a format like '[%(asctime)s %(name)] {%(filename)s:%(lineno)d} %(levelname)s - %(message)s','%m-%d %H:%M:%S' .

I would expect the logger name, filename, and line number to work correctly.

However, it always shows name=dagster filename=log_manager.py lineno=262.

I believe this is because Dagster is re-logging messages to @Loggers, rather than using original log messages.

            for logger in self._loggers:
                logger.log(
                    dagster_record.levelno,
                    dagster_record.msg,
                    exc_info=dagster_record.exc_info,
                    extra=self._extract_extra(record),
                )

https://sourcegraph.com/github.com/dagster-io/dagster/-/blob/python_modules/dagster/dagster/core/log_manager.py?L262

---

Message from the maintainers:

Impacted by this bug? Give it a 👍. We factor engagement into prioritization.

[jamiedemaria]

Looks like a bug to me! we'll triage it and get it in the backlog

[markfickett]

Thanks!

I think the ideal solution for me would be, instead of having a user-supplied logger, just have a user-supplied handler, and then DagsterLogHandler.emit would do if record.levelno >= user_handler.level: user_handler.handle(record) .

[agon-shabi]

Bumping this as the behaviour is quite surprising - I ran into it when trying to use sentry's logging integrations.

Found the same thing that @markfickett did, i.e. dagster is mutating the original log record prior to passing it to other loggers.

Also feels like user-supplied handlers would be sufficient, but I might be missing a benefit of user-supplied loggers.

Small script to demonstrate the undesirable behaviour:

# Custom loggers receive already-formatted log message, when we would expect them to receive the original

import logging
from logging import Handler, LogRecord
from dagster import op, logger, job, OpExecutionContext, InitLoggerContext


@logger
def my_logger(context: InitLoggerContext):  # function has to accept 'context' here even if not required.
    logger_ = logging.getLoggerClass()(name="my-logger", level=logging.INFO)
    logger_.addHandler(MyHandler())
    return logger_


class MyHandler(Handler):
    def emit(self, record: LogRecord) -> bool:
        print(f"The message: [{record.msg}]")
        return True

@op
def my_op(context: OpExecutionContext):
    context.log.info(f"My message")


@job(
    logger_defs={"my_logger": my_logger},
    config={
        "loggers": {
            "my_logger": {},  # have to specify this in the config, otherwise logger doesn't get created.
        },
    },
)
def my_job():
    my_op()


my_job.execute_in_process()

Outputs:

The message: [my_job - 8c543058-7edc-45c1-866d-bff702c61072 - my_op - My message]

It also appears that if I use a custom logger in this way, I don't get any of the standard event logs (e.g. RUN_START, ENGINE_EVENT, STEP_START, etc.)

• nevermind, this was because my handler was set to INFO level, and the dagster event logs are created at DEBUG