Setting Up Proper Logging • Nicolay Christopher Gerold

Obviously, you want to log at the right level.

DEBUG (10): Detailed diagnostic information
INFO (20): Confirmation of expected operation
WARNING (30): Unexpected event or near-future problem
ERROR (40): Software couldn’t perform function
CRITICAL (50): Program may be unable to continue

How to decide between them? I would say go with your gut. Don’t over-do it.

The logging is made of several components: loggers, handlers, filters, and formatters.

Loggers: Interface for application code
- Determine which messages to handle based on severity
- Pass messages to handlers
- Support hierarchical naming (e.g., ‘parent.child’)
Handlers: Send log records to destinations
- Console (StreamHandler)
- Files (FileHandler)
- Network (SocketHandler)
- Email (SMTPHandler)
- System logs (SysLogHandler)
Formatters: Define log message structure
- Time, level, logger name, message
- Custom formats using attributes like %(levelname)s, %(message)s

Most people declare the logger once and are done with it. It’s simple, consistent and easy to use.

You can configure them in your code, or in a configuration file.

logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

### Or from a dict

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'simple': {
            'format': '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
        },
        'detailed': {
            'format': '%(asctime)s - %(name)s - %(levelname)s - %(pathname)s:%(lineno)d - %(funcName)s() - %(message)s'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'file': {
            'class': 'logging.FileHandler',
            'formatter': 'detailed',
            'filename': 'app.log'
        }
    },
    'root': {
        'handlers': ['console', 'file'],
        'level': logging.DEBUG,
        'formatter': 'simple'
    }
})

[loggers]
keys=root

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

What many people don’t know is that the logging module maintains a registry of loggers. So you can “override” the logger configuration for a specific module.

For example, a good convention to use when naming loggers is to use a module-level logger. This means that you use the __name__ of the module as the logger name.

This let’s you log the module name in your logs. So if we are in a myapp.users.auth, we can use that info in our logs:

logger = logging.getLogger(__name__)

# Global logger output
"ERROR: User authentication failed"

# __name__ based logger output
"ERROR [myapp.users.auth]: User authentication failed"

def setup_logging():
    # configuration here

import logging
from logger_setup import setup_logging
setup_logging()
logger = logging.getLogger(__name__)

The global configuration is still applied.

If we want to override it, we can use:

logger = logging.getLogger("myapp.users.auth")
logger.propagate = False

The handlers can send logs to different destinations. At the same time.

Sounds like overkill, but it’s useful if you have to audit the logs, you run code in customer environments, or you want to send critical logs to an email address.

{
    'console': {
        'class': 'logging.StreamHandler',
        'formatter': 'simple'
    },
    'file': {
        'class': 'logging.FileHandler',
        'formatter': 'detailed',
        'filename': 'app.log'
    }
}

I send the logs to the console and to a file.

But I can also send the logs to a network socket, or to an email address, or anywhere else.

Formatting is more of a personal preference. I don’t want to over-do it. I want the information to find logs easily and trace it back to the source and specific invocation.

Often that’s information on the line number, the function name, and the file name. But also timestamps, user ids, request ids, etc.

Everything you need to find the source, associate it with a specific invocation, and give you the ability to replicate the issue.

formatter = logging.Formatter(
    fmt='%(asctime)s - %(name)s - %(levelname)s - %(pathname)s:%(lineno)d - %(funcName)s() - %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S'
)

In most production environments, you pipe the logs somewhere else (e.g. ELK Stack, Sentry, etc.), so you can analyze them.

So you want to format the logs in a way that is easy to parse.

class JSONFormatter(logging.Formatter):
    def format(self, record):
        log_data = {
            'timestamp': self.formatTime(record),
            'level': record.levelname,
            'module': record.module,
            'function': record.funcName,
            'line': record.lineno,
            'message': record.getMessage()
        }
        return json.dumps(log_data)

You don’t want to weed through all the logs to find the ones you need.

That’s why you use filters.

Often you want to exclude logs from certain functions (e.g. sucessfull health checks).

class HealthCheckFilter(logging.Filter):
    def filter(self, record):
        return 'health_check' not in record.getMessage() and record.levelno < logging.WARNING

logger.addFilter(HealthCheckFilter())

You thought we were done? No. We can add more context to the logs with adapters.

Adapters set context for all log messages.

Request IDs
User IDs
Session IDs
Environment information

Here’s how to use them:

class RequestContextAdapter(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        return '[Request: %s] [User: %s] %s' % (
            self.extra['request_id'],
            self.extra['user_id'],
            msg
        ), kwargs

# Set up the adapter
logger = logging.getLogger(__name__)
context_logger = RequestContextAdapter(logger, {
    'request_id': 'abc-123',
    'user_id': 'user-456'
})

# Now all logs will include the context
context_logger.info("User updated their profile")
# Output: [Request: abc-123] [User: user-456] User updated their profile

You can even make it dynamic using middleware (in a web application):

class RequestLoggingMiddleware:
    def __init__(self, get_response):
        self.get_response = get_response
        self.logger = logging.getLogger(__name__)

    def __call__(self, request):
        request_id = str(uuid.uuid4())
        user_id = request.user.id if request.user.is_authenticated else 'anonymous'

        context_logger = RequestContextAdapter(self.logger, {
            'request_id': request_id,
            'user_id': user_id
        })

        request.logger = context_logger  # Attach to request object
        return self.get_response(request)

You would then use the request.logger to log within the API call.

Main learnings

Use name for logger names to automatically track the module hierarchy
Use logger.exception() for exceptions - it automatically includes traceback
Configure logging at the application’s entry point
Different handlers can have different formatters and levels