本文深入探讨了python `logging`模块中，当`datefmt`参数被错误地设置为一个预计算的固定时间戳字符串时，导致所有日志条目时间戳相同的问题。教程将解释`%(asctime)s`和`datefmt`的正确用法，并提供结合`%(msecs)03d`实现动态、高精度时间戳的解决方案，确保日志输出的时间戳能够实时更新并包含毫秒信息。
理解Python logging模块中的时间戳格式化
Python的logging模块是一个强大且灵活的日志记录框架。在配置日志格式时，我们经常会用到%(asctime)s占位符来显示日志记录的时间。%(asctime)s默认会以YYYY-MM-DD HH:MM:SS,mmm的格式输出时间，其中,mmm表示毫秒。然而，通过datefmt参数，我们可以自定义%(asctime)s的输出格式。
常见问题：datefmt导致时间戳固定
在配置logging时，一个常见的误区是将datefmt参数设置为一个通过datetime.now().isoformat()等方法预先计算好的时间戳字符串，而不是一个时间格式化字符串。例如：
import logging
from logging.config import dictConfig
from datetime import datetime
import sys
logging_config = dict(
version=1,
formatters={
'verbose': {
'format': ("%(asctime)s %(levelname)s "
"[%(name)s:%(lineno)s] %(message)s"),
# 错误示例：datefmt被设置为一个固定时间戳字符串
'datefmt': datetime.now().isoformat(sep='T', timespec='milliseconds')
},
'simple': {
'format': '%(asctime)s %(levelname)-8s %(message)s',
'datefmt': datetime.now().isoformat(sep='T', timespec='milliseconds')
},
},
handlers={
'console': {
'class': 'logging.StreamHandler',
'level': 'DEBUG',
'formatter': 'verbose',
'stream': sys.stdout,
},
},
loggers={
'logger': {
'handlers': ['console'],
'level': logging.DEBUG,
'propagate': False
},
}
)
# 应用配置
dictConfig(logging_config)
logger = logging.getLogger('logger')
# 记录多条日志
logger.info("第一条日志")
logger.info("第二条日志")
logger.info("第三条日志")
当以上代码运行时，我们会发现所有日志条目都显示相同的%(asctime)s时间戳，且不包含毫秒信息，例如：
2024-01-04 03:18:18 INFO [logger:38] 第一条日志 2024-01-04 03:18:18 INFO [logger:39] 第二条日志 2024-01-04 03:18:18 INFO [logger:40] 第三条日志
这是因为datefmt参数在日志配置字典被创建时，datetime.now().isoformat()就被立即评估并生成了一个固定的时间戳字符串（例如"2024-01-04T03:18:18.123"）。此后，logging模块会将这个固定的字符串作为%(asctime)s的“格式”，而不是一个动态的时间格式化模式。结果就是，无论何时记录日志，%(asctime)s都将输出这个在配置加载时捕获的固定时间。
解决方案：正确使用format和datefmt
要实现动态且包含毫秒的时间戳，我们需要理解%(asctime)s和datefmt的真正作用：
- %(asctime)s：这是一个特殊的占位符，它会在每次记录日志时动态捕获当前时间。
- datefmt：它是一个字符串，用于指定如何格式化%(asctime)s所捕获的时间。它应该是一个标准的strftime()格式字符串，而不是一个实际的时间戳值。
- %(msecs)03d：这是一个独立的占位符，用于显示当前时间的毫秒部分，并用零填充到三位数。
正确的做法是，在format字符串中明确包含%(msecs)03d来显示毫秒，并将datefmt设置为一个不包含毫秒的标准日期时间格式字符串。
以下是修正后的logging_config示例：
import logging
from logging.config import dictConfig
from datetime import datetime
import sys
logging_config = dict(
version=1,
formatters={
'verbose': {
# 修正1: 在format中添加 %(msecs)03d 来显示毫秒
'format': ("%(asctime)s.%(msecs)03d %(levelname)s "
"[%(name)s:%(lineno)s] %(message)s"),
# 修正2: datefmt 应为格式字符串，不包含毫秒，因为毫秒已由 %(msecs)03d 处理
'datefmt': '%Y-%m-%dT%H:%M:%S'
},
'simple': {
'format': '%(asctime)s.%(msecs)03d %(levelname)-8s %(message)s',
'datefmt': '%Y-%m-%dT%H:%M:%S'
},
},
handlers={
# 示例中为了简化，仅保留console handler
'console': {
'class': 'logging.StreamHandler',
'level': 'DEBUG',
'formatter': 'verbose',
'stream': sys.stdout,
},
},
loggers={
'logger': {
'handlers': ['console'],
'level': logging.DEBUG,
'propagate': False
},
}
)
# 应用配置
dictConfig(logging_config)
logger = logging.getLogger('logger')
# 记录多条日志
logger.info("第一条日志")
logger.info("第二条日志")
logger.info("第三条日志")
通过上述修改，日志输出将显示动态且包含毫秒的时间戳：
2024-01-04T03:30:11.595 INFO [logger:38] 第一条日志 2024-01-04T03:30:11.598 INFO [logger:39] 第二条日志 2024-01-04T03:30:11.603 INFO [logger:40] 第三条日志
这里的关键在于：
- datefmt: '%Y-%m-%dT%H:%M:%S' 告诉%(asctime)s将其捕获的时间格式化为年-月-日T时:分:秒的形式。
- %(msecs)03d 在format字符串中被独立地解析和替换为当前的毫秒数。 这样，%(asctime)s负责提供实时的时间（不含毫秒），datefmt负责格式化这个时间，而%(msecs)03d则负责提供实时的毫秒部分，三者结合实现了我们期望的动态高精度时间戳。
注意事项
- datefmt的默认行为：如果datefmt未指定，%(asctime)s会使用默认的YYYY-MM-DD HH:MM:SS,mmm格式。在这种情况下，通常不需要额外添加%(msecs)03d，除非你想自定义日期时间部分的格式。
- datetime.now()的执行时机：任何在logging_config字典定义时调用的函数（如datetime.now()）都会在字典创建时立即执行一次，其结果会成为字典的一部分。因此，datefmt必须是一个格式字符串，而不是一个函数调用的结果。
- 文件处理器命名中的时间戳：如果需要在日志文件名中包含动态时间戳，如原问题中的filename: '/home/abc/efg/logs/logtest_'+datetime.now().strftime("%Y%m%d-%H%M%S")+'.log'，这种用法是正确的。因为文件名只需要在文件创建时确定一次，而不是在每次日志记录时都动态更新。
总结
在Python logging模块中，实现动态且包含毫秒的时间戳，核心在于正确区分format字符串中占位符的作用以及datefmt参数的预期值。datefmt应始终是一个strftime()兼容的格式字符串，用于指导%(asctime)s如何格式化其捕获的时间。要包含毫秒，最可靠的方法是在format字符串中显式使用%(msecs)03d占位符，并相应地调整datefmt以避免重复或冲突的格式化。遵循这些原则，可以确保日志系统提供准确、实时的事件时间记录。
Python免费学习笔记（深入）：立即使用
在学习笔记中，你将探索 Python 的核心概念和高级技巧！
