Structured Logging for a project

Question

I am using Logging on my python project. My question is about the correct and elegant way of structuring the logging in my project, for that i will first describe the structure i am using.

I have 3 main .py scripts, so acquisition.py , actuation.py and management.py, that are called as services at startup. The 3 scripts above import network.py and devices.py.

I wanted to organize my logging per file associated with the 3 main scripts, so i would like to have: acquisition.log , actuation.log and management.log. Inside this logs i would like to have the respective logs from the calls to network.py a device.py (using the namespace %(name))

Example (acquisition.log):

INFO acquisition.thread 2016-03-17 12:26:02,069 in Thread 70de3b66-e14b-11e5-8953-80fa5b0ae007
DEBUG acquisition 2016-03-17 12:26:02,070 Thread launched 70de3b66-e14b-11e5-8953-80fa5b0ae007
INFO acquisition.devices 2016-03-17 12:26:03,072  Variable_R read:  0013a20040c1bb0b  temperature1
ERROR acquisition.devices 2016-03-17 12:26:19,076 variable.read.DeviceConfigurationError: 0013a20040c1bb0b 
INFO acquisition.thread 2016-03-17 12:26:19,077 exit Thread 70ddfa20-e14b-11e5-8953-80fa5b0ae007
ERROR acquisition.devices 2016-03-17 12:26:25,085 variable.read.DeviceConfigurationError: 0013a20040c1bb0b 
INFO acquisition.thread 2016-03-17 12:26:25,086 exit Thread 70de3b66-e14b-11e5-8953-80fa5b0ae007

In this case you can see that for the same log file, i can have logging from different files, it can be seen in the log namespace acquisition.thread and acquisition.devices.

The way i achieve this is having a logger function that i use to create a fallback logger in each file, where i am logging. And, later if i want to log information from that file, i alter in the main script file the logger created in the imported file.

Code example that explain the above:

acquisition.py (main script):

imports...
import logger_sys
import logging
import xnetwork
import xdevices

# Log configuration
log_name = os.path.basename(__file__).strip(".py")
logit = logger_sys.setup_logger(log_name, log_name) #internal logger for main file
logger_thread = logging.getLogger(log_name + '.thread')

#Log configuration of external files
xnetwork.logger = logging.getLogger(log_name + '.network')
xdevices.logger = logging.getLogger(log_name + '.devices')

logit.info("START acquisition_service")

# REST OF THE CODE... 

xdevices.py:

import logger_sys

# Fallback logger in case the calling script doesnt modify logger
log_name = __name__.strip(".py") + '_fallback'
logger = logger_sys.setup_logger(log_name, log_name, stream_hdlr=False)

# REST OF THE CODE...

xnetworks.py:

import logger_sys

# Fallback logger in case the calling script doesnt modify logger
log_name = __name__.strip(".py") + '_fallback'
logger = logger_sys.setup_logger(log_name, log_name, stream_hdlr=False)

# REST OF THE CODE...

logger_sys.py:

import logging, sys, os
from global_settings import RUNNING_MODE, DEBUG, STAGING, PRODUCTION

def setup_logger(namespace, filename, stream_hdlr=True):

    logger = logging.getLogger(namespace)

    handler_format = logging.Formatter("%(levelname)s %(name)s %(asctime)s %(message)s")

    log_handler = logging.FileHandler(filename + ".log")
    logger.addHandler(log_handler)
    log_handler.setFormatter(handler_format)

    if RUNNING_MODE == DEBUG:
        if stream_hdlr:
            log_handler = logging.StreamHandler(sys.stdout)
            logger.addHandler(log_handler)
            log_handler.setFormatter(handler_format)

        logger.setLevel(logging.DEBUG)

    elif RUNNING_MODE == STAGING or RUNNING_MODE == PRODUCTION:
        logger.setLevel(logging.INFO)

    return logger

Objective?

• I would like to know if there are a more elegant solutions, that don't use the logic of passing the logger as an argument in the methods that are called.

• I would like to understand how typically logging is structured in more complex cases, for example when using external modules.

• And, i would like to read critics about this strategy of logging.

Thank you in advance

Answer 1

You should study the official logging cookbook and some complex projects that do logging right. I suggest reading the requests source code to see how one fairly complex project does logging.

Perhaps the key takeaway from the cookbook for your case is:

Multiple calls to logging.getLogger('someLogger') return a reference to the same logger object. This is true not only within the same module, but also across modules as long as it is in the same Python interpreter process.

A typical approach is to have something like the following at the top of a file:

import logging
log = logging.getLogger(__name__)

This makes log global, so it can be used within functions without passing log as an argument:

def add(x, y):
    log.debug('Adding {} and {}'.format(x, y))
    return x + y

If you're creating some long running service and intend to log all/most/many function calls, consider using a decorator. I suggest this post from the Fresh Books Dev Blog as a introduction to using decorators for logging. It sounds like your program might benefit from the decorator approach.