Логирование это явный продукт этапа эксплуатации. Логи, как сущности процесса разработки, появляются уже на этапах, когда ваше приложение работает. И вам хочется знать, как именно оно работает, и корректно ли.
Пожив некоторое время и в системе, где общей культуры ведения логов вообще не было. Потом, где не было “уровней” логирования, а были только условные аудит логи и ошибки. А потом в бигтехе, где все сделано по “индустриальным стандартам”. И каждая сраная библиотека успевает насрать в Error логи по 10 сообщений о том, что её авторы смотрели лунтика, и либа родилась инициализация прошла успешно.
В итоге я для себя, а так же предлагаю и тебе, пришел к выводу. Что нормального решения все ещё не придумали. Каждое из существующих подходит только к конкретному ИТ продукту.
Расскажу о каждом, который знаю или видел. Но так как я специализируюсь на бекенд разработке веб приложений, то наиболее развернутый ответ будет только для моего профиля.
Так же мысли и выводы, к которым я пришел в этой заметке, основываются на ранее обсужденной концепции минимизации раздражителей.
Логи с уровнями
Очень популярный подход. Но в разработке бекенда он плохо работает, имхо. Почему? Как раз из-за своих “уровней”.
Хочу построить свои рассуждения наоборот, с того где это кажется полезным. А потом обсудим его применимость в бекенде.
Логгеры с уровнями логирования в себе подразумевают в своем DevX два фундаментальных юзкейса, без которых на ваш логгер не будут, даже в шутку, смотреть. Первый - не логировать, если уровень лога меньше выставленной настройки. Как раз наличие тех самых Trace, Debug, Info, Info2, Warn, PreWarn, Error, Crit, Critical (да-да, я видел оба в одном логгере). И все эти уровни выстроены по линеечки. А второй - возможность на-лету переключить этот уровень. Что бы в какой-то момент логи переключились на более подробные.
Как мне кажется, эти фичи нужны только разработчикам, которые вообще не могут добраться до логов своего ИТ продукта. К ним относятся разработчики библиотек, фреймворков, cli тулов. Они собственноручно не могут дойти до приложения, поменять его код, и раздебажить логами. Когда они уже написали все тесты, но все равно что-то не работает в приложении, и что бы собрать как можно больше данных о проблемном поведении, нужно внедрять дебажные принтлны прямо в код. И что бы они не спамили постоянно, скрывать их за параметрами вызова, флагами --verbose или енв переменными. При этом клиент их продукта должен быть достаточно квалифицирован, что бы вообще включить эти дебаг логи, собрать, а потом ещё и принести их разработчику.
Еще к ним можно отнести разработчиков бекенда, которые не могут по каким-то причинам освоить процессы CI/CD, особенно CD, и особенно C. Когда в компании такой долгий или неавтоматизированный этап Continuous Delivery, что, в лучшем случае, от всей аббревиатуры можно с натяжкой оставить только Delivery. Когда релиз занимает весь день, или даже ночь. А предрелизный процесс длится неделю, решая что катим, и оно - готово, а что повезем через месяц.
В этом случае, конечно, стоит в серьез рассматривать отдельные уровни. как временное решение проблемы долгих релизных циклов. И что б раздебажиться - проще поддерживать замусоренную кодовую базу, но иметь данные для решения возникающих проблем.
Но обычно, и к этому нужно стремиться у себя в команде, в бекенд разработке ваши логи - рядом. На расстоянии одного урла и авторизации, максимум - за корпоротивным VPN. Зачем закладывать в код логи, которые то логируются, то не логируются? Зачем дублировать текстом уже написанный реальный код, что бы он вывелся в лог?
Если у вас быстрый релизный цикл - добавляете обычных логов (о которых ниже) в приложение, отвозите на прод. Раздебажили? Отлично, проблема решена.
У вас стабильный стейдж/препрод/whatever? Даже на прод не нужно деплоить, просто на тестовое окружение утащите новую версию.
У вас хорошо организована архитектура юнит или компонентных тестов? Просто добавьте тест. Даже выкатываться куда-то не нужно.
Аудит логи
Есть специальный кейс, когда вам все же нужно писать логи, которые вы никогда, как разработчик, не будете читать. Это аудит логи. Которые нужны, что бы были. И что бы лежали и пылились. Примерно, как документы на квартиру. Большую часть времени они лежат внизу коробки с другими такими же забытыми документами, но если что-то важное случается - они резко становятся важны.
Тут ситуация сложная, потому что нужно подумать. Обычно, из того что я видел, такие логи пишутся на условном Info уровне / в stdout. Как бы просто информация, что действие случилось. Но подумать тут нужно о том, как такие логи будут использоваться.
Если это логирование доступа пользователей в систему, то странно их видеть рядом со строками “здесь”, “здесь2” и “сюда не должно дойти”. Наверное, таким логам нужна какая-то гарантия доставки до системы хранения. Или хотя бы надежда, что логи доедут до системы хранения. Почему они рядом с обычным логированием? Вынесите этот юзкейс “логирования” в отдельную сущность, и начните обращаться с ними, как с полноценными “записями действий”. Сделайте их частью бизнес логики, и путаница развяжется.
Если вы считаете, что вынесение этих логов как часть бизнес логики - оверкил, то есть решение по-проще. Вынесите аудит-логирование в отдельный компонентный логгер.
Контекстные логгеры
Просто хочется здесь упомянуть вид логгеров, которые по факту являются логгером с одним уровнем. Извне можно включать или отключать этот логгер в контексте его исполнения. А так же добавлять в этот контекст дополнительную информацию, по мере выолнения кода.
Ярким примером служат старомодные cli программы, у которых есть флаг вида -v / --verbose, включающий подробное логирование всего процесса выполнения.
Но обычно, у таких логгеров есть метод вида WithData/Keys/Context/Tags, в который можно запихать какую-то информацию в начале исполнения. И потом, все логи пишущиеся в данном контексте, будут иметь, помимо основного лога, ещё вот эту дополнительную, ранее внесенную информацию. Соответственно такие логгеры могут плодиться и самокопироваться, если контекстам выполнения нужно разойтись.
Обычно полезны, так как позволяют добавить информацию в лог только один раз. И потом все логи будут привязаны к этой информации. Например, ID юзера.
Но полезность иногда сомнительная. Так, в случае потребности запуска асинхронных процессов, у них нет способа почистить свой стек дополнительной информации. Нужно или брать полностью чистый логгер и наполнять его заново только нужными данными. Или костыльно переопределить не нужные ключи null или пустыми значениями.
Изолированное логирование
На перекрестке контекстного и многоуровневого логирования, на самом деле, тоже есть специальный кейс, который можно понять и принять.
Фундаментально, до этого по тексту, я подразумевал, что логгер с уровнями переключает уровни во всем приложении сразу. И обычно, так и есть. Никто не парится, и использует глобальный объект логгера.
Но вот когда мы соединяем оба подхода - получаем изолированное дебаг логирование (не знаю как оно нормально называется, напишите мне правильный термин для этого). Это когда у вас в коде есть некоторое количество дебаг логов, но вы не можете в общей конфигурации переключить уровень, что бы одномоментно включились все дебаг логи. А уровень логирования зависит от контекста потока исполнения кода. То есть приложение умеет включать дебаг логи, но только на время выполнения одного действия, изолированного контекстом.
Например, запрос в АПИ. Все запросы, которых 100500тыс/секунду, ничего не логируют. А конкретный запрос/заказ/клиент, которого мы помечаем специальным флагом, начинает на всем протижении своего контекста логировать дебаг логи. Если это запросы, и вы живете в многосервисной системе, где сервисы общаются между собой, то можно использовать хедеры. И наполнять их автоматически, когда контекст исполнения в одном сервисе переносится на RPC вызов в другой сервис. Так можно задебажить весь путь исполнения кода в системе.
Изолированное логирование 2
Ещё один полезный кейс, который возникает на объединении разных видов логгеров, про детализацию только тогда, когда она нужна. Прием подсмотрен из трейсинга, когда происходит частичный сбор семплов.
В трейсинге обычно все-все запросы и трейсы не собираются, и используются разные стратегии семплирования. Или как минимум не остаются в долгом хранилище, а выкидываются по истечении некоторого времени. Кроме специально помеченных трейсов. Обычно, помечают два вида трейсов: дебаг трейсы, запросы которых специально генерируются человеков; и трейсы с возникшей ошибкой.
И вот тут появляется полезный юзкейс такого семплирования в случае возникновения ошибок. Можно писать детальные логи не на момент выполнения кода, а только в момент возникновения ошибки. Таким образом система будет вас уведомлять с полным контекстом выполнения только в случае каких-то проблем, на которые вы будете обращать внимание. Но не будет беспокосить в стабильно работающем режиме.
Да, у этого способа есть недостатки:
- большее потребление ресурсов на 1 запрос, потому что нужно накопить все потенциальные логи в памяти
- вы не увидите сообщения в случае полного падения приложения
- первые логи о начале выполнения какого-то куска кода для долгих процессов возникают поздно, что не удобно для дебага
- некоторая общая сложность концепции: происходит ленивое исполнение кода там, где все привыкли к его мгновенности
Компонентные логгеры
Компонентные логгерами можно называть те реализации, которые могут отделиться от своего глобального логгера-прородителя и начать существовать полностью самостоятельно. Со своими элементами управления, включенными уровнями и так далее. Где-то такие логгеры называют именными.
Вот было бы круто, если бы все библиотеки пользовались ими? Что бы в конструкторах библиотек принимался логгер, а не брался глобальный.
Во-первых, полезность такого логгера в том, что разработчики библиотеки подключения к бд уже могут полноценно пользоваться уровнями логирования по их назначению. Инфо логи вернуться на свой уровень с уровня ворнинга. На уровне с ошибками правда останутся только ошибки, с которыми нужно и можно что-то сделать.
Во-вторых, отдельная настройка позволяет включать разную реакцию логгеров разных компонентов на контекст, в котором происходит генерация лога. Например, когда прокинут флаг дебаг лога, можно отдельно и прозрачно настроить: бизнес логику мы логируем, JSON запроса и ответа тоже логируем, SQL запросы все логируем, но вот HTTP дампы запросов во внешние системы логировать не будем.
Но есть и очевидные минусы. Такая свобода добавляет уровень сложности в настройке приложения. А так же высокий порог входа для новеньких, из-за дополнительной когнитивной нагрузки.
Info и error
Этот раздел я оставил себе для того, что бы не согласиться с Дейвом.
Dave Cheney Practical Go: Let’s talk about logging
Не согласиться, но не во всем.
Судя по статье, опыт Дейва базируется на разработке cli приложениях и библиотеках. Он хочет оставить только дебаг и информационные логи. И это как раз соответствует моим примерам выше - отличный вариант для консольных тулзов. На одном из уровней пишем важный для пользователя текст, на втором - для разработчика. Но кажется, ещё нет бекенд систем, в логи которых свободно и специально пускают пользователей, что б они почитали журналы работы приложения.
С чем я согласен - это уровни трейса, варнинга и различных фаталов - не нужны. И его рассуждения соответствуют современным процессам разработки.
Trace
Трейс - это самый мемный уровень. Используя его, разработчик как бы признается, что его способности в удаленном дебаге кода на сколько малы, что нужно нужно написать на каждой строке принтлн. Причем, под способностями я не имею в виду персональные технические скилы. Не способность может быть обусловлена сложностью доступа к продашкену или ужастно пахнущим кодом с итальянским соусом.
Лучше честно написать принтлны или систем.логи, чем делать вид, что этот цирк - норма. В здоровых системах должен быть строго запрещен под угрозой увольнения с позором.
Так же помечу, что уровень trace - не про трейсинг, который opentracing/opentelemetry.
Debug
Уровень чисто для разработчика. В работающем приложении на продакшене этого уровня конечно же не должно быть. Уровень только для того, что бы локально поделать принтлны - подебажить. Сразу после дебага должен удаляться.
Так как юзкейс использования ограничен локальной разработкой, то можно оформить его как отдельный компонентный логгер. И что бы не пустить его в продакшн, написать линтер для ЯП, который будет проверять наличие вызовов в коде.
Если вы делаете библиотеку, то тут конечно же уже не стоит избавляться от такого уровня или логгера. Если вы хотите, что бы у пользователя-разработчика была возможность предоставить вам детальные горячие данные о работе вашей библиотеки, то дебаг - подходящий кандидат. И дебаг логгер нужен тогда не для того, что бы отладить программу, а что бы собрать отладочную информацию.
Warn
Чистое зло. Сообщение на этом уровне как бы говорит, что “что-то не так”. И если бы это была приборная панель самолета, то иметь лампочку наличия неисправности было бы хорошо. И об этом я еще порассуждаю в разделе про алерты.
Но зачем что-то делать, тебе как разработчику, если ничего не произошло? Как говорит Дейв в своей статье “звучит как не моя проблема”.
Откройте логи вашего сервиса и найдите там ближайший варнинг. Он вас о чем-то предупреждает. О чем-то, что в скором времени сломается. Но когда это время наступит? Скорее всего никогда.
Разработчикам библиотек лучше все же принять решение. Или вы нормально обрабатываете “предупреждающее” поведение, и ситуция является нормой. Или стоит падать полностью и с ошибкой, если дальнейшее исполнение кода не безопасно.
Info
Достаточно простой пациент. По моей практике, уровенем info пользуются как инструментом, что бы сказать “оно случилось, держу в курсе”.
Эта потребность закрывается аудит логгером. Когда вам нужно, по чьим-то требованиям, или просто хочется потом для дебага и разбора поддержки, просто логировать случившиеся события и как система повела себя - объявите отдельный аудит-логгер и пользуйтесь им.
Так как он отдельный, то и фильтровать мусорные сообщения можно легко. И в коде порядок, на информационном уровне пишутся только “держу в курсе” сообщения.
Error
С чем я точно не согласен - уровень error нужен для бекенд разработчика.
И он нужен для сообщений об ошибках, когда в системе произошел сбой заложенных в неё процессов. Для бекенд разработчиков это, очевидно, ошибки в результате исполнения бизнес логики. Они могли случиться далеко внутри tcp стека вашего ЯП и иметь текст 127.0.0.1 connection refused. Но они прервали выполнение бизнес логики, и не были ей обработаны или учтены.
В случае с бекенд разработкой отдавать пользователю полноценный текст ошибки как минимум не юзер-френдли. Как максимум - не безопасно, потому что такой текст может содержать сенситивные данные.
Дейв рассуждает в рамках одного целосного приложения. Но произошедшая внутри сервиса ошибка, во время вызова одного из АПИ методов, не заканчивается аккуратно и удобно внутри приложения. Неожиданная ошибка, в лучшем случае, перехватывается в первых эшелонах системы, на уровне BFF или Gateway сервисов.
Но обычно она раскатывается громом по системе, логам всех сервисов на пути исполнения, залетает в аудит логи на анализ ИБ. И кто-нибудь ещё в базу данных текст ошибки запишет, так как не доверяет местной системе сбора логов, а кто-нибудь отправит в сервис сбора ошибок типо Sentry. А клиент увидит красное “упс, что-то пошло не так”.
Поэтому, для непредвиденного поведения системы, когда мы уже постарались и сделали все что смогли с этой ошибкой. И покастили к известным типам, поретраили запросы, и дедлайн на контекст увеличили. И ничего не помогло. И после этой долгой битвы нам остается только залогировать её. И после - передать вверх по системе о своей неудаче.
В итоге, хочется узнать о том, что такая заруба произошла. Узнать о факте, что система не отказоустойчива. И уровень логирования Error как раз позволяет ментально и лингвистически подчеркнуть для разработчика, читающего лог, что настала пора сесть и подумать. Как такое случилось, и как не допустить этого в дальнейшем.
Формально конечно, не важно как назвать этот уровень. Хоть error, хоть fail, хоть info. Даже не важно, будут ли у логгера вообще уровни, или только функция Println. Важен факт логирования ошибки, причем в данном контексте слово “ошибка” скрывает в себе значение “ошибку архитектуры приложения”, “ошибку проектирования”, “ошибку использования библиотеки”. То есть для отказоустойчивых систем, а точнее для отказоустойчивой бизнес логики, слово “ошибка” нужно понимать в каком-то более фундаментальном смысле. Вкладывать больший смысл, чем обычное “упс, что-то пошло не так, попробуйте позже”.
Идельный логгер
Собирая все мысли выше, хочется сформулировать какой я хочу видеть логгер в бекенд приложениях.
Первое, хотелось бы разделять логгер для разработчика и логгер для аудит-логов. Даже если они оба хотят писать в stdout, но все равно они должны быть разными классами/интерфейсами с разными сигнатурами методов. Причем, специализированными под использование: в сигнатуре аудит-логгера хочется видеть фиксированные поля или пары ключ-значение. Что бы все строки выглядели примерно как client_id=15 method=login action="failed attempt" с точностью до формата вывода. А логгер для разработчика в приложении должен иметь более расслабленный вариант сигнатуры. Что бы разработчик мог на месте непредвиденной ошибки оставить как можно больше деталей случившегося.
Очевидно, что аудит логгерам не нужны всякие сложные концепции использования, о которых мы говорили выше, или будем ниже. Они должны быть просты, даже чуть ли не топорны в использовании. Метод вызвался - лог записался. И ещё, у меня есть некоторое подозрение, но это не точно, что аудит логи не могут существовать полностью без контекста исполнения. Кто-то или что-то все равно является инициатором выполняемого действия.
Второе - это явное отсутствие самого глобального логгера. Но при этом, нужно наличие функций управления регистром компонентных логгеров вне места их объявления или использования в зависимых библиотеках.
Третье - экосистема в приложении, что бы можно было настроить для каждого контекста исполнения требуемые логи. И что бы это делалось без перекомпиляции самого приложения. А как-то конфигурировалось на уровне конфига приложения, или входящего контекста исполнения, например, в хедерах запроса.
Уровни мне не нужны. Нужен способ логировать ошибки приложения. А так же уровень для дебаг логирования для удобства разработчика. Дебаг логирование удобно как минимум при локальной разработке, но если прям не терпится - можно и до прода оставить. Мы оставляем только метода, которые не являются уровнями в прямом понимании этой концепции, потому что их работа независима. Дебаг лог не включает в себя обязательность логирование ошибки, и наоборот.
Так как у нас есть ортогональная методам логирования концепция компонентных логгеров, то и для бекенд разработчика, и для разработчика библиотек есть удобный инструмент интегрирования друг с другом. Разработчик библиотеки закладывает все дебаг логи внутрь своей библиотеки. И если бекенд разработчик явно сконфигурирует логирование на вербоз уровень внутри конкретной либы на включение дебага, то все остаются довольны. Можно временно включить все логи компонента, можно только на конкретные запросы для точечной проверки.
Что бы можно было включать конкретные логи на контекст исполнения нам точно потребуется интеграция нашего логгера с экосистемой проброса контекста исполнения местного языка программирования или фреймворка. Во втором пункте мы констатировали, что глобальный логгер нам не нужен. Но разработчику все равно нужно конструировать его откуда-то. Здесь нужно накодить складывание и вытаскивание логгеров из конкретного контекста исполнения, причем, по имени компонента. Разработчику сетевой библиотеки нужно брать логгер не прикладного уровня приложения, который был последним в стеке контекста, а свой - библиотечный.
Но у нас не всегда есть явный контекст внутри библиотеки: нужно запустить асинхронное выполнение кода или включить бесконечный вотчер какой-нибудь переменной. Очень часто в таком коде нужно стартовать новый контекст, или помержить два контекста. Из-за такой неопределенности нам нужно все же дать инструмент начинающим разработчикам, которые не умеют мыслить на высоких уровнях абстракции. Поэтому нам все ещё нужен метод, создающий компонентный логгер без контекста исполнения. Из-за наличия такого метода и нужны внешние функции управления разными именованными логгерами.
Саммари
Тема логирования очень сложная. И надеюсь, я смог убедить тебя. Или хотя бы направить на мысли о том, что в зависимости от разрабатываемого продукта, подходят разные подходы к логированию или разные “уровни”. В библиотеках - одни, в cli приложениях - другие, при разработке бекенда - третьи. Какие лучше использовать в мобильной разработке, а какие - в анализе AI систем - не подскажу, нет должного опыта.
А так же надеюсь, что смог донести концепцию логирования ошибок в бекенде. Теперь можно обсудить и сами ошибки, как концепцию.