Unexpected side-effect to calling LoggerFactory()

[hp685]

I'm using structlog package 19.2.0 but I've validated the behavior to be the same in version 19.1.0. Instantiating LoggerFactory causes all subsequent calls to logging.getLogger to be of type structlog.stdlib._FixedFindCallerLogger.

import logging
from structlog.stdlib import BoundLogger, LoggerFactory
from structlog import wrap_logger

print (logging.getLogger('foo'))
print(wrap_logger(logging.getLogger('bar'), 
    logger_factory=LoggerFactory(), wrapper_class=BoundLogger))

print(logging.getLogger('jazz'))  # would expect this to be a logging.Logger instance

prints

logging.Logger object at 0x10169bf90>
<BoundLoggerLazyProxy(logger=<logging.Logger object at 0x101732990>, wrapper_class=<class 'structlog.stdlib.BoundLogger'>, processors=None, context_class=None, initial_values={'logger_factory': <structlog.stdlib.LoggerFactory object at 0x1017dbad0>}, logger_factory_args=())>
<structlog.stdlib._FixedFindCallerLogger object at 0x1017db8d0>

A minimal example (May not be appropriate usage. Only to illustrate)

import logging
from structlog.stdlib import LoggerFactory

print(logging.getLogger('foo'))
LoggerFactory()
print(logging.getLogger('jazz'))  # would expect this to be a logging.Logger instance

prints

<logging.Logger object at 0x1085b9f90>
<structlog.stdlib._FixedFindCallerLogger object at 0x108650990>

This is a rather unexpected side-effect and causes client's code to return an unexpected type for logging.getLogger calls if structlog LoggerFactory is ever instantiated in a parent application. Is this something that can be addressed?

[hynek]

Why ist that a problem to you? The class that replaces it is a subclass of Logger and should be fully compatible. The behavior is also documented:

Sets a custom logger using logging.setLoggerClass() so variables in log format are expanded properly.

[hp685]

Hey @hynek,

It causes class name change for downstream applications' logger that run within a host app, which can be perplexing for maintainers of downstream apps.

In my scnenario, the application supports dynamic updates and based on some config value, we set the logger type to logging.Logger, structlog or a custom logger. Each logger also logs the class name and it's difficult to differentiate if every logger returns structlog.stdlib._FixedFindCallerLogger after structlog is used at least once.

[giorgiodig]

This is causing issues with opentelemetry:

Invalid type _FixedFindCallerLogger for attribute '_logger' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types [opentelemetry.attributes] _from_structlog=False _record=<LogRecord: opentelemetry.attributes, 30, /Users/giorgio/.local/share/virtualenvs/releasebot-_HUS3iaX/lib/python3.11/site-packages/opentelemetry/attributes/__init__.py, 101, "Invalid type %s for attribute '%s' value. Expected one of %s or a sequence of those types">

[hynek]

This is causing issues with opentelemetry:

Invalid type _FixedFindCallerLogger for attribute '_logger' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types [opentelemetry.attributes] _from_structlog=False _record=<LogRecord: opentelemetry.attributes, 30, /Users/giorgio/.local/share/virtualenvs/releasebot-_HUS3iaX/lib/python3.11/site-packages/opentelemetry/attributes/__init__.py, 101, "Invalid type %s for attribute '%s' value. Expected one of %s or a sequence of those types">

I'm sorry, but I don't know what to make of this and I don't have the time to go spelunking through the whole OTEL code base.

Could you provide an Short, Self Contained, Correct, Example?

[folt]

I have the same problem, structlog is causing an error in the logs.

[roger-collins-self]

@giorgiodig @folt

My current fix to get this working with OpenTelemetry (and Websockets):

from opentelemetry.sdk._logs import LoggingHandler
from opentelemetry.util.types import Attributes

class AttrFilteredLoggingHandler(LoggingHandler):
    DROP_ATTRIBUTES = ["_logger", "websocket"]

    @staticmethod
    def _get_attributes(record: logging.LogRecord) -> Attributes:
        attributes = LoggingHandler._get_attributes(record)
        for attr in AttrFilteredLoggingHandler.DROP_ATTRIBUTES:
            if attr in attributes:
                del attributes[attr]
        return attributes

OTEL's LoggingHandler doesn't call the super().emit nor does it call self.format(), so the processors are never run. This means the Record still has a the _logger attribute stored from structlog.stdlib.ProcessorFormatter.wrap_for_formatter which can't be serialized.

I believe the only way to fix this is a PR to the Python OpenTelemetry SDK