72.1 The logging Module: Levels, Loggers, Handlers, Formatters
Right, let’s talk about logging. You’ve been using print() statements to debug your code since you wrote your first Hello, World. I get it. It’s immediate, it’s simple, and when your script is three lines long, it’s perfect. But you’re not writing three-line scripts anymore, are you? You’re building applications. And when your application is running on a server at 2 AM and something goes horribly wrong, you’re not going to SSH in to tail -f a bunch of print() output. You need a system. A robust, configurable, and frankly, adult system for understanding what your code is doing when you’re not there to watch it. That system is the logging module.
It’s powerful, but its power comes from its architecture, which can feel a bit convoluted at first. Stick with me. Once you see how the pieces fit together, you’ll never go back.
The Core Components: It’s a Pipeline
Think of logging not as a single function, but as an assembly line. A log message is the raw material, and it goes through a series of stations where it gets shaped, filtered, and finally shipped off to its destination. The four key stations are:
- Loggers: The entry point. You create a named logger (usually
logger = logging.getLogger(__name__)in each module) and use it to create log messages (.info(),.error(), etc.). - Handlers: The destination. They take a log message and send it somewhere. To the console? A file? An email? A database? That’s the handler’s {{< bibleref “Job 3 ” >}}. Formatters: The stylists. They take a log record and turn it into a string. Want a timestamp, the logger name, the filename, and the line number? The formatter makes that happen.
- Filters: The bouncers (optional). They provide fine-grained control to let certain records pass and deny others, even beyond the level-based filtering.
The beauty is that these components are loosely coupled. You can attach multiple handlers (e.g., a console handler and a file handler) to a single logger, and each handler can have its own formatter and filter. This is why it scales from a simple script to a massive enterprise application.
Logging Levels: The Hierarchy of Problems
The logging module uses levels to categorize the severity of your messages. This isn’t just bureaucracy; it’s your primary filter for controlling verbosity. The levels, in increasing order of severity, are: DEBUG, INFO, WARNING, ERROR, and CRITICAL.
The default level is WARNING. This is the most common “gotcha.” Your logger has a level, and so does your handler. A message will only be emitted if it meets or exceeds the level of both the logger and the handler. If you write logger.debug("Calculated value: %s", value) and see nothing, it’s because your logger is still set to its default, WARNING.
import logging
# Get a logger for the current module. Best practice, right here.
logger = logging.getLogger(__name__)
# This won't print anything because the default level is WARNING.
logger.debug("This is a debug message. You won't see me by default.")
logger.info("Won't see this either.")
# This will print because it's >= WARNING.
logger.warning("This is a warning. Now you see me!")
logger.error("And this is an error. You'll definitely see this.")
Configuring the Machinery
You can configure all of this in code, which is great for scripts. But for any real application, you should use a configuration dictionary or file. It keeps your configuration separate from your logic and is infinitely more maintainable.
Here’s a basic setup in code, attaching a console handler with a custom formatter:
import logging
# Create a logger specific to our module
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG) # Capture everything from DEBUG up
# Create a console handler that logs even DEBUG messages
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
# Create a formatter with useful info. Note: using %-style for a change.
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
# Add the handler to the logger
logger.addHandler(ch)
# Now this will work!
logger.debug("This is a detailed debug message. Useful for development.")
The real power move is using logging.config.dictConfig(). You can define your entire logging infrastructure in a dictionary (or YAML/JSON file) and load it once at the start of your application.
import logging
from logging.config import dictConfig
config_dict = {
'version': 1,
'formatters': {
'detailed': {
'format': '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'detailed',
},
'file': {
'class': 'logging.FileHandler',
'filename': 'app.log',
'level': 'DEBUG', # File gets the spicy DEBUG details
'formatter': 'detailed',
}
},
'root': { # The root logger captures all messages from all loggers
'level': 'DEBUG',
'handlers': ['console', 'file']
}
}
dictConfig(config_dict)
# Now any logger in your application will use this config
logger = logging.getLogger(__name__)
logger.info("This goes to both the console and the file!")
logger.debug("This goes only to the file. The console isn't nosy enough for this.")
Pitfalls and “Oh, Come On” Moments
The Root Logger Trap: If you just call
logging.info()instead of using a module-specific logger, you’re using the root logger. It’s global. If some library you’re using also configures the root logger, you can accidentally break your own logging or have your messages intermingled with library messages in weird ways. Always create your own named logger withgetLogger(__name__). It’s the closest thing to a logging best practice that is an absolute law.String Formatting: Do It Right. Never use f-strings or
%-formatting inside a log call. Why? Because the string is formatted immediately, even if the message is filtered out and never logged. This is a waste of CPU cycles. Use the built-in formatting of the logging methods. They only do the work if the message is actually going to be output.# BAD: Formatted even if DEBUG is disabled. logger.debug(f"Value is {calculate_expensive_value()}") # STILL BAD: The % operation happens immediately. logger.debug("Value is %s" % calculate_expensive_value()) # GOOD: Arguments are passed and formatting is only done if needed. logger.debug("Value is %s", calculate_expensive_value())Logger Hierarchy & Propagation: Loggers have a hierarchy based on their names, using dot notation.
getLogger('my_app')is the parent ofgetLogger('my_app.utils'). By default, a message logged tomy_app.utilswill also propagate up to the handlers ofmy_appand the root logger. This is why you sometimes see the same message logged three times. You can control this with thepropagateattribute on a logger, but understanding the hierarchy is key to untangling a messy logging setup.
The logging module is a classic Python “batteries-included” masterpiece. It’s a bit complex because the problem it solves is complex. Master it, and you’ll have a window into your application’s soul, day or night.