在AWS Lambda函数中两次获取日志 [英] Getting logs twice in AWS lambda function

问题描述

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

I'm attempting to create a centralized module to set up my log formatter to be shared across a number of python modules within my lambda function. This function will ultimately be run on AWS Greengrass on a local on-premise device.

由于某种原因，当我添加自己的处理程序以格式化消息时，日志将输出两次-一次以正确的日志级别输出，第二次以不正确的级别输出.

For some reason, when I add in my own handler to format the messages the logs are being outputted twice - once at the correct log level and the second time at an incorrect level.

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

If I use the standard python logger without setting up any handlers it works fine e.g.

main.py:

import logging

logging.debug("test1")

cloudwatch logs:

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

我的目标是在我的代码上使用一个格式化程序，该格式化程序会将这些日志消息格式化为JSON.然后，将它们吸收到集中式日志记录数据库中.但是，当我这样做时，我会收到两次日志消息.

My objective is to have one formatter on my code which will format these log messages into JSON. They will then get ingested into a centralized logging database. However, when I do this I get the log messages twice.

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函数时，我在云监视日志中两次收到调试消息，如下所示:

When the lambda function is now run I get the debug message twice in the cloud watch logs as follows:

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行存在哪个构造函数.这可能会为正在发生的事情提供一些启示.

I cannot explain this behavior and would appreciate any thoughts on what could be causing it. I also don't know which constructor exists at line 880. This may shed some light on what is happening.

参考文献:

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

1. Setting up a global formatter: How to define a logger in python once for the whole program?

清除默认的lambda日志处理程序: 在AWS Lambda中使用python日志记录

Clearing the default lambda log handlers: Using python Logging with AWS Lambda

创建全局记录器: Python:全局日志记录模块

推荐答案

AWS Lambda还在根记录器上设置了一个处理程序，在和中捕获了写入stdout的所有内容并将其记录为级别INFO.因此，您的日志消息被捕获两次:

AWS Lambda also sets up a handler, on the root logger, and anything written to stdout is captured and logged as level INFO. Your log message is thus captured twice:

• 通过根记录器上的AWS Lambda处理程序(作为从嵌套子记录器到根的日志消息 propagate )，此记录器具有自己的格式.
• 通过AWS Lambda stdout-to-INFO记录器.

• By the AWS Lambda handler on the root logger (as log messages propagate from nested child loggers to the root), and this logger has its own format configured.
• By the AWS Lambda stdout-to-INFO logger.

这就是为什么消息都以(asctime) [(levelname)]-(module):(lineno),信息开头的原因； root logger配置为以该格式输出消息，而写入stdout的信息只是该输出中的另一个%(message)部分.

This is why the messages all start with (asctime) [(levelname)]-(module):(lineno), information; the root logger is configured to output messages with that format and the information written to stdout is just another %(message) part in that output.

在您处于AWS环境(或)时，请勿设置处理程序，禁用将输出传播到根处理程序，并将所有消息记录为INFO消息， AWS；在后一种情况下，您自己的格式化程序可以在输出中包含levelname级别信息.

Just don't set a handler when you are in the AWS environment, or, disable propagation of the output to the root handler and live with all your messages being recorded as INFO messages by AWS; in the latter case your own formatter could include the levelname level information in the output.

您可以使用logger.propagate = False禁用日志传播，这时您的消息将仅传递给您的处理程序，也不会传递给根处理程序.

You can disable log propagation with logger.propagate = False, at which point your message is only going to be passed to your handler, not to to the root handler as well.

另一种选择是仅依靠AWS Root记录器配置.根据这篇出色的逆向工程博客文章，根记录器配置为:

Another option is to just rely on the AWS root logger configuration. According to this excellent reverse engineering blog post the root logger is configured with:

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)

这将logging.Formatter上的time.localtime转换器替换为time.gmtime(因此时间戳使用UTC而不是locatime)，设置了一个自定义处理程序，以确保消息进入Lambda基础结构，配置格式并添加过滤器仅向记录添加aws_request_id属性的对象(因此上述格式化程序可以包括该对象)，但实际上不过滤任何内容.

This replaces the time.localtime converter on logging.Formatter with time.gmtime (so timestamps use UTC rather than locatime), sets a custom handler that makes sure messages go to the Lambda infrastructure, configures a format, and adds a filter object that only adds aws_request_id attribute to records (so the above formatter can include it) but doesn't actually filter anything.

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

You could alter the formatter on that handler by updating the attributes on the handler.formatter object:

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基础架构很可能会依靠所使用的特定格式.您在问题中显示的输出不包含日期部分(formatter.datefmt字符串的%Y-%m-%dT部分)，这可能意味着该格式已被解析，并在Web应用程序视图中呈现给您.数据.

and then just drop your own logger handler entirely. You do want to be careful with this; AWS Lambda infrastructure could well be counting on a specific format being used. The output you show in your question doesn't include the date component (the %Y-%m-%dT part of the formatter.datefmt string) which probably means that the format has been parsed out and is being presented to you in a web application view of the data.

这篇关于在AWS Lambda函数中两次获取日志的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！