Why Your Python Logger Might Be Playing Hard to Get (And How We Made It Work)

The Quest for the Elusive Logs

As Python developers, we've all been there: you set up logging, you expect it to work, and then... nothing. No logs in your console. No helpful debug messages. It’s like your logger has decided to go on vacation. 😤

But don't worry, dear reader. Today, we’re going to walk you through the epic saga of troubleshooting logging issues, and how we turned a silent logger into a chatty, verbose champion.

The Problem: The Mysterious Case of the Invisible Logs

So there we were, just trying to log some information with Python’s built-in logging module and structlog (for those shiny structured logs). We fired up our logger with the hope of getting some valuable output, only to find… silence.

We had set up everything—environment variables, log levels, handlers, the works. But for some reason, our log messages were nowhere to be found.

We dug into the code and found the culprit: the log level was printing as 0—a mysterious NOTSET. If the log level is 0, the logger is essentially a lazy couch potato that doesn't want to do anything. No logs, no effort. 🛋️

What Went Wrong?

Let's break down what went wrong, and why our logger wasn't being cooperative:

Logging Level Wasn't Set Properly: Python’s logging module uses levels (e.g., DEBUG, INFO, WARNING, ERROR, CRITICAL) to determine which log messages to show. The log level tells the logger to filter out messages below a certain level. But, when the logger's level is set to NOTSET (level 0), it's like the logger is in "I'll only log if I feel like it" mode.
Miscommunication Between basicConfig() and the Logger: We had configured basicConfig(), which should set the level for logging, but somewhere along the way, the logger was ignoring this and just sitting there, doing nothing.
Handler Confusion: We also tried adding a StreamHandler to direct the logs to stdout, but if basicConfig() wasn’t working properly or if handlers were being set multiple times, it made the logger a little...confused. 🤔

The Solution: Making the Logger Work Harder

At this point, we knew what needed to be done: a little nudge to get the logger back on track.

Explicitly Set the Log Level: After calling basicConfig(), we ensured the logger’s level was explicitly set to the correct level (like INFO or DEBUG) using base_logger.setLevel(log_level). This ensured the logger knew exactly what level of logs to capture. It’s like saying, “Hey logger, you’re not on vacation anymore. Get to work!”
Handler Check: We checked if the logger already had handlers attached. If not, we added a StreamHandler to make sure our logs were outputting to stdout. No duplicate handlers allowed! No one likes unnecessary noise.
Simplified the structlog Setup: Finally, we simplified the structlog setup just to make sure nothing complicated (like custom JSON renderers) was getting in the way. With ConsoleRenderer, the logger was happily displaying its logs in the console, with some color to boot. 🌈

The Code That Saved the Day

Here’s what the final code looked like after we made the necessary adjustments:

import logging
import sys
import structlog
import os

def get_logger():
    # Fetch log level from environment, default to INFO if not set
    log_level = os.environ.get("LOG_LEVEL", "INFO").upper()

    # Ensure log level is valid
    try:
        log_level = getattr(logging, log_level)
    except AttributeError:
        log_level = logging.INFO  # Default to INFO if invalid log level

    # Set up logging configuration
    logging.basicConfig(
        level=log_level,
        stream=sys.stdout,  # Ensure output to stdout
        format="%(message)s"  # Simplify format for testing
    )

    # Get the logger
    base_logger = logging.getLogger("ingestit")

    # Print logger level to debug if it's being set correctly
    print(f"Logger level (before setLevel): {base_logger.level}")

    # Explicitly set the log level for this logger
    base_logger.setLevel(log_level)

    # Print logger level after setting it explicitly (for debugging)
    print(f"Logger level (after setLevel): {base_logger.level}")

    # Add a handler if none exists (to avoid duplicate handlers)
    if not base_logger.handlers:
        handler = logging.StreamHandler(sys.stdout)
        handler.setFormatter(logging.Formatter("%(message)s"))
        base_logger.addHandler(handler)

    # Wrap logger with structlog
    logger = structlog.wrap_logger(
        base_logger,
        processors=[
            structlog.stdlib.add_log_level,
            structlog.processors.TimeStamper(fmt="iso"),
            structlog.dev.ConsoleRenderer(colors=True)  # Simplified for debugging
        ],
        wrapper_class=structlog.stdlib.BoundLogger,
    )

    logger.info("Logger initialized successfully!")
    return logger

The Outcome: Logging Triumph!

With these changes in place, our logger was no longer a lazy couch potato. 🎉 It was hard at work, logging messages to the console, and giving us all the insights we needed.

Here’s what we saw when we tested it:

logger = get_logger()
logger.info("This is a test log message.")

Expected output: A well-structured log message with timestamps and log levels, right in our terminal. ✨

Key Takeaways:

Always Explicitly Set the Log Level: Don’t leave the logger in NOTSET mode. Set the level explicitly after configuring basicConfig().
Check for Duplicate Handlers: If you're adding handlers, ensure they aren’t added multiple times. It’s like inviting your friends to a party, but not giving them multiple invitations.
Use Simple Configs for Debugging: When things aren’t working, sometimes the simplest solutions (like using ConsoleRenderer in structlog) can help you isolate issues quickly.

In Conclusion...

If your Python logger ever starts acting like a hermit and refusing to share anything, don’t despair. Armed with a little debugging and the right settings, you too can have a verbose and talkative logger. After all, it’s much easier to debug when you can actually see what’s going on.

Now go forth, and log with confidence! ✌️

Why Your Python Logger Might Be Playing Hard to Get (And How We Made It Work)

Harleen Mann

Data & Integration Architect