本文深入探讨了python `logging`模块中`datefmt`参数的常见误用，特别是当其被错误地设置为`datetime.now()`的返回值时，导致所有日志条目显示相同的时间戳。文章详细解释了`%(asctime)s`和`%(msecs)03d`的正确用法，并提供了两种解决方案：一是移除`datefmt`以利用默认的毫秒级时间戳，二是结合`%(msecs)03d`与格式化字符串来精确控制时间戳格式，确保日志时间戳的动态性和准确性。
1. Python logging模块的时间戳机制
Python的logging模块提供了强大的日志功能，其中时间戳是日志信息中不可或缺的一部分。在日志格式字符串中，%(asctime)s是一个特殊的占位符，它会被日志事件发生的时间替换。logging模块允许通过datefmt参数来自定义%(asctime)s的输出格式。
- %(asctime)s: 表示日志事件的发生时间。
- datefmt: 一个字符串，用于指定%(asctime)s的格式。它遵循time.strftime()的格式代码。
- %(msecs)03d: 这是一个独立的占位符，用于表示日志事件发生时的毫秒部分（三位数字，不足补零）。它与%(asctime)s是分开处理的。
当datefmt未指定时，%(asctime)s通常会默认以YYYY-MM-DD HH:MM:SS,mmm（包含毫秒）的格式输出。然而，一旦datefmt被指定，%(asctime)s的格式将完全由datefmt控制，并且不再自动包含毫秒。若此时仍需显示毫秒，则必须显式地在format字符串中添加%(msecs)03d。
2. 问题分析：datefmt被错误设置为datetime.now()的返回值
一个常见的错误是将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"),
# 错误示例：datetime.now()在这里被立即执行
'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', # 使用verbose formatter
'stream': sys.stdout,
},
},
loggers={
'my_app_logger': {
'handlers': ['console'],
'level': logging.DEBUG,
'propagate': False
},
}
)
dictConfig(logging_config)
logger = logging.getLogger('my_app_logger')
# 模拟日志输出
logger.info("这是一条日志消息。")
import time
time.sleep(0.005) # 短暂延迟
logger.info("这是另一条日志消息。")
time.sleep(0.005)
logger.info("这是第三条日志消息。")预期输出（错误示例）：
立即学习“Python免费学习笔记（深入）”；
2024-01-04T03:18:18.123 INFO [my_app_logger:37] 这是一条日志消息。 2024-01-04T03:18:18.123 INFO [my_app_logger:40] 这是另一条日志消息。 2024-01-04T03:18:18.123 INFO [my_app_logger:42] 这是第三条日志消息。
问题根源： 当logging_config字典被创建时，datetime.now().isoformat(...)会被立即执行一次，并将其返回值（一个固定的时间字符串，例如"2024-01-04T03:18:18.123"）赋值给datefmt。这意味着datefmt不再是一个格式化指令，而是一个静态的时间字符串。logging模块在处理%(asctime)s时，会尝试使用这个静态字符串作为格式来格式化当前时间，但这显然不是其设计用途。最终的结果是，%(asctime)s被这个固定的字符串替换，导致所有日志的时间戳都相同，并且无法反映真实的日志发生时间。
3. 解决方案：正确配置时间戳以包含毫秒
要解决此问题，我们需要理解datefmt应该是一个格式字符串，而不是一个具体的时间值。同时，如果需要毫秒精度，必须在format字符串中显式使用%(msecs)03d。
3.1 方案一：移除datefmt，使用默认毫秒格式
如果对时间戳的格式要求不高，仅需包含毫秒，最简单的方法是完全移除datefmt参数。logging模块的默认行为通常会在%(asctime)s中包含毫秒。
import logging
from logging.config import dictConfig
import sys
import time
logging_config_option1 = dict(
version=1,
formatters={
'verbose': {
'format': ("%(asctime)s %(levelname)s "
"[%(name)s:%(lineno)s] %(message)s"),
# 移除 datefmt，使用默认的毫秒格式
# 'datefmt': None # 也可以显式设置为 None
},
},
handlers={
'console': {
'class': 'logging.StreamHandler',
'level': 'DEBUG',
'formatter': 'verbose',
'stream': sys.stdout,
},
},
loggers={
'my_app_logger': {
'handlers': ['console'],
'level': logging.DEBUG,
'propagate': False
},
}
)
dictConfig(logging_config_option1)
logger_option1 = logging.getLogger('my_app_logger')
print("--- 方案一输出 (移除datefmt) ---")
logger_option1.info("这是一条日志消息 (Option 1)。")
time.sleep(0.005)
logger_option1.info("这是另一条日志消息 (Option 1)。")
time.sleep(0.005)
logger_option1.info("这是第三条日志消息 (Option 1)。")预期输出（方案一）：
--- 方案一输出 (移除datefmt) --- 2024-01-04 03:30:11,595 INFO [my_app_logger:37] 这是一条日志消息 (Option 1)。 2024-01-04 03:30:11,598 INFO [my_app_logger:40] 这是另一条日志消息 (Option 1)。 2024-01-04 03:30:11,603 INFO [my_app_logger:42] 这是第三条日志消息 (Option 1)。
可以看到，时间戳现在包含了毫秒，并且每次日志事件的时间戳都是动态更新的。
3.2 方案二：结合%(msecs)03d与格式化字符串
如果需要自定义%(asctime)s的日期时间部分（例如ISO 8601格式），同时又需要毫秒精度，那么正确的做法是：
- 将datefmt设置为一个格式字符串，它定义了时间戳中秒及以前的部分。
- 在format字符串中，将%(msecs)03d添加到%(asctime)s之后，以显式地包含毫秒部分。
import logging
from logging.config import dictConfig
import sys
import time
logging_config_option2 = dict(
version=1,
formatters={
'verbose': {
# 在 format 字符串中添加 %(msecs)03d
'format': ("%(asctime)s.%(msecs)03d %(levelname)s "
"[%(name)s:%(lineno)s] %(message)s"),
# datefmt 应该是一个格式字符串，定义到秒
'datefmt': '%Y-%m-%dT%H:%M:%S'
},
},
handlers={
'console': {
'class': 'logging.StreamHandler',
'level': 'DEBUG',
'formatter': 'verbose',
'stream': sys.stdout,
},
},
loggers={
'my_app_logger': {
'handlers': ['console'],
'level': logging.DEBUG,
'propagate': False
},
}
)
dictConfig(logging_config_option2)
logger_option2 = logging.getLogger('my_app_logger')
print("\n--- 方案二输出 (自定义datefmt并包含毫秒) ---")
logger_option2.info("这是一条日志消息 (Option 2)。")
time.sleep(0.005)
logger_option2.info("这是另一条日志消息 (Option 2)。")
time.sleep(0.005)
logger_option2.info("这是第三条日志消息 (Option 2)。")预期输出（方案二）：
--- 方案二输出 (自定义datefmt并包含毫秒) --- 2024-01-04T03:30:11.595 INFO [my_app_logger:37] 这是一条日志消息 (Option 2)。 2024-01-04T03:30:11.598 INFO [my_app_logger:40] 这是另一条日志消息 (Option 2)。 2024-01-04T03:30:11.603 INFO [my_app_logger:42] 这是第三条日志消息 (Option 2)。
此方案成功地实现了ISO 8601格式（到秒）并准确地包含了毫秒部分，同时确保了时间戳的动态更新。
4. 注意事项与最佳实践
- datefmt应始终是格式字符串：切勿将datetime.now()的返回值直接赋给datefmt。datefmt的目的是告诉logging模块如何格式化时间，而不是提供一个固定的时间。
- 理解%(asctime)s和%(msecs)03d的区别：%(asctime)s负责日期和时间的主体部分，其格式受datefmt控制。%(msecs)03d则专门用于显示毫秒，它独立于datefmt工作，必须在format字符串中显式声明。
- 文件处理器中的datetime.now()：在日志文件路径（例如filename: '/home/abc/efg/logs/logtest_'+datetime.now().strftime("%Y%m%d-%H%M%S")+'.log'）中使用datetime.now()是正确的，因为这只在应用程序启动时执行一次，用于生成唯一的文件名。这与datefmt的动态时间戳需求不同。
- 简化配置：如果对时间戳格式没有特殊要求，并且默认的YYYY-MM-DD HH:MM:SS,mmm格式满足需求，则完全可以省略datefmt参数，以简化配置。
总结
正确配置Python logging模块的时间戳对于日志分析和问题排查至关重要。核心在于理解datefmt参数的真正作用是一个格式化字符串，而非一个静态的时间值。通过结合%(asctime)s和%(msecs)03d，我们可以灵活地控制日志时间戳的格式和精度，确保每一条日志都拥有准确、动态的时间信息。
