CODEWITHSUNDEEP
pythonlogging
Sledge
Sledge

Reputation: 1345

Custom extra data in python log with multiple modules

I'm trying to implement a logger in python that involves many modules. The core functionality involves a gRPC microservice which takes a payload, generates an id and does some optimization.

When multiple requests come in at once, the log can get jumbled up. What I would like to do is tag the logger lines with a the run_id so that the run_id prints in the log for each function call made in the parent and all imported modules.

I tried this:

logger = logging.getLogger("myservice")
log_file = "logs/solver.log"
formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(log_id)s - %(name)s - %(message)s", datefmt="%y/%m/%d %H:%M:%S")  #: log_id is custom data
log_data = {'log_id': None}

concise_log = logging.FileHandler(log_file)                 #: file handler for concise log
concise_log.setLevel(logging.INFO)
concise_log.setFormatter(formatter)

#: Add the logging hanlders to the logger
logger.addHandler(concise_log)
logger.addHandler(detailed_log)

logger.info(f"log_file: {log_file}", extra=log_data)
logger.info("LOG START", extra=log_data)
logger.debug("Debug level messages are being recorded.", extra=log_data)

I used a dummy value for log_data initially because the logger will error out otherwise.

Later on I set the log_id and log various things like so: 

    log_id = str(uuid.uuid4())
    log_data = {'log_id': log_id}      #: extra data for logger

    #: load the server config:
    logger.info("loading server config...", extra=log_data)

This works fine, but if I make calls to my logger in any imported function, it will error out because those functions don't have log_data.

What I would like to be able to do is set the log_id in a more global way so that the logger always has the right log_id in the imported modules, which will change from request to request.

Is there another pattern that I should be using to accomplish this?

Upvotes: 3

Views: 2641

Answers (1)

blues
blues

Reputation: 5195

This is best done with a LoggerAdapter. The official documentation has an excellent example that is very close to what you are trying to do. The code will approximately look like this:

class LogIdAdapter(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        return '[%s] %s' % (self.extra['log_id'], msg), kwargs

tmp_logger = logging.getLogger("myservice")
# ... set up handlers etc here. do not include log_id in formatter, it will be added later
logger = LogIdAdapter(tmp_logger, {'log_id': str(uuid.uuid4())})

logger.info("some text") # this log will have log_id prepended

Upvotes: 2

Related Questions