Получение журналов дважды в лямбда-функции AWS

Question

Я пытаюсь создать централизованный модуль для настройки моего средства форматирования журналов, которое будет совместно использоваться несколькими модулями Python в моей функции лямбда-выражения. В конечном итоге эта функция будет работать на AWS Greengrass на локальном локальном устройстве.

По какой-то причине, когда я добавляю свой собственный обработчик для форматирования сообщений, журналы выводятся дважды - один раз на правильном уровне журнала и второй раз на неправильном уровне.

Если я использую стандартный Python Logger без настройки каких-либо обработчиков, он работает нормально, например

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()

Когда лямбда-функция теперь запущена, я получаю отладочное сообщение дважды в журналах наблюдения за облаком следующим образом:

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. Очистка обработчиков лямбда-журналов по умолчанию: использование журналирования python с AWS Lambda

3. Создание глобального регистратора: Python: модуль журналирования - глобально

Answer 1

AWS Lambda также настраивает обработчик для корневого регистратора и всего, что записано в stdout захватывается и регистрируется как уровень INFO, Таким образом, ваше сообщение регистрируется дважды:

• С помощью обработчика AWS Lambda на корневом регистраторе (поскольку сообщения журнала распространяются от вложенных дочерних регистраторов к корню), и этот регистратор имеет собственный настроенный формат.
• Регистратором AWS Lambda stdout-to-INFO.

Вот почему все сообщения начинаются с (asctime) [(levelname)]-(module):(lineno), Информация; root logger сконфигурирован для вывода сообщений в этом формате, а информация, записанная в stdout, является просто еще одной %(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, а не locatime), задает пользовательский обработчик, который гарантирует, что сообщения отправляются в инфраструктуру 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 строка), что, вероятно, означает, что формат был проанализирован и представлен вам в представлении данных веб-приложения.

Answer 2

Я не уверен, является ли это причиной вашей проблемы, но по умолчанию регистраторы 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 logger каким-то образом заканчивается подключением некоторых обработчиков, что приводит к дублированию сообщений. Чтобы избежать этого, вы можете установить propagate в вашем логгере False или только прикрепите ваши обработчики к корневому логгеру.