Как мы внедряли сквозное логирование в монолит

Всем привет, давайте представим ситуацию, у вас есть зоопарк из сервисов и сторонних интеграцией, и вот как-то раз, ваша складская система написанная на 1С присылает к вам на ручку запрос с информацией по товару и дальше все начинает идти не по плану, и ожидаемое действие не произошло, ваш сервис что-то сделал, но вот что именно вы не знаете под валом таких же запросов, а отловить нужный запрос никак не получается. Если ситуация знакома, то решение вам отзовется в сердечке. Мы столкнулись с таким кейсом на проекте заказчика. Чтобы отдебажить весь путь события, пришлось потратить немало времени на поиск всех вызываемых зависимостей и определить момент, в котором всё пошло не так. Повторять такой сценарий не хотелось, поэтому мы решили повысить наблюдаемость за сервисами заказчика с помощью сквозного логирования. Повторение подобного кейса мы не захотели пережить и решили повысить наблюдаемость за нашими сервисами с помощью сквозного логирования.

Теперь познакомимся, меня зовут Микенин Денис, я разработчик из команды CORE в компании GRI, наша команда занимается внедрением глобальных технических фич и решением проблем на уровне всего кода всех проектов, с которыми работает. В этой статье хочу поделиться опытом и сложностями, с которыми мы столкнулись при внедрении вроде не сложной вещи, как сквозное логирование. Я не претендую на лавры великого знатока, поэтому внедрение такой фичи в нашу не простую архитектуру из сервисов было интересным вызовом для меня.

На данный момент основная кодовая база проекта — Django-монолит. Есть сервисы, которые уже вынесены отдельно, но большая часть всё ещё находится внутри монолита. У заказчика после кейса выше появилась потребность повысить observability, чтобы лучше понимать, что происходит с кодом и жизненным циклом события, пришедшего к нам на ручку, а также в celery тасках, вызываемых в результате запросов на ручки и в просто периодических тасках, не зависящих от запросов пользователей или других систем. Потому что все понимают, что когда происходит аномалия в логике, где не ожидаешь, то нужно лучше понимать, что к этому привело и отследить весь путь от запроса до ошибки. Да, логов достаточно, но как их связать в один логический контекст, чтобы выстроить «картину» происходящего, вот это проблема и требует лишних когнитивных напряжений мозга, и траты драгоценного времени при аварии. Вот как раз для выстраивания такой «картины» мы и занялись внедрением фичи.

Фича по идее планировалась быть простой для внедрения, особенно в Django, но в проекте есть отдельные микросервисы на Django и Go, есть Kafka, сторонние интеграции по REST и SOAP, наши системы observability и Sentry, Celery, и во всех них надо учесть, передачу этого айди, чтобы можно было легко дебажить и видеть, в какой момент событие все поломало и особенно важно в сторонних интеграциях, чтобы можно было отследить момент передачи события в другую систему и в случае аварий партнеры могли найти быстро нужный кейс по айди. Так что простая задача стала обрастать ворохом зависимостей для тестирования и точек внедрения, и конечно в таком случае всегда может пойти что-то не так.

Сквозное логирование у нас, это добавление уникального айди, который генерируется на каждый запрос к нашему API и добавляется в каждый вызываемый лог в рамках работы одной логики запроса к API или вызове Celery таски. Зная этот айди, мы можем в Kibana найти логи с его вхождением, как на примере (здесь и далее я заблюрил содержимое с информацией наших окружений).

Итак начнем, до внедрения в проекте заказчика использовался стандартный логгер из питонячего модуля logging. Была задача помимо сквозного логирования также оптимизировать наш механизм сбора логов, сделать его менее ресурсоемким и быстрым для нашего ELK стека. Для этого мы начали осуществлять переход на structlog. Первым делом, установили либу в наш проект - structlog. Затем начали описывать шаги формирования выходного лога, итоговый вид ниже:

