Logger触发异常后重复输出问题及解决方案

Let me break down the underlying mechanics here—this is a super common gotcha with Python's logging system combined with Flask's default behavior.

1. The Root Cause: Log Propagation + Flask's Auto-Configured Root Logger #

Python's logging system uses a hierarchical structure. When you create a custom logger (like logging.getLogger("my_logger")), it inherits from the root logger by default, and its propagate attribute is set to True. That means any log message your custom logger emits will also be passed up to all parent loggers (including the root logger) to be handled again.

Here's what happens when Flask hits an exception:

• Flask detects that the root logger hasn't been configured yet (which is often the case if you only set up your own logger), so it automatically adds a default StreamHandler to the root logger.
• This default handler uses a basic format that doesn't include timestamps (something like %(levelname)s: %(name)s: %(message)s).
• So when your custom logger outputs a message (with your timestamped format), the same message gets propagated up to the root logger, which outputs it again using Flask's plain format. That's why you see duplicate output—one from your handler, one from Flask's root handler—and the second one loses the timestamp.

2. Why Disabling Flask's Logger Fixes It #

When you disable Flask's logger (e.g., app.logger.disabled = True), you're telling Flask not to touch the root logger at all. It won't add its default handler, so there's no second handler to duplicate your log messages. Your custom logger's output is the only one that gets printed.

A Better Fix (Without Disabling Flask's Logger) #

Instead of disabling Flask's logger entirely, you can just stop your custom logger from propagating messages up the chain. Add this line when setting up your logger:

logger.propagate = False

This keeps your custom logger's output isolated—messages won't reach the root logger, so Flask's default handler won't duplicate them. You'll still keep Flask's own logs (like server startup messages) if you want them.

Example to Illustrate #

Here's a simplified version of what your code might look like, and how to fix it:

import logging
from flask import Flask

# Set up custom logger
logger = logging.getLogger("my_logger")
formatter = logging.Formatter('%(asctime)s Any_Name: %(message)s')
handler = logging.StreamHandler()
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.INFO)
# Add this to stop propagation
logger.propagate = False

app = Flask(__name__)

@app.route('/fail')
def trigger_error():
    logger.info("My heart will go on!")
    raise ValueError("Oops, an error occurred")

if __name__ == '__main__':
    app.run(debug=True)

Now when you hit /fail, you'll only see your timestamped log message once, even when the exception is raised.

Recap of the Underlying Mechanics #

• Python logging uses a parent-child hierarchy; child loggers propagate messages up by default.
• Flask auto-configures the root logger with a basic handler/format when it encounters an unconfigured root logger during an exception.
• Duplication happens because both your custom handler and Flask's root handler process the same log message.
• Timestamp loss occurs because Flask's default log format doesn't include %(asctime)s.

内容的提问来源于stack exchange，提问作者Anders Breid