confusion around ignoring callsite frames

[dhduvall]

I have a program written to send all logs through structlog, and recently started using SQLAlchemy. I noticed that the SQL statement logging in SQLAlchemy was always putting _log_info as the function name in log entries, and found myself unable to fix this.

SQLAlchemy uses the stacklevel parameter to findCaller(), but structlog doesn't support that yet (#537).

I thought I might be able to use the additional_ignores parameter to CallsiteParameterAdder and/or the ignore_frame_names parameter to stdlib.LoggerFactory, but neither one seems to make any difference (I see now that this isn't the purpose of the latter).

When I run the following program (with uv run --script repro.py), I see lines like

select pg_catalog.version()              filename=base.py func_name=_log_info lineno=189
[raw sql] {}                             filename=base.py func_name=_log_info lineno=189

Indeed, all the entries have the same callsite information.

If I comment out the call to configure_structlog_logging() and call configure_python_logging() instead, I see

select pg_catalog.version()              filename=base.py func_name=_execute_context lineno=1842
[raw sql] {}                             filename=base.py func_name=_execute_context lineno=1842

(and some other function name/line number combinations later on).

I get that same behavior if I revert the change and use structlog again, but instead remove the logger_factory parameter to structlog.configure(). I'm not sure what deleterious effects that would have, but IIRC, the structlog guide to configure combined logging suggested that, so that's what I have.

If I remove the additional_ignores parameter to CallsiteParameterAddr, nothing changes (I added it in to try to fix the problem, but it didn't appear to help).

Before discovering #602, I tried modifying the argument to _find_first_app_fram_and_name() in _FixedFindCallerLogger.findCaller() to add "sqlalchemy.engine.base", and that worked, but differently than the way the stacklevel and no-logger_factory methods work. Now I get

select pg_catalog.version()              filename=base.py func_name=_get_server_version_info lineno=3513
[raw sql] {}                             filename=base.py func_name=_get_server_version_info lineno=3513

This makes sense to me, as we're ignoring all frames from that module, not just a specific number (this is where #386 would come in handy, as it would add precision over simply using the module name). Note that base.py is a different file here than the one referenced previously.

Is removing logger_factory a useful answer to this? The structlog/stdlib guide doesn't say that it's necessary or why it's preferred, it just uses it.

Source

# /// script
# requires-python = ">=3.13"
# dependencies = [
#     "psycopg==3.2.9",
#     "sqlalchemy==2.0.41",
#     "structlog==25.4.0",
# ]
# ///

import logging
import structlog

import sqlalchemy

def query() -> None:
    engine = sqlalchemy.create_engine("postgresql+psycopg://postgres@localhost/postgres")
    engine.logger.setLevel(logging.INFO)
    # What we don't want to see is func_name=_log_info in the logs.
    with engine.connect() as conn:
        res = conn.execute(sqlalchemy.text("SELECT 1"))
        print(res.first())

def configure_structlog_logging() -> None:
    shared_processors=[
        structlog.processors.CallsiteParameterAdder(
            {
                structlog.processors.CallsiteParameter.FILENAME,
                structlog.processors.CallsiteParameter.FUNC_NAME,
                structlog.processors.CallsiteParameter.LINENO,
            },
            additional_ignores=["sqlalchemy.engine.base"],
        ),
    ]

    structlog.configure(
        processors=shared_processors,
        logger_factory=structlog.stdlib.LoggerFactory(),
        wrapper_class=structlog.stdlib.BoundLogger,
    )

    formatter = structlog.stdlib.ProcessorFormatter(
        foreign_pre_chain=shared_processors,
        processors=[
            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
            structlog.dev.ConsoleRenderer(pad_event=40),
        ],
    )

    handler = logging.StreamHandler()
    handler.setFormatter(formatter)

    root_logger = logging.getLogger()
    root_logger.addHandler(handler)

def configure_python_logging() -> None:
    formatter = logging.Formatter("%(message)-40s filename=%(filename)s func_name=%(funcName)s lineno=%(lineno)d")

    handler = logging.StreamHandler()
    handler.setFormatter(formatter)

    root_logger = logging.getLogger()
    root_logger.addHandler(handler)

def main() -> None:
    configure_structlog_logging()
    # configure_python_logging()
    query()


if __name__ == "__main__":
    main()