How to add code line number using structlog

Question

Using python standard logging module, the line number for the originating log call can be added using: %(lineno)s.

How can this be accomplished using structlog?

Answer 1

EDIT:

Structlog version 21.5.0 introduced the CallsiteParameter processor, so this should be a much more straightforward process right now, as @vitvlkv's answer shows.

---

I had a similar need and I ended up creating a custom processor

I took a look to what structlog does to output the module and line number when it is told to "pretend" to format in a compatible mode with the logging library (meaning: when it's using a regular stdlib.LoggerFactory) and I found inspiration in that. The key were the following words...

By using structlog’s structlog.stdlib.LoggerFactory, it is also ensured that variables like function names and line numbers are expanded correctly in your log format.

... from this documentation page

The code seems to keep looking for execution frames until it finds one that is in a non logging-related module.

I have all the setup for structlog inside a module called my_libs.util.logger so I want to get the first frame that is NOT inside that module. In order to do that, I told it to add my logging-related my_libs.util.logger to those exclusions. That's what the additional_ignores in the code below does.

In the example I hardcoded the module's name ('my_libs.util.logger') in the exclusion list for clarity, but if you have a similar setup you'll probably be better off using __name__ instead. What this does is ignoring execution frames that exist because of the logging machinery in place. You can look at it as a way of ignoring calls that may have occurred as part of the process of actually logging the message. Or, otherwise said, calls that happened after the logging.info("Foo") that happened in the actual module/line that you do want to output.

Once it finds the right frame, extracting any kind of information (module name, function name, line number... ) is very easy, particularly using the inspect module. I chose to output the module name and the line number, but more fields could be added.

# file my_libs/util/logger.py
import inspect
from structlog._frames import _find_first_app_frame_and_name

def show_module_info_processor(logger, _, event_dict):
    # If by any chance the record already contains a `modline` key,
    # (very rare) move that into a 'modline_original' key
    if 'modline' in event_dict:
        event_dict['modline_original'] = event_dict['modline']
    f, name = _find_first_app_frame_and_name(additional_ignores=[
        "logging",
        'my_libs.util.logger',  # could just be __name__
    ])
    if not f:
        return event_dict
    frameinfo = inspect.getframeinfo(f)
    if not frameinfo:
        return event_dict
    module = inspect.getmodule(f)
    if not module:
        return event_dict

    if frameinfo and module:
        # The `if` above is probably redundant, since we already
        # checked for frameinfo and module but... eh... paranoia.
        event_dict['modline'] = '{}:{}'.format(
            module.__name__,
            frameinfo.lineno,
        )
    return event_dict

def setup_structlog(env=None):
    # . . . 
    ch.setFormatter(logging.Formatter('%(message)s'))

    logging.getLogger().handlers = [ch]

    processors = [
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        # . . . more . . . 
        show_module_info_processor,  # THIS!!!
        structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S"),
        structlog.processors.format_exc_info,
        structlog.processors.StackInfoRenderer(),
        # . . . more . . . 
    ]

    # . . . more . . . 
    structlog.configure_once(
        logger_factory=structlog.stdlib.LoggerFactory(),
        wrapper_class=structlog.stdlib.BoundLogger,
        context_class=structlog.threadlocal.wrap_dict(dict),
        processors=processors,
    )

This produces an output like:

server_1                           
| INFO  [my_libs.hdfs] 2019-07-01 01:01:01 [info     ] Initialized HDFS               
[my_libs.hdfs] modline=my_libs.hdfs:31

Answer 2

Have a look at this answer to the more general question of how to get a line number. https://stackoverflow.com/a/3056270/5909155 This cannot be bound to the logger with log.bind(...) because it has to be evaluated each time you log. Thus, you should add a key-value pair like this

logger.log(..., lineno=inspect.getframeinfo(inspect.currentframe()).lineno)

each time. Maybe wrap this in a function, though, like this: https://stackoverflow.com/a/20372465/5909155 Don't forget to

import inspect

Answer 3

According to official docs, you may add

structlog.configure(
        processors=[
            # ...
            # Add callsite parameters.
            structlog.processors.CallsiteParameterAdder(
                [CallsiteParameter.FILENAME,
                CallsiteParameter.FUNC_NAME,
                CallsiteParameter.LINENO],
            ),
            # ...
        ],

So, I guess there is no need to write a custom processor for this. It was hard to find in the official docs though.