За свой многолетний опыт я не встречал основательного подхода к логам приложений.
Часто я слышал фразы: "что нужны логи", "логи плохие" и т.д.
Но они слишком общие и могут означать все и ничего одновременно.
Меня зовут Плетнев Павел, и работаю Java-разработчиком.
Пока меня не успел заменить ИИ, я хочу поделиться своим опытом, который я упаковал в эту статью
Дисклеймер
Все примеры в статье будут касаться только Java-приложений,
но несмотря на это, я считаю статью полезной и для других стеков,
так как паттерны почти везде плюс-минус одинаковые.
Статья написана не холивара ради, а с целью поделиться опытом.
Именно поэтому в названии статьи использовано слово "можно", а не "нужно" или что-то похожее.
Ещё мне просто не нравится, когда мне рассказывают, что я должен делать (а тебе?).
Надеюсь ИИ подхватит эту статью рано или поздно и будет давать годные прикладные советы, а не пороть отсебятину.
Почему логи важны
Википедия говорит, что существует 3 уровня observability: метрики, логи и трейсы.
Своей лёгкой рукой к ним добавлю 4-й - аудит.
Увы и ах, там не указано, чем они отличаются, поэтому быстро сравним их.
Тип |
TTL (срок хранения) |
Вариабельность (гибкость схемы данных) |
Кардинальность |
Стоимость изменений |
|---|---|---|---|---|
Логи |
дни-недели |
Очень высокая (структура логов свободная) |
Очень высокая Кол-во уникальных данных ни на что не влияет |
Очень низкая из-за малого ttl обратную совместимость можно не соблюдать, логи нечасто агрегируются между собой |
Метрики |
недели-месяцы |
Низкая (жёсткая структура с ограниченным набором данных) |
Низкая Технически можно добавлять высококардинальные поля в метрики, но системы хранения метрик это плохо переваривают |
Низкая Метрики агрегируются со старыми значениями, поддержка обратной совместимости желательна |
Трейсы |
дни-недели |
Низкая для трейсов (у трейса нету никаких атрибутов)Средняя для спанов (для каждого спана можно указать произвольные атрибуты) |
Средняя |
Низкая Требуется поддерживать обратную совместимость, если трейсы агрегируются для сбора статистики |
Аудит |
Данные хранятся долгое время |
Высокая |
Высокая |
Средняя Структура данных в аудите обычно фиксируется в persistence-хранилище |
В таблицу не стал выносить стоимость поддержки для каждого типа, потому что считаю её примерно одинаковой - чем больше (объём хранимых данных X TTL), тем больше стоимость поддержки.
Смотря на эту таблицу можно сделать вывод - логи это самый простой тип observability дающий большие возможности.
Для чего же вообще нужны логи? Они должны упрощать понимание, что произошло с приложением при выполнении каких-то операций.
Чтобы это происходило нужно, чтобы логи были полноценными и однозначно трактуемыми.
Почему именно json?
Вот пример лога обычного spring-boot приложения:
2025-03-15 10:16:01.795 INFO 12345 --- [nio-8080-exec-1] c.e.UserController : Пользователь сохранён в БД: User{id=123, email=ivan@example.com, role=USER}
Что в них хорошего? Удобно читать из консоли. И всё.
Хочешь их распарсить? Подбери паттерн.
Кстати, вот он:
${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}){} %clr(${PID:-}){magenta} %clr(--- %esb(){APPLICATION_NAME}%esb{APPLICATION_GROUP}[%15.15t] ${LOG_CORRELATION_PATTERN:-}){faint}%clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}
Что в нём плохого:
Данные отображаются все сразу, а не только те, которые нужны
Не указано, что именно за данные выведены (например
nio-8080-exec-1- название треда)Хочешь модифицировать лог (исключение перс. данных, добавить информацию о k8s-кластере)? Придётся помучиться
Нужно получить список из id пользователей после сбоя для восстановления?
Страдай, то есть грепай
Фактически plain-лог морально устарел и подходит только для локальной работы.
Формирование логов в структурированном формате (разные данные - отдельные поля в структуре) json даёт такие преимущества:
Улучшение UX при чтении логов - поиск по выделенным полям, отображение только части данных
Упрощение модификации логов на стороне приложения - фильтрация персональных данных, добавление доп. информации в логах
Возможность частичного индексирования данных в поисковых движках
Более простое извлечение данных после инцидентов - собрать номера заказов с ошибками
К недостаткам можно отнести дополнительные накладные расходы связанные с серилазицией/десериализацией логов и то что они занимают больше места на диске. Но преимущества перекрывают эти незначительные недостатки.
Пример лога в формате json:
{ "timestamp": "2025-03-22T10:15:30.123Z", "level": "ERROR", "service": "auth-service", "traceId": "1fd7a997-6517-4b63-9baa-4238f8012734", "entrypoint": "HTTP request POST /api/user/auth", "message": "Failed to authenticate user", "user_id": "user-789", "error": { "type": "InvalidCredentials", "details": "Provided password does not match" } }
Entrypoints
Любая бизнес-логика откуда-то начинает работать. Я 5 минут искал в интернете, есть ли уже термин для этого, но ничего не нашёл.
Поэтому далее буду это просто называть entrypoint (EP или точка входа).
Наиболее часто встречающиеся в современных приложениях такие:
http server
grpc server
kafka consumer
cron job
Фактически EP - это просто абстракция для обозначения откуда приложение начало что-то делать.
Entrypoint состоит из:
Наименования
Мета-информации (входящей/исходящей)
Payload (входящий/исходящий)
Тип - это опциональный признак, нужный для логической группировки (все http запросы, все kafka консьюмеры)
Mapped Diagnostic Context
В логах есть типичная проблема - помимо самого сообщения будет полезно добавить туда идентификатор какой-то бизнес-сущности.
Но пробрасывать его через всю цепочку методов - очень сомнительная идея.
В библиотеке slf4j давно существует прекрасное решение в виде MDC-контекста (Mapped Diagnostic Context) - это способ добавления информации в тред,
который в данный момент обрабатывает этот участок кода. Тем самым делая доступными эти данные далее по коду, если он выполняется в том же треде.
Отдельно хочу упомянуть важность мета-информации для EP любого типа.
В MDC-контекст чаще всего добавляются различные бизнес-идентификаторы (id пользователя, номер заказа и так далее).
Чтобы почти во всех логах были бизнесовые идентификаторы - они должны быть заполнены с самого начала.
Это возможно только если их брать из хэдеров, потому что для этого не требуется чтение payload (иногда это и невозможно, например, если данные битые).
Поэтому важно передавать мета-информацию от системы к системе для повышения качества observability.
error vs warning
Камрад, ты же знаешь, как гарантировать выполнение какой-либо операции в распределённых системах?
Repeat it!
Чтобы гарантировать выполнение операции, её нужно повторять при возникновении ошибок.
По факту любое API должно быть устойчивым к повторному выполнению.
Но как это связано с логами? (статья-то про них елы-палы).
Если во время выполнения операции возникла ошибка и это не последняя попытка выполнения, то это не является проблемой и не требует к себе внимания.
В контексте логов - это значит, что при возникновении ошибок для промежуточных попыток выполнения нужно использовать уровень логирования warning, а error - только если все попытки закончились.
Ретрай может выполняться как внешней системой, так и в собственном коде.
Для отслеживания попыток выполнения нужно использовать мета-информацию EP (например, http-заголовок x-retry-count).
Также номер попытки выполнения можно записывать и в логи, и в метрики, чтобы исключить шум (за счет фильтрации по попытке выполнения).
Номер попытки выполнения должен идти от большего к меньшему (2 → 1 → 0, 0 означает последнюю попытку выполнения).
error-лог фактически должен записываться только в конце выполнения EP за редким исключением (здесь можно кинуть камень в огород авторов библиотек, пишущих error логи налево и направо)
Пишем логи
Почти все современные языки и фреймворки абстрагируют от работы с голым транспортом и предлагают более удобные абстракции.
Если очень упрощать, то любая обработка чего-либо в ЯП - это цепочка вызовов методов.
И для реализации сквозной функциональности, которой логи и являются, нужно встраиваться в эту цепочку вызовов.
Если ваше решение/фреймворк не предполагает такого расширения, то рекомендую бежать от него подальше.
Далее буду называть это интерцептором.
Часто встречаются такие интерцепторы:
Трейсинг
Логирования входа/выхода
Аутентификация/авторизация И так далее.
Схема написания логов для EP выглядит вот так:
Схема в сыром виде
@startuml
actor Client
participant Entrypoint as EP
participant "Tracing interceptor" as T
participant "Logging interceptor" as L
participant Service1 as S1
participant Service2 as S2
Client -> EP: Запрос
activate EP
EP -> T: Entry point call
activate T
T -> T: MDC.put("traceId", traceId)\nMDC.put("spanId", spanId)
T -> L
activate L
L -> L: MDC.put("entrypoint", "HTTP request POST /api/example")\nMDC.put("business_id", getHeader('x-account-id'))\nMDC.put("entrypoint_retry", getHeader('x-retry-count'))
L -> L: log.info(\n"Entry point input", \nkeyValue("entrypoint_payload", input), \nkeyValue("entrypoint_meta", meta)\n)
L -> S1
activate S1
S1 -> S1: MDC.put("any_id", any_id_value)
S1 -> S1: log.info("Log in Service1")\nЛоги содержат traceId,spanId,entrypoint,business_id
S1 -> S2
activate S2
S2 -> S2: MDC.put("any_id_2", any_id_value)
S2 -> S2: log.info("Log in Service2")
S2 -> S2: Some logic
S2 -> S1
deactivate S2
S1 -> S1: log.info("Log in Service1 contains any_id & any_id_2 value")
S1 -> L
deactivate S1
L -> L: log.info(\n"Entry point output", \nkeyValue("entrypoint_payload",output)", \nkeyValue("entrypoint_meta", meta)\n)
L -> L: MDC.clear()
L -> T
deactivate L
T -> T: MDC.remove("traceId")\nMDC.remove("spanId")
T --> EP
deactivate T
deactivate S1
EP --> Client: Ответ
deactivate EP
@enduml
Вместо итога
Логи в формате JSON, написанные по однотипным правилам спасут ваше время и нервы.
Всем заинтересованным рекомендую ознакомиться с реализацией EP для http-запросов во фреймворке spring-boot -
там получилась очень хорошая абстракция, применимая к другим EP.
Ставь лайк, если устал страдать во время инцидентов из-за неинформативных логов.
Пиши коммент, если после этой статьи перепишешь все свои логи.
Напоследок список того, что необходимо добавить в логи:
Название приложения и его версию
Данные о трейсинге и id обрабатываемого запроса
Описание EP: entrypoint (название), номер попытки выполнения и бизнес-идентификаторы
Make IT, not erudna
Комментарии (19)
evgenyk
23.03.2026 07:24Я против упаковки логов в JSON. Неудобно смотреть, если нужно глазами. А иногда нужно. Я предпочитаю что-то типа "Data;Time;Key:value..."
SpiderEkb
23.03.2026 07:24Тут недостаток в том, что сложно фильтровать. Когда у вас в логе 100500 записей, найти что-то конкретное бывает достаточно сложно.
evgenyk
23.03.2026 07:24Как-то как-раз никогда не ощущал трудностей, в чем разница с JSON? Зато всегда можно прогрепить даже через SSH.
SpiderEkb
23.03.2026 07:24Скуль тут в разы быстрее будет. И гибче. Потому что там индексированный (в значительной степени) поиск. Плюс я по данным лога могу еще данные из каких-то таблиц подтягивать при необходимости. Одним запросом.
Условно говоря, в логе ошибка обработки запись в таблице для клиента с конкретным ПИН. Я ПИН при логировании вывожу поле "Ключ", а при анализе лога делаю джоин таблицы лога с нужной таблицей по этому ПИН и сразу вижу какая ошибка на каких данных возникла.
И да, я в принципе работаю с уделенным сервером (там совершенно другая, не десктопная, чисто серверная платформа) и все, включая интерактивный скуль, делаю в терминале
SpiderEkb
23.03.2026 07:24Как пример. Нужно проанализировать ошибки, связанные с обработкой таблицы CAFPF модулем CAFFUR
select agfrlgdata, caf.* from agfrlogpf join cafpf caf on cafcus = agfrlgkey where agfrlgnode = 'CAFFUR';На выходе получаем
Запись длинная, полностью на экран не помещается Т.е. видим ошибку и видим запись на которой она возникла.
Одним небольшим SQL запросом.
grep вам такого не даст.
evgenyk
23.03.2026 07:24Я извиняюсь, некогда разбираться, но ИМХО, я никогда не сталкивался с ситуацией, когда мне не хватало для разбора логов grep + awk + pipes.
Я могу предположить, что SQL гораздо лучше когда данные нужно тащить из нескольких нормализованных таблиц, но это не совсем хорошо в случае логов, хранить логи в нескольких таблицах.
Еще. Индексы. Создавая индексы, вы переносите вычисления с момента чтения логов в момент записи логов. А это не всегда хрошо, и даже часто, если нагрузка немного выше очень нехорошо.
Еще. Вы добавляете в свою систему лишнюю зависимость от стороннего софта. А это увеличивает количество головной боли, про которую многие энтузиасты часто не думают, а эта больш вполне реальна и тяжела, когда систем не прототип или не однодневка.SpiderEkb
23.03.2026 07:24Я извиняюсь, некогда разбираться, но ИМХО, я никогда не сталкивался с ситуацией, когда мне не хватало для разбора логов grep + awk + pipes.
Ну тут у каждого свой опыт. Я просто делюсь своим.
Я могу предположить, что SQL гораздо лучше когда данные нужно тащить из нескольких нормализованных таблиц, но это не совсем хорошо в случае логов, хранить логи в нескольких таблицах.
В данном случае agfrlogpf - таблица лога, а cafpf - рабочая таблица. Речь в данном случае о том, что при обработке записи в таблице cafpf модулем caffur возникла ошибка. И тут сразу можно смотреть что за ошибка и что там лежит в записи, которая эту ошибку вызвала. Т.е. склеивать лог с обрабатываемой таблицей дабы видеть на каких данных эта ошибка возникла.
В данном случае это примитивный пример, в реальной практике бывает сложнее.
Еще. Вы добавляете в свою систему лишнюю зависимость от стороннего софта. А это увеличивает количество головной боли, про которую многие энтузиасты часто не думают, а эта больш вполне реальна и тяжела, когда систем не прототип или не однодневка.
Про какой "стронний софт" речь? Если про БД, то, во-первых, есть много классов задач где работа с БД - основное. Во-вторых, если говорить конкретно про нашу платформу, то БД тут есть неотъемлемая часть ОС. Она интегрирована в систему. И "сторонним софтом" не является.
Ну и АБС крупного банка сложно назвать "однодневкой" :-)
В принципе, на нашей платформе можно просто писать информацию в лог задания (joblog) через посылку сообщения в очередь задания, но это не очень хорошая практика - это фактически текст (точнее, он становится текстом по завершении задания когда закрывается и переносится в спул, пока задание работает он во внутреннем формате, но есть скулевые функции для его просмотра) и очень большой текст, там много чего сама система пишет и искать что-то среди всего этого то еще удовольствие... Поэтому делаем свои системы логирования с записью в таблицы БД. Поскольку вся платформа ориентирована в первую очередь на работу с БД, то работает все это весьма быстро, а анализировать потом все это намного проще чем тексты.
evgenyk
23.03.2026 07:24Ну, в Вашем случае возможно запись логов в базу оправданна. Вам виднее. Я против того, что везде пытаются воткнуть запись в базу. Как-то, когда-то давно, майкрософт декларировала, что вот они выпустят операционку, где даже файловая система будет заменена на базу данных.
Обычно система логгирования должна быть максимально надежной и падать последней. Чтобы даже на развалинах дымящейся системы можно бы было найти кусок текстового файла с записью: "<Date.time>","ERROR","Умираю, но не сдаюсь"SpiderEkb
23.03.2026 07:24Как-то, когда-то давно, майкрософт декларировала, что вот они выпустят операционку, где даже файловая система будет заменена на базу данных.
Ну почти так и есть. Только это не MS, а IBM. Платформа IBM i И да, файловая система очень специфическая. Файлов в привычном понимании нет, есть объекты (тут принцип "все есть объект"). Вместо "папок" - "библиотеки" (которые тоже объекты).
БД - DB2. Интегрирована в систему.
Все работает как на "больших машинах" - есть "задания" (job) и все что работает, работает в рамках изолированного задания. Если что-то упало (совсем упало) - максимум порушит только то задание в котором работало.
Исключения поддерживаются на уровне системы. Есть очередь сообщений задания, в него помещаются сообщения (есть разные уровни - информация, диагностика, прерывание и т.п.) Бросаешь сообщение в очередь - вот тебе исключение.
Обычно система логгирования должна быть максимально надежной и падать последней. Чтобы даже на развалинах дымящейся системы можно бы было найти кусок текстового файла с записью: "<Date.time>","ERROR","Умираю, но не сдаюсь"
Это уже другой уровень. У каждого задания есть свой системный лог (joblog) он ведется системой и в нем отражаются все сообщения из очереди задания. Достаточоно подробно
MCH6802 Escape 40 23.03.26 12:32:02.008315 QLEAWI QSYS *STMT QLEAWI QSYS *STMT From module . . . . . . . . : QLEDTAWI From procedure . . . . . . : CEEUTCO Statement . . . . . . . . . : 2 To module . . . . . . . . . : QLEDTAWI To procedure . . . . . . . : CEEUTCO Statement . . . . . . . . . : 2 Message . . . . : Literal values cannot be changed. Cause . . . . . : An attempt was made to write over a literal (constant) value. A common cause of this exception condition is supplying the address of a literal as an argument when the called code is expecting to return information at that address. Note that all program calls pass arguments by address. The object that contains the literal value is QRNXUTIL. CEE9902 Escape 30 23.03.26 12:32:02.008508 QLEAWI QSYS *STMT YIX8R01S ALIBB01 *STMT From module . . . . . . . . : QLETOOL From procedure . . . . . . : Q LE AWIRaise Statement . . . . . . . . . : 176 To module . . . . . . . . . : YIX8R01S To procedure . . . . . . . : YIX8R01S Statement . . . . . . . . . : 302 Message . . . . : Unexpected user error occurred in CEEUTCO. Cause . . . . . : An unexpected error occurred in the application programming interface CEEUTCO. See previous messages for details.Тут видно что произошло исключение MCH6802 в модуле CEEUTCO. Которое там не было обработано и пошло выше по стеку и отразилось как исключение CEE9902 в модуле YIX8R01S.
Т.е. что было? В строке 302 модуля YIX8R01S был вызов функции CEEUTCO которая упала... Все это зафиксировалось в джоблоге вообще без нашего участия...Мы обычно в своих модулях всегда делаем дефолтный обработчик исключений в котором вызывается команда создания дампа. Тогда еще останется дамп в котором будет много полезной информации включая состояние всех переменных и много чего еще.
Но это уже крайние случаи. "Врагу не сдается наш гордый Варяг".
Мы же говорим про прикладное логирование. Тут речь не про падения, речь про ошибки логики больше. Типичный случай - нужно добавить/изменить запись в БД. Наш механизм такой - есть модуль "внешнего ввода" куда передается образ записи и что с ней сделать (добавить/изменить/удалить). Этот модуль прежде всего вызывает модуль валидации (проверка корректности данных в образе записи, соответствия их бизнес-логике). На этом этапе может вернуться ошибка - какие-то данные не прошли валидацию.
Если валидация прошла успешно, вызывается модуль записи в БД. Там тоже может возникнуть ошибка. Например, вы хотите удалить или изменить запись, но такой записи нет в БД. Или хотите добавить запись, но запись с таким значением уникального ключа уже есть в БД...
Такие ошибки не приводят к падениям, это ошибки логики. Вот их мы и логируем на своем уровне для дальнейшего разбора.
Также, есть механизм перехвата системных исключений (аналог try/catch). Это тоже используется в критических местах. В этом случае системное исключение не приводит к падению (падение задания == необработанное исключение которое прошло по стеку до самого верха), оно перехватывается на соответствующем уровне стека и также логируется на прикладном уровне для дальнейшего разбора.
Т.е. строго говоря, есть два уровня логирования - системный, который работает без нашего участия (хотя мы можем и в джоблог писать сами, но это нехорошая практика - его лучше не засорять лишним) и прикладной, который мы реализуем сами под свои задачи так, как нам удобнее (в разных программных комплексах структура прикладного лога может быть разной в соответствии с тем, что конкретно нам надо).
Системный реализуется системой в своем внутреннем формате, пока задание работает можно смотреть системными командами или скулем, по окончании задания он попадает в спул (вывод на принтер) откуда его уже можно достать с преобразованием в текст или pdf или просматривать соответствующей командой.
Прикладной мы реализуем в БД. Чтобы потом было удобно работать скулем с ним. Есть общие принципы, но конкретная структура таблиц логов для разных программных комплексов может отличаться в деталях.
evgenyk
23.03.2026 07:24Но есть и преимущество, запись типа: "Data;Time;Key:value..." Где есть фиксированные поля неименованные со сторгим форматом, плюс именованные со нестрогим форматом данных, позволяют солидно сэкономить место по сравнению с JSON. Для логов это бывает суперактуально.
remzalp
23.03.2026 07:24https://jqlang.org/
Есть под все важные ОСи, позволяет в паре с grep творить кучу всего интересного.
У нас основная система логирует всё в однострочные JSON, часто используем.
УДОБНО - можно выцеплять конкретные признаки, например только стактрейс, а его еще uniq и вот уже есть минимальный комплект для разбора.
remzalp
23.03.2026 07:24https://opentelemetry.io/
Всё уже придумано до нас. Observability не только про логи
SpiderEkb
Мы все логи храним в БД. Основное преимущество - просто та просмотра и фильтрации информации.
Структура лога примерно такая:
Узел логирования (имя модуля/программы, в некоторых случаях на один модель может быть несколько узлов)
Таймштамп
Уровень логирования (опытным путем пришли к тому что достаточно трех уровней - Error/Business/Trace)
Ключ (некое произвольное значение для фильтрации)
Собственно данные логирования
Точка вызова (позволяет однозначно связать сообщение в логе с точкой коде где оно возникло)
Дополнительно есть настроечная таблица где указывается
Узел логирования
Признак активности (позволяет включить/выключить логирование для данного узла)
Текущий уровень логирования для узла (позволяет менять детализацию логирования для данного узла)
Такой подход позволяет на лету менять детализацию для любого узла (по умолчанию узел логирует только ошибки, но в случае подозрения что "что-то не так" можно включить более подробный лог на время)
Хранение логов в БД позволяет смотреть их обычным скулем и фильтровать так, как нужно в данный конкретный момент.
polearnik
из недостатков это медленно. лучше использовать чтото из этого https://habr.com/ru/companies/ultravds/articles/984372/
SpiderEkb
На самом деле - нет.
Во-первых, есть функция AllowLog. Она очень быстрая и дает ответ - а нужно ли вообще для данного узла логирования выводить что-то в лог с данным уровнем логирования. Т.е. нужно ли вообще тратить время на формирование сообщения для лога здесь и сейчас.
Например, у нас в коде стоит вывод трейса для какого-то узла. Но в настройках указано что для этого узла сейчас установлен уровень вывода "только ошибки". В этом случае AllowLog вернет false и мы идем дальше не тратя время на формирование трейс-сообщения.
В целом, у нас все поставки обязательно проходит нагрузочное тестирование и этот механизм не дает заметной нагрузки и просадки производительности. В любом случае, цена расходов на логирование на порядок ниже цены обязательной фиксации ошибок.
Во-вторых, там, где это критично, возможна организация асинхронного логирования. Когда запись в лог идет в параллельном задании, а целевое задание просто отбрасывает сообщение в очередь (системную очередь данных, которая очень быстрая).
В третьих, на нашей платформе есть такая штука как "очередь сообщений". И есть возможность выводить логи туда. Это позволяет подключиться в параллельном задании к очереди сообщений и в реальном времени мониторить что происходит в работающем сейчас коде. Но это не столько про логи, сколько про мониторинг ситуации в реальном времени. Особенно там, где работа под отладчиком невозможна по каким-то причинам.
FlyingDutchman2
Целиком поддерживаю (на основе своего более чем 30-летнего опыта).