Comments 23
А если имеются планы потом собирать этот лог в elastic желательно сразу называть поля в журнале согласно ECS (https://www.elastic.co/guide/en/ecs/current/ecs-field-reference.html).
Добрый день! На совете разработчиков из разных команд была большая война за нейминг полей и они согласовывались с болью. Поэтому ECS формат был неудобен. Но спасибо Вам, пусть этот комментарий будет советом многим: кастомизировать не обязательно, если в этом нет необходимости и можно прибегнуть к стандартам, которые уже придумали разные люди.
Больная тема. Спасибо что поделились.
Насколько сложно расширить вывод?
Например, критические ошибки мы сбрасываем в закрытый телеграм канал.
Если подключать ваш логгер, хорошо быть иметь возможность расширения вывода.
Я рад, что статья Вам помогла. Отвечу про расширение вывода. Расширение вывода делается очень просто, я описал это в месте, где конфигурирование handler, у которого есть поле func. Вот, эта функция как реализует вывод журнала в нужное место. На примере у меня указан обычный print, но в Вашем случае это может быть отправка в телеграм-канал.
Спасибо за Вашу обратную связь.
Таки нет, потому что стандартный logging в Python - синхронный. Асинхронность библиотеки достигается очередями через Queue, запуском в asyncio результата по очереди. То есть, если функцию логгирования сделать асинхронной - упадет ошибка о том, что мы вызываем асинхронное в синхронном коде логгера в очереди. Опять же: моя цель была не качать без всякой нужды асинхронные библиотеки, которые есть в pypi, ибо они все имеют свою экосистему и не используют стандартный logging, там запись определения бы была такая: logger = libname_logging(). А вызов через await logger.info(“message”). Не все функции в проекте могут быть асинхронными и это бы привело к неоднородности логеров в проекте. И второе: было бы несколько точек конфигурирования логеров, а мы этого делать не хотим, когда у питона из коробки свой собственный и даже лучший способ это сделать.
Познавательно, спасибо! Заливайте на pypi, с удовольствием попробую.
У вашего решения есть заметные недостатки:
Ваша миделвара полностью вычитывает тело запроса ещё до того как основной код примет решение о том нужно ли ему вообще это тело. Например приложение может вообще прервать обработку запроса (и не вычитывать его тело) из-за того, что он не прошёл проверку авторизации.
А если клиент отправил 100500 МБ данных в теле? У вас это всё загрузится в память и пользователь вашей библиотеки даже не может на это повлиять. Ну и кроме того это ломает обработку заголовка запроса Expect: 100-continueАналогичная проблема с телом ответа - вы без всяких проверок вычитываете его в память полностью. А там может быть очень много данных. Не просто так тело ответа реализовано как итератор - это позволяет реализовать возврат большого тела без необходимости его полной загрузки в память. Ваша миделвара ломает это стандартное поведение.
Когда я делал подобное логирование тела запроса и ответа, то я во первых проверял Content-Type, что бы он имел какое-то определённое значение. Например application/json, т.к. в контексте приложения нет смысла логировать что-то другое. И так же проверял Content-Length запроса и ответа, что бы он не превышал определённого лимита (а ещё его вообще может не быть, если тело передаётся чанками). Ну и тело запроса я достаю уже после того как запрос был обработан приложением.
Да, Вы верно подметили этот недочет. На самом деле, тут оставляется выбор за разработчиком уже достраивать новые ограничения на контент, на формат данных с помощью pydantic, на то, как будет мидлварь сплитить и декомпозировать отдельные части запроса и ответа. Совет с content-type - очень крутой, возьму на заметку. Спасибо за Ваш комментарий!
Было бы интересно посмотреть на результаты нагрузочного тестирования в сравнении с библиотекой loguru. Рассматривали ее как альтернативу?
Давно не писал на питоне, тем более с async/await поэтому возможно мой вопрос не в тему. Здесь имеется ввиду что асинхронный код не блокирует тред /процесс питона (GIL и все такое) или же логгер вообще будет сам по себе где то буферизировать логи и пушить их в какой-то стрим?
Я клоню к тому, что не случится ли ситуация когда нагрузка очень большая и код отрабатывает быстрее чем логи пушатся наружу, и какой-нибудь внутренний буфер/очередь забьется и начнет делать проблемы?
Никак нет. Как я уже пометил в этом комментарии https://habr.com/ru/post/575454/#comment_23431790 - асинхронная библиотека логирования реализована на принципе очереди Queue стандартного logging в питоне. То есть, есть шанс, что можно набить этот буфер очень быстро, но при 860 rps полет был нормальный. Да, есть эффект того, что код отрабатывает быстрее, а логи уже потом за ним поспевают, это нормально для асинхронного мира в других языках программирования, например в Котлине такой же эффект с корутинами.
Это важно. При тех же RPS при большом пейлоаде или сложной структурой данных, время сериализации может увеличиться.
А что если канал куда логи отправляются тормозит? Память то не резиновая. Обычно в таких случаях explicitly указывают размер очереди и поведение при заполнении. Например что логи будут дропаться если очередь слишком большая.
А то можно сильно удивиться когда что-то начнет падать по OOM или что канал будет забиваться... или CPU подскочить на сериализации в 3 часа ночи.
И кстати, такой проблемы нет?
user = { name: "alex" }
logger("my name", { user, }; ->> ушло в очередь
user.name = "ahmed"
Что уйдет в лог?
Решение проблемы со слишком большим объёмом данных из комментаторов предложена очень корректно: ограничение по чанкам, ограничение по content lenght. Также я планирую доработать мидлварь для бан-листа для формирования бинарников(если content length - binary), также ограничивать определенные endpoints.
И кстати, такой проблемы нет?
user = { name: "alex" }
logger("my name", { user, }; ->> ушло в очередь
user.name = "ahmed"Что уйдет в лог?
уйдет в лог “alex”, потому что мы сразу ставим record объект в очередь логгера, а его результат записи стрима уже будет работать в asyncio. То есть CPU bound задача с форматированием сработает синхронно, а вывод стрима (I/O) - отработает асинхронно. В этом вся прелесть предложенного мной подхода. И да, Мистер “ahmed” останется ждать своего часа побывать в логгере.
А все же, почему не tsv? Это ж на каждую запись дублируется структура, да еще и с такими длинными именами. Я понимаю, если структура в каждой записи меняется, но здесь вроде бы нет.
Да и раз уже JSON, то давайте вложенность: {"request" : {"uri" : "", "referer": "", "protocol": "" }, "response": {}}
А это вообще странно выглядит: "response_headers": "{\"content-length\": \"13\", \"content-type\": \"application/json\"}", "response_body": "{\"foo\":\"baz\"}"
Формат специфичный и дело уже разработчика подстраивать формат: я это описал в части, где инициализировал pydantic структуру. Вот, по сути этой структурой можно сделать что угодно в части формата. Тело ответа и заголовки строкой в связи со спецификациями проектов в компании, требования архитекторов и девопсов для однообразия. Решения придумывались совместно над типом данных некоторых полей, они также изменяемы, как видно в коде примеров. Суть статьи была показать, как заставить все механизмы вместе: нативное логирование, асинхронность, форматирование в удобный кастомный формат, который нужен только автору, а можно еще и под ECS это подбить, также показать это дело со стороны веба(аналогичное можно на http-клиентах сделать, могу показать, как это было реализовано на примере httpx библиотеки).
А JSON зачем же?
1) JSON для кастомно-настроенного логстэша. Какие никакие, а поля (я убрал из примеров, но были поля еще трассировки OpenTelemetry, посчитал, что для статьи это неважно)
2) тело и заголовки в строке, потому что эксплуатация хочет это в таком виде читать, копировать, использовать для своих нужд, а также оптимизация для разработчиков на других языках программирования: тут формат вышел из попытки подстроиться под текущие и устоявшиеся стандарты скорее, чем какое-то ноу хау. Поэтому я заложил возможность менять форматы как угодно и где угодно, чтобы это не было головной болью для разработчиков.
Судя по всему, asynclog использует потоки. В таком случае о какой асинхронности мы можем говорить здесь? В случайные моменты времени поток переключается и синхронно пишет в файл, блокируя loop.
Еще он может использовать celery, но это примерно то же самое - запись в брокер будет тоже идти синхронно для всего процесса.
Буду рад если окажется что я ошибаюсь.
Не используются потоки. Используется обычный класс, который наследуется от QueueHandler, если внимательно попрыгать по исходникам этой либы.
Либо мы про разные библиотеки говорим, либо у вас вообще ссылка не на ту библиотеку стоит.
https://github.com/unpluggedcoder/asynclog/blob/master/asynclog/handler.py - вот единственный файл на 85 строк, там явно идет использование futures.ThreadPoolExecutor.
И где вообще происходит вывод в файл? Средствами logging? Но он синхронный!
Как вообще вы относитесь к тому факту что asyncio не поддерживает асинхронный io для файлов? Есть aiofiles, который, в свою очередь, тоже использует потоки чтобы эмулировать асинхронность.
Асинхронный JSON-Logger для FastAPI