Python日志时间格式与精度设置解析

怎么入门文章编程？需要学习哪些知识点？这是新手们刚接触编程时常见的问题；下面golang学习网就来给大家整理分享一些知识点，希望能够给初学者一些帮助。本篇文章就来介绍《Python日志时间格式与精度问题详解》，涉及到，有需要的可以收藏一下

本文深入探讨了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("这是第三条日志消息。")

预期输出（错误示例）：

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格式），同时又需要毫秒精度，那么正确的做法是：

1. 将datefmt设置为一个格式字符串，它定义了时间戳中秒及以前的部分。
2. 在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，我们可以灵活地控制日志时间戳的格式和精度，确保每一条日志都拥有准确、动态的时间信息。

今天带大家了解了的相关知识，希望对你有所帮助；关于文章的技术知识我们会一点点深入介绍，欢迎大家关注golang学习网公众号，一起学习编程~