本文探讨了在python `logging` 配置中，当 `datefmt` 参数被错误地设置为 `datetime.now()` 的结果时，导致所有日志记录显示相同时间戳的问题。通过深入分析 `%(asctime)s` 和 `%(msecs)03d` 的工作机制，文章提供了两种解决方案：一是移除 `datefmt` 以利用默认的时间戳格式，二是通过在 `format` 字符串中显式添加 `%(msecs)03d` 来实现带有毫秒的自定义时间格式，确保日志时间戳的动态性和准确性。
在Python应用程序中，日志记录是调试、监控和故障排除的关键组成部分。logging 模块提供了高度灵活的配置选项，允许开发者自定义日志的输出格式、目的地和级别。然而，在配置日志时间戳时，一个常见的误区可能导致所有日志记录的时间戳显示为同一个值，尤其是在尝试使用 datefmt 参数来自定义时间格式时。本文将深入分析这一问题的原因，并提供两种有效的解决方案。
理解 logging 中的时间戳字段
在 logging.Formatter 中，有两个主要的格式化字段与时间戳相关：
-
%(asctime)s: 这是日志记录时间的主要字段。它的具体格式由 Formatter 实例的 datefmt 参数控制。
- 如果 datefmt 未指定，%(asctime)s 将使用默认格式，该格式通常包含毫秒（例如 YYYY-MM-DD HH:MM:SS,mmm）。
- 如果 datefmt 已指定，%(asctime)s 将严格按照 datefmt 字符串进行格式化。这意味着，如果 datefmt 只定义到秒，那么 %(asctime)s 也只会显示到秒，而不会包含毫秒。
- %(msecs)03d: 这个字段专门用于显示当前日志记录的毫秒部分。它总是输出三位数字，不足三位时前导补零。这个字段与 datefmt 参数无关，它直接从日志记录的时间戳中提取毫秒信息。
问题根源：datefmt 中的一次性求值
当在 logging 配置字典中将 datefmt 参数设置为 datetime.now().isoformat(...) 或类似的时间函数调用时，问题便会浮现。例如：
'datefmt': datetime.now().isoformat(sep='T',timespec='milliseconds')
这里的关键在于 datetime.now().isoformat(...) 表达式会在 logging_config 字典被创建（即脚本加载 logger_settings.py 文件时）的那一刻被执行一次。这意味着 datefmt 的值是一个固定的字符串，它代表了配置加载时的那个特定时间点。
立即学习“Python免费学习笔记（深入）”；
因此，所有后续的日志记录，无论它们何时发生，其 %(asctime)s 字段都会被这个固定的 datefmt 值所格式化。如果 datefmt 字符串本身不包含动态的毫秒占位符，那么所有日志条目的时间戳看起来就如同“静止”了一般，无法反映出不同日志事件之间微小的时间差异。
解决方案
为了确保日志时间戳的动态性和毫秒精度，我们可以采用以下两种解决方案：
方案一：利用 %(asctime)s 的默认毫秒精度
如果对时间戳的格式要求不高，并且希望 %(asctime)s 自动包含毫秒，最简单的方法是不设置 datefmt 参数，或者将其设置为 None。
示例配置：
import logging
import sys
from datetime import datetime
import time
logging_config_default_msecs = dict(
version=1,
formatters={
'verbose': {
'format': ("%(asctime)s %(levelname)s "
"[%(name)s:%(lineno)s] %(message)s"),
# 'datefmt': None # 或者直接移除此行，%(asctime)s将使用默认格式
},
'simple': {
'format': '%(asctime)s %(levelname)-8s %(message)s',
# 'datefmt': None
},
},
handlers={
'console': {
'class': 'logging.StreamHandler',
'level': 'DEBUG',
'formatter': 'verbose',
'stream': sys.stdout,
},
},
loggers={
'app_logger': {
'handlers': ['console'],
'level': logging.DEBUG,
'propagate': False
},
}
)
# 示例使用
if __name__ == '__main__':
from logging.config import dictConfig
print("--- 方案一：利用 %(asctime)s 默认毫秒精度 ---")
dictConfig(logging_config_default_msecs)
logger = logging.getLogger('app_logger')
logger.info("这是第一条日志 (方案一)")
time.sleep(0.005) # 模拟时间间隔
logger.info("这是第二条日志 (方案一)")
time.sleep(0.008)
logger.info("这是第三条日志 (方案一)")在这种配置下，%(asctime)s 将使用 logging 模块的默认格式，通常为 YYYY-MM-DD HH:MM:SS,mmm，自动包含毫秒。
方案二：自定义 datefmt 并显式添加 %(msecs)03d (推荐)
如果需要自定义 datefmt 的格式（例如 ISO 8601 格式，但不希望 datefmt 自身处理毫秒），可以将 datefmt 设置为只包含年月日时分秒的格式，然后在 format 字符串中显式地添加 %(msecs)03d 来显示毫秒。这是最灵活且符合期望的解决方案，它允许你精确控制日期时间的整体格式，同时确保毫秒部分的动态性。
示例配置：
import logging
import sys
from datetime import datetime
import time
logging_config_custom_msecs = dict(
version=1,
formatters={
'verbose': {
'format': ("%(asctime)s.%(msecs)03d %(levelname)s " # 显式添加 .%(msecs)03d
"[%(name)s:%(lineno)s] %(message)s"),
'datefmt': '%Y-%m-%dT%H:%M:%S' # datefmt 只定义到秒
},
'simple': {
'format': '%(asctime)s.%(msecs)03d %(levelname)-8s %(message)s',
'datefmt': '%Y-%m-%dT%H:%M:%S'
},
},
handlers={
'file_handler': {'class': 'logging.FileHandler',
'formatter': 'verbose',
'level': logging.DEBUG,
'filename': '/tmp/logtest_'+datetime.now().strftime("%Y%m%d-%H%M%S")+'.log'},
'console': {
'class': 'logging.StreamHandler',
'level': 'DEBUG',
'formatter': 'simple',
'stream': sys.stdout,
},
},
loggers={
'app_logger': {
'handlers': ['file_handler', 'console'], # 确保引用正确的handler名称
'level': logging.DEBUG,
'propagate': False
},
}
)
# 示例使用
if __name__ == '__main__':
from logging.config import dictConfig
print("\n--- 方案二：自定义 datefmt 并显式添加 %(msecs)03d ---")
dictConfig(logging_config_custom_msecs)
logger = logging.getLogger('app_logger')
logger.info("这是第一条日志 (方案二)")
time.sleep(0.005) # 模拟时间间隔
logger.info("这是第二条日志 (方案二)")
time.sleep(0.008)
logger.info("这是第三条日志 (方案二)")在这个方案中，%(asctime)s 会按照 '%Y-%m-%dT%H:%M:%S' 格式化（只到秒），然后 .%(msecs)03d 会追加当前日志记录的毫秒数。这样既实现了自定义的日期时间格式，又确保了毫秒的动态显示。
注意事项与最佳实践
- 避免在 logging 配置字典的 datefmt 值中直接调用 datetime.now() 或其他时间函数，除非你确实希望其值在配置加载时被固定。对于需要动态更新的值，应使用 Formatter 提供的占位符。
- 理解 %(asctime)s 和 %(msecs)03d 的区别和作用。%(asctime)s 是一个复合字段，其格式受 datefmt 影响；而 %(msecs)03d 是一个独立的、始终表示毫秒的字段。
- 对于文件名的动态生成，例如 filename': '/tmp/logtest_'+datetime.now().strftime("%Y%m%d-%H%M%S")+'.log'，使用 datetime.now().strftime(...) 是完全正确的。因为文件名只需要在应用启动时确定一次，并且它不会影响日志记录内部的时间戳格式。
通过采用上述解决方案，可以有效避免Python logging 中 datefmt 配置不当导致的时间戳固定问题，确保日志的准确性和实用性。
