15

我正在尝试创建一个集中模块来设置我的日志格式化程序，以便在我的 lambda 函数中的多个 python 模块之间共享。此功能最终将在本地本地设备上的 AWS Greengrass 上运行。

出于某种原因，当我添加自己的处理程序来格式化消息时，日志被输出了两次——一次在正确的日志级别，第二次在不正确的级别。

如果我使用标准的 python 记录器而不设置任何处理程序，它可以正常工作，例如

main.py：

import logging

logging.debug("test1")

cloudwatch logs：

12:28:42 [DEBUG]-main.py:38,test1

我的目标是在我的代码上有一个格式化程序，它将这些日志消息格式化为 JSON。然后，它们将被摄取到集中式日志数据库中。但是，当我这样做时，我会收到两次日志消息。

loghelper.py：

def setup_logging(name):

    formatter = logging.Formatter("%(name)s, %(asctime)s, %(message)s")

    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(formatter)

    logger = logging.getLogger(name)

    if logger.handlers:
        for handler in logger.handlers:
            logger.removeHandler(handler)

    logger.setLevel(logging.DEBUG)
    logger.addHandler(handler)
    return logger

main.py：

import logging

logger = loghelper.setup_logging('main.test_function')

def test_function():
    logger.debug("test function log statement")

test_function()

现在运行 lambda 函数时，我在云监视日志中收到两次调试消息，如下所示：

cloudwatch logs：

12:22:53 [DEBUG]-main.py:5, test function log statement
12:22:53 [INFO]-__init__.py:880,main.test_function,2018-06-18 12:22:53,099, test function log statement

请注意：

  • 第一个条目的级别正确，但格式错误。
  • 第二个条目报告了错误的级别、错误的模块但格式正确。

我无法解释这种行为，并希望对可能导致它的原因有任何想法。我也不知道第 880 行存在哪个构造函数。这可能会对正在发生的事情有所了解。

参考：

  1. 设置全局格式化程序： 如何在 python 中为整个程序定义一个记录器？

  2. 清除默认 lambda 日志处理程序： 将 python 日志记录与 AWS Lambda 一起使用

  3. 创建全局记录器： Python：记录模块 - 全局

4

2 回答 2

30

AWS Lambda 还在根记录器上设置了一个处理程序，写入的任何内容都会stdout被捕获并记录为 level INFO。因此，您的日志消息被捕获两次：

  • 由根记录器上的 AWS Lambda 处理程序（因为日志消息从嵌套的子记录器传播到根），并且此记录器配置了自己的格式。
  • 通过 AWS Lambda 标准输出到信息记录器。

这就是为什么消息都以(asctime) [(levelname)]-(module):(lineno),信息开头的原因；根记录器配置为输出具有该格式的消息，写入标准输出的信息只是%(message)该输出的另一部分。

只是不要在 AWS 环境中设置处理程序，或者禁用将输出传播到根处理程序并让所有消息都INFO被 AWS 记录为消息；在后一种情况下，您自己的格式化程序可以levelname在输出中包含级别信息。

您可以使用 禁用日志传播logger.propagate = False，此时您的消息只会传递给您的处理程序，而不是根处理程序。

另一种选择是仅依赖 AWS 根记录器配置。根据这篇优秀的逆向工程博客文章，根记录器配置为：

logging.Formatter.converter = time.gmtime
logger = logging.getLogger()
logger_handler = LambdaLoggerHandler()
logger_handler.setFormatter(logging.Formatter(
    '[%(levelname)s]\t%(asctime)s.%(msecs)dZ\t%(aws_request_id)s\t%(message)s\n',
    '%Y-%m-%dT%H:%M:%S'
))
logger_handler.addFilter(LambdaLoggerFilter())
logger.addHandler(logger_handler)

这将time.localtime转换器logging.Formatter替换为time.gmtime（因此时间戳使用 UTC 而不是本地时间），设置自定义处理程序以确保消息进入 Lambda 基础设施，配置格式，并添加仅aws_request_id向记录添加属性的过滤器对象（因此上述格式化程序可以包含它）但实际上并没有过滤任何东西。

您可以通过更新对象的属性来更改该处理程序上的格式化程序handler.formatter：

for handler in logging.getLogger().handlers:
    formatter = handler.formatter
    if formatter is not None and 'aws_request_id' in formatter._fmt:
        # this is the AWS Lambda formatter
        # formatter.datefmt => '%Y-%m-%dT%H:%M:%S'
        # formatter._style._fmt => 
        #    '[%(levelname)s]\t%(asctime)s.%(msecs)dZ'
        #    '\t%(aws_request_id)s\t%(message)s\n'

然后完全删除您自己的记录器处理程序。你确实要小心这个；AWS Lambda 基础设施很可能依赖于使用的特定格式。您在问题中显示的输出不包括日期组件（字符串的%Y-%m-%dT一部分formatter.datefmt），这可能意味着格式已被解析出来并在数据的 Web 应用程序视图中呈现给您。

于 2018-06-18T13:35:22.913 回答
1

我不确定这是否是您的问题的原因，但默认情况下，Python 的记录器会将其消息传播到记录层次结构。您可能知道，Python 记录器以树的形式组织，root记录器位于顶部，其他记录器位于其下方。在记录器名称中，点 ( .) 引入了新的层次结构级别。所以如果你这样做

logger = logging.getLogger('some_module.some_function`)

那么你实际上有 3 个记录器：

The root logger (`logging.getLogger()`)
    A logger at module level (`logging.getLogger('some_module'))
        A logger at function level (`logging.getLogger('some_module.some_function'))

如果您在记录器上发出一条日志消息并且它没有根据记录器的最低级别被丢弃，那么该消息将传递给记录器的处理程序及其父记录器。有关详细信息，请参阅此流程图。

如果该父记录器（或层次结构中更高的任何记录器）也有处理程序，那么它们也会被调用。

我怀疑在您的情况下，根记录器或main记录器以某种方式最终附加了一些处理程序，这导致了重复的消息。为避免这种情况，您可以propagate在记录器中设置False或仅将处理程序附加到根记录器。

于 2018-06-18T13:30:05.387 回答