structlog.configure(
    processors=[
        structlog.stdlib.filter_by_level,
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.processors.TimeStamper(),
        structlog.processors.JSONRenderer(
            sort_keys=True
        ),
    ],
    context_class=dict,
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

Так мы настроили логирование в проекте заказчика и получили следующий результат:

{
    "event": "example_log",
    "level": "info",
    "logger": "struct.project",
    "timestamp": 1788345593.0933151
}

В целом все хорошо, ничего не предвещало беды, и вроде можно приступать к добавлению сквозного логирования, но во время тестирования на стенде и проверке ошибок в Sentry, получили сломанное отображение ошибок, которые вызывает наш фасад логирования. Русский текст отображался в юникоде, сломалась группировка issue и некорректно формировался title и message. В title писался весь event целиком и получался сломанный json с экранированием юникода, вместо конкретного имени события. 

Теперь сделаем шаг назад и расскажу про фасад логирования. В отдельном файле, в котором мы определили методы логирования, которые можно вызывать, и разработчик может использовать единую точку входа, а уже внутри методов мы можем накручивать всю необходимую логику и обогащать данные, ниже урезанный пример нескольких функций из файла logs.py

...
_default_logger = wrap_logger(logging.getLogger('struct.project'))

def log_err(message: str, /, *) -> None:
    """Метод логирования ERROR уровня.

    :param message: лог
    """
     …
    _default_logger.error(message)


def log_info(message: str, /, *) -> None:
    """Метод логирования INFO уровня.

    :param message: лог
    """
     …
    _default_logger.info(message)
...

После анализа понимаем, что логи формируются корректно и с этой стороны проблем не стоит ожидать, тогда посмотрели в сторону формирования события для Sentry и вот тут обнаружили камень преткновения. У нас переопределено поведение _before_send, функции, которая отвечает за формирование данных отправляемых в Sentry, поскольку в проекте используются свои методы и мы ранее для них определяли поведение, а для обычных рейзов оставляли формирование в Sentry по-умолчанию, то в этом месте и случилось расхождение по всем проблемам выше. 

Проблема с группировкой решилась переопределением fingerprint (уникальный текст, по которому будет группировка событий в Sentry). Да понимаем, что это увеличивает размер отправляемых событий, но мы постарались минимизировать эти издержки, а сломанный json и юникод решили точечным декодированием и десериализацией.

if is_default_logger and 'exception' not in event:
    event['fingerprint'] = [title]

После решение этой проблемы у нас следующее состояние: есть новый тип логера, есть пофикшенные ошибки связанные с Sentry, нет сквозного айди. Теперь приступаем к добавлению этой части функционала. Для этого в конфигурацию нашего structlog я добавлю настройку structlog.contextvars.merge_contextvars, которая добавляет поля к контексту потока и эти поля появятся в каждом логе.

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,  # тут добавили
        structlog.stdlib.filter_by_level,
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.processors.TimeStamper(),
        structlog.processors.JSONRenderer(
            sort_keys=True,
            ensure_ascii=IS_PRODUCTION,
            serializer=functools.partial(ujson.dumps, reject_bytes=False),
        ),
    ],
    context_class=dict,
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

Теперь нужно добавить сам айди, для этого нам потребуется middleware который будет на каждый запрос на ручку добавлять его, нам остается только провалидировать и присвоить его в контекстные переменные потока с помощью строки:

structlog.contextvars.bind_contextvars(request_id=unique_id)

В результате получили следующий лог:

{
    "event": "example_log",
    "level": "info",
    "logger": "struct.project",
    "timestamp": 1788345593.0933151,
    "request_id": "d808a04a-eb83-4125-92fe-f1c0ef6c1bed"
}

Ура, теперь мы можем отследить весь жизненный цикл события от прихода на ручку запроса до респонса, но кажется, что чего-то не хватает, а именно понимания что происходит дальше в celery тасках. Для Celery тасок в проекте используется также свой фасад и теперь в нем нам предстоит прописать добавление айди в логи таски. Для начала сформируем заголовки для таски в emit методе (также фасад и отвечает за создание celery-таски).

...
celery_task_params['headers'] = build_headers_with_request_id(headers) 
...

Но это пока не все, мы только сформировали заголовки с мета-данными, которые хотим прокинуть в celery таску. Теперь нам необходимо применить эти данные в тасках, чтобы наш айди появился и там, и мы могли проследить весь путь. Для этого напишем сигнал, который будет срабатывать перед запуском тасок в настройках работы celery.

@task_prerun.connect
def add_request_id_in_task(sender=None, task_id=None, task=None, args=None, kwargs=None, **extra):
    """Метод который берет request_id из контекста созданных тасок или генерирует уникальный,
    если запущена периодическая таска без контекста.
    """
    request_id = None
    ...
    #ранее достаем айди в переменную
    structlog.contextvars.bind_contextvars(request_id=unique_id))	
    ...

В результате при вызове нашего emit мы будем добавлять айди из его контекста, а затем наш сигнал вызываемый у таски будет забирать этот айди и присваивать его уже в свой поток, и если в рамках одной таски мы вызовем другую, то благодаря нашей абстракции этот айди прокинется и в новую таску, таким образом сможем отследить по логам весь жизненный путь действий, который инициализировал пользователь. Затем мы добавили необходимые настройки и конфиги в остальные Django-сервисы проекта заказчика и получили общее решение.

Теперь что касается REST и SOAP интеграций, для SOAP запросов мы используем либу zeep и написали метод-плагин для нее. В нем перед отправкой будет браться актуальный айди и подставляться в отправляемый документ с определенным заголовком. Внедрили, протестировали, все довольны. 

А вот для REST подхода наступили сначала на грабли, попытались переопределить поведение либы requests с ее методами (get, post, requests  и т.д.) в момент старта приложений, чтобы при их вызове собирался корректный headers и обновлялся с нашим айди, но практика применения показала, что при долгом использовании такое применение вызывает зацикливание, которое выедает ОП и в python начинают сыпаться ошибки с HTTPSConnectionPool. В итоге вернулись к классике, и дополнили существующие классы для запросов формированием айди и сделали метод для его формирования, где не требуются такие классы и разрабы могут его сами вызывать.

Вышеперечисленные действия позволили нам лучше контролировать происходящее в сервисах проекта, и мы уже почувствовали облегчение при разборе проблемных ситуаций. Но это, конечно, не финал, а только стартовая точка. В архитектуре проекта ещё есть куда расти и что улучшать с точки зрения observability.

Если подвести итог, я постарался рассказать, как мы внедряли сквозное логирование в проекте заказчика, с какими сложностями столкнулись и почему в итоге пришли именно к такому решению. Из неочевидного — обязательно проверяйте Sentry после изменений в логировании. Дальше у нас ещё много планов по улучшению наблюдаемости, и о них расскажу в будущем.

Спасибо вам за внимание и до новых встреч в следующих статьях!