Хабр Курсы для бэкендеров
РЕКЛАМА
Практикум, Хекслет, SkyPro, авторские курсы — собрали всех и попросили скидки. Осталось выбрать!
Поток Бэкенд доступен 24/7 благодаря поддержке друзей Хабра
Комментарии 19
Мы все логи храним в БД. Основное преимущество - просто та просмотра и фильтрации информации.
Структура лога примерно такая:
Узел логирования (имя модуля/программы, в некоторых случаях на один модель может быть несколько узлов)
Таймштамп
Уровень логирования (опытным путем пришли к тому что достаточно трех уровней - Error/Business/Trace)
Ключ (некое произвольное значение для фильтрации)
Собственно данные логирования
Точка вызова (позволяет однозначно связать сообщение в логе с точкой коде где оно возникло)
Дополнительно есть настроечная таблица где указывается
Узел логирования
Признак активности (позволяет включить/выключить логирование для данного узла)
Текущий уровень логирования для узла (позволяет менять детализацию логирования для данного узла)
Такой подход позволяет на лету менять детализацию для любого узла (по умолчанию узел логирует только ошибки, но в случае подозрения что "что-то не так" можно включить более подробный лог на время)
Хранение логов в БД позволяет смотреть их обычным скулем и фильтровать так, как нужно в данный конкретный момент.
из недостатков это медленно. лучше использовать чтото из этого https://habr.com/ru/companies/ultravds/articles/984372/
На самом деле - нет.
Во-первых, есть функция AllowLog. Она очень быстрая и дает ответ - а нужно ли вообще для данного узла логирования выводить что-то в лог с данным уровнем логирования. Т.е. нужно ли вообще тратить время на формирование сообщения для лога здесь и сейчас.
Например, у нас в коде стоит вывод трейса для какого-то узла. Но в настройках указано что для этого узла сейчас установлен уровень вывода "только ошибки". В этом случае AllowLog вернет false и мы идем дальше не тратя время на формирование трейс-сообщения.
В целом, у нас все поставки обязательно проходит нагрузочное тестирование и этот механизм не дает заметной нагрузки и просадки производительности. В любом случае, цена расходов на логирование на порядок ниже цены обязательной фиксации ошибок.
Во-вторых, там, где это критично, возможна организация асинхронного логирования. Когда запись в лог идет в параллельном задании, а целевое задание просто отбрасывает сообщение в очередь (системную очередь данных, которая очень быстрая).
В третьих, на нашей платформе есть такая штука как "очередь сообщений". И есть возможность выводить логи туда. Это позволяет подключиться в параллельном задании к очереди сообщений и в реальном времени мониторить что происходит в работающем сейчас коде. Но это не столько про логи, сколько про мониторинг ситуации в реальном времени. Особенно там, где работа под отладчиком невозможна по каким-то причинам.
Мы все логи храним в БД.
Целиком поддерживаю (на основе своего более чем 30-летнего опыта).
Я против упаковки логов в JSON. Неудобно смотреть, если нужно глазами. А иногда нужно. Я предпочитаю что-то типа "Data;Time;Key:value..."
Тут недостаток в том, что сложно фильтровать. Когда у вас в логе 100500 записей, найти что-то конкретное бывает достаточно сложно.
Как-то как-раз никогда не ощущал трудностей, в чем разница с JSON? Зато всегда можно прогрепить даже через SSH.
Скуль тут в разы быстрее будет. И гибче. Потому что там индексированный (в значительной степени) поиск. Плюс я по данным лога могу еще данные из каких-то таблиц подтягивать при необходимости. Одним запросом.
Условно говоря, в логе ошибка обработки запись в таблице для клиента с конкретным ПИН. Я ПИН при логировании вывожу поле "Ключ", а при анализе лога делаю джоин таблицы лога с нужной таблицей по этому ПИН и сразу вижу какая ошибка на каких данных возникла.
И да, я в принципе работаю с уделенным сервером (там совершенно другая, не десктопная, чисто серверная платформа) и все, включая интерактивный скуль, делаю в терминале
Как пример. Нужно проанализировать ошибки, связанные с обработкой таблицы CAFPF модулем CAFFUR
select agfrlgdata, caf.*
from agfrlogpf
join cafpf caf
on cafcus = agfrlgkey
where agfrlgnode = 'CAFFUR';На выходе получаем
Т.е. видим ошибку и видим запись на которой она возникла.
Одним небольшим SQL запросом.
grep вам такого не даст.
Я извиняюсь, некогда разбираться, но ИМХО, я никогда не сталкивался с ситуацией, когда мне не хватало для разбора логов grep + awk + pipes.
Я могу предположить, что SQL гораздо лучше когда данные нужно тащить из нескольких нормализованных таблиц, но это не совсем хорошо в случае логов, хранить логи в нескольких таблицах.
Еще. Индексы. Создавая индексы, вы переносите вычисления с момента чтения логов в момент записи логов. А это не всегда хрошо, и даже часто, если нагрузка немного выше очень нехорошо.
Еще. Вы добавляете в свою систему лишнюю зависимость от стороннего софта. А это увеличивает количество головной боли, про которую многие энтузиасты часто не думают, а эта больш вполне реальна и тяжела, когда систем не прототип или не однодневка.
Я извиняюсь, некогда разбираться, но ИМХО, я никогда не сталкивался с ситуацией, когда мне не хватало для разбора логов grep + awk + pipes.
Ну тут у каждого свой опыт. Я просто делюсь своим.
Я могу предположить, что SQL гораздо лучше когда данные нужно тащить из нескольких нормализованных таблиц, но это не совсем хорошо в случае логов, хранить логи в нескольких таблицах.
В данном случае agfrlogpf - таблица лога, а cafpf - рабочая таблица. Речь в данном случае о том, что при обработке записи в таблице cafpf модулем caffur возникла ошибка. И тут сразу можно смотреть что за ошибка и что там лежит в записи, которая эту ошибку вызвала. Т.е. склеивать лог с обрабатываемой таблицей дабы видеть на каких данных эта ошибка возникла.
В данном случае это примитивный пример, в реальной практике бывает сложнее.
Еще. Вы добавляете в свою систему лишнюю зависимость от стороннего софта. А это увеличивает количество головной боли, про которую многие энтузиасты часто не думают, а эта больш вполне реальна и тяжела, когда систем не прототип или не однодневка.
Про какой "стронний софт" речь? Если про БД, то, во-первых, есть много классов задач где работа с БД - основное. Во-вторых, если говорить конкретно про нашу платформу, то БД тут есть неотъемлемая часть ОС. Она интегрирована в систему. И "сторонним софтом" не является.
Ну и АБС крупного банка сложно назвать "однодневкой" :-)
В принципе, на нашей платформе можно просто писать информацию в лог задания (joblog) через посылку сообщения в очередь задания, но это не очень хорошая практика - это фактически текст (точнее, он становится текстом по завершении задания когда закрывается и переносится в спул, пока задание работает он во внутреннем формате, но есть скулевые функции для его просмотра) и очень большой текст, там много чего сама система пишет и искать что-то среди всего этого то еще удовольствие... Поэтому делаем свои системы логирования с записью в таблицы БД. Поскольку вся платформа ориентирована в первую очередь на работу с БД, то работает все это весьма быстро, а анализировать потом все это намного проще чем тексты.
Ну, в Вашем случае возможно запись логов в базу оправданна. Вам виднее. Я против того, что везде пытаются воткнуть запись в базу. Как-то, когда-то давно, майкрософт декларировала, что вот они выпустят операционку, где даже файловая система будет заменена на базу данных.
Обычно система логгирования должна быть максимально надежной и падать последней. Чтобы даже на развалинах дымящейся системы можно бы было найти кусок текстового файла с записью: "<Date.time>","ERROR","Умираю, но не сдаюсь"
Как-то, когда-то давно, майкрософт декларировала, что вот они выпустят операционку, где даже файловая система будет заменена на базу данных.
Ну почти так и есть. Только это не 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 или просматривать соответствующей командой.
Прикладной мы реализуем в БД. Чтобы потом было удобно работать скулем с ним. Есть общие принципы, но конкретная структура таблиц логов для разных программных комплексов может отличаться в деталях.
Я не про json. Я про БД
Но есть и преимущество, запись типа: "Data;Time;Key:value..." Где есть фиксированные поля неименованные со сторгим форматом, плюс именованные со нестрогим форматом данных, позволяют солидно сэкономить место по сравнению с JSON. Для логов это бывает суперактуально.
https://jqlang.org/
Есть под все важные ОСи, позволяет в паре с grep творить кучу всего интересного.
У нас основная система логирует всё в однострочные JSON, часто используем.
УДОБНО - можно выцеплять конкретные признаки, например только стактрейс, а его еще uniq и вот уже есть минимальный комплект для разбора.
https://opentelemetry.io/
Всё уже придумано до нас. Observability не только про логи
Зарегистрируйтесь на Хабре, чтобы оставить комментарий
Как можно писать логи