Python中DEBUG级别日志失效问题分析及解决

我在Python中实现日志功能，需将日志时区切换为纽约时区，为此开发了CustomFormatter类。当日志级别设为INFO及以上时功能正常，但设置为DEBUG级别时无日志输出。

相关代码 #

import logging
from datetime import datetime
from tzlocal import get_localzone
import pytz

# class CustomFormatter is to change timezone
class CustomFormatter(logging.Formatter):
    def converter(self, timestamp):
        dt = datetime.fromtimestamp(timestamp, tz=get_localzone())
        return dt.astimezone(pytz.timezone('America/New_York'))

    def formatTime(self, record, datefmt=None):
        dt = self.converter(record.created)
        if datefmt:
            s = dt.strftime(datefmt)
        else:
            try:
                s = dt.isoformat(timespec='milliseconds')
            except TypeError:
                s = dt.isoformat()
        return s

def logging_config(log_filename, log_level, 
                   log_format = '%(asctime)s.%(msecs)03d - %(levelname)s - %(message)s', 
                   date_format='%Y%m%d_%H:%M:%S'):
    # Create a logger object
    logger = logging.getLogger()

    # Configure the logging level
    logger.setLevel(log_level)

    # Create a file handler
    file_handler = logging.FileHandler(log_filename)

    # Create a stream handler (to display logs in the notebook)
    stream_handler = logging.StreamHandler()

    # Create the custom formatter
    formatter = CustomFormatter(log_format, datefmt=date_format)

    # Set the formatter for both handlers
    file_handler.setFormatter(formatter)
    stream_handler.setFormatter(formatter)

    # Set the logging level for both handlers
    file_handler.setLevel(log_level)
    stream_handler.setLevel(log_level)

    # Add both handlers to the logger
    logger.addHandler(file_handler)
    logger.addHandler(stream_handler)

    return logger

def logging_test(logger):
    # Log messages
    logger.debug('This is a debug message')
    logger.info('This is an info message')
    logger.warning('This is a warning message')
    logger.error('This is an error message')
    logger.critical('This is a critical message')
    return 0

if __name__ == '__main__':
    log_filename = './log_test.log'
    print('log_filename*', log_filename)
    log_format = '%(asctime)s.%(msecs)03d - %(levelname)s - %(message)s'
    logger = logging_config(log_filename = log_filename,
                            log_format = log_format,                              
                            log_level = logging.DEBUG, #INFO,
                            date_format="%Y%m%d_%H%M%S")
    
    logging_test(logger)

现象 #

• 设置log_level = logging.DEBUG时，仅输出：

$ ipython local_functions.py
log_filename* ./log_test.log
(base)

• 设置为INFO及以上级别时，日志输出正常：

log_filename* ./log_test.log
20240104_211453.256 - INFO - This is an info message
20240104_211453.261 - WARNING - This is a warning message
20240104_211453.261 - ERROR - This is an error message
20240104_211453.262 - CRITICAL - This is a critical message

该问题已通过将tz = get_localzone()修改为tz = pytz.utc解决，问题根源如下：

问题根源 #

1. get_localzone()的加载异常：get_localzone()需要读取系统时区配置文件（如/etc/timezone或Windows注册表），在部分环境（如容器、简化Python环境、IPython/Jupyter）中，可能存在时区文件缺失、权限不足或初始化顺序问题，导致调用时抛出静默异常。
2. 日志级别对异常的容忍度差异：日志模块处理DEBUG级别日志时，对格式化阶段的异常容忍度极低——一旦CustomFormatter.converter方法抛出异常，整个DEBUG日志记录会被直接丢弃；而INFO及以上级别日志的处理逻辑有更宽松的异常捕获，或者异常发生时会 fallback 到默认格式化逻辑，因此能正常输出。
3. pytz.utc的稳定性：换成pytz.utc后，跳过了加载本地时区的复杂流程，不存在依赖系统配置的问题，因此不会抛出异常，所有级别日志都能正常处理。

内容的提问来源于stack exchange，提问作者Boris Kushnarev