systemd journal or computer readable logs
Maksim Melnikau, Linux Mobile hobbyist, World of Tanks developer
LVEE 2012
Main goal of logs is changing now. Admins don’t read logs anymore, but write programs to read logs instead. This is why logs should be readable by computer in first turn, and only in second turn by human.
The systemd journal is nice example of how it could be implemented.
Проблемы современных логов
Классические системы логирования (syslog, etc) разрабатывались с целью предоставления информации для отладки администратором. В те времена на одного администратора приходилось небольшое количество систем, и он ещё был в состоянии просматривать логи самостоятельно.
Теперь, когда на одного администоратора приходятся десятки, а иногда и сотни/тысячи систем, просматривать логи глазами больше невозможно. Администраторы прибегают к автоматическим системам мониторинга, таким как zabbix и др, а для анализа логов используют средства энтерпрайз-уровня (такие, как syslog-ng), которые занимаются разбором логов, анализом и т.д. Однако классические логи плохо подходят для автоматической обработки, сложны для парсинга, их формат постоянно меняется, а сообщения могут быть локализованны.
Авторы systemd journal предлагают для решения данной проблемы разделить сообщение на 2 части: понятную человеку и удобную для автоматической обработки. Кроме того предлагается дополнить сообщение важной информацией, которая раньше не всегда сохранялась. Предлагается вариант реализации, учитывающий удобство пользования как разработчиками ПО, так и администраторами.
Использование библиотеки libsystemd-journal
Пример отправки сообщения в лог:
#include <stdlib.h>
#include <systemd/sd-journal.h>
int main() {
int i=0, j=0;
while(i<10 && j<10) {
random()&1 ? ++i : ++j;
sd_journal_send(
"MESSAGE=(%d,%d)", i, j,
"MESSAGE_ID=51141ddad48f4924aef970b1eab2af42",
"I=%d", i,
"J=%d", j,
NULL
);
}
return 0;
}
В данном примере значения переменных i и j увеличиваются случайным образом. После каждой итерации значения I и J сохраняются в лог с помощью journal-протокола, функцией sd_journal_send библиотеки libsystemd-journal из пакета systemd.
Сборка может осуществляться через:
gcc -O2 -Wall -std=gnu99 -lsystemd-journal example.c -o example
При сохранении информации используются следующие идентификаторы:
- MESSAGE
-текстовое сообщение, для людей. Записи в логе будут выглядить как пары значений i и j в скобках: (3,4) - MESSAGE_ID, I, J
-для автоматической обработки. Под MESSAGE_ID обычно подразумевается UUID типа сообщения. Это позволяет легко отделить одни сообщения от других, даже если формат/набор данных совпадает. I и J-это уже бизнес-параметры, которые мы сохраняем как словарь <<ключ-значение>>.
Таким образом мы можем как угодно изменять форматирование сообщения пользователю без изменения данных для автоматической обработки.
Разбор логируемых данных
Для получения данных из лога можно использовать утилиту systemd-journalctl из пакета systemd, а можно написать свою (используя библиотеку libsystemd-journal). Следует учитывать, что journal хранится в бинарном виде, а формат и подход к хранению логов можно сравнить с некоторыми реляционными и нереляционными базами данных. Формат хранения может изменяться, но разработчки гарантируют возможнлость доступа к данным через библиотеку/утилиты systemd. Выбор бинарного хранилища позволяет хранить информацию более компактно, а также осуществлять быстрый и удобный поиск по любым параметрам сообщения.
systemd-journalctl поддерживает вывод информации в различных форматах: short, verbose, export (сообщение целиком), json (сообщение целиком в json-формате), cat (только <<пользовательское>> сообщение без дополнительных параметров). Утилита может показывать определённое количество сообщений, а также может быть запущенна в режиме <
В systemd-journal, если вы используете systemd, сохраняется так же все kernel/stdout/stderr/syslog-сообщения сервисов системы и ядра.
Рассмотрим одно сообщение из примера:
# systemd-journalctl -o json I=1 -n 1
[
{
".cursor" : "...",
".realtime" : 1337625703076274,
".monotonic" : 95084661530,
".boot_id" : "97af7b9ccc9341a78bff939661d1e53b",
"MESSAGE_ID" : "51141ddad48f4924aef970b1eab2af42",
"MESSAGE" : "(1,1)",
"I" : "1",
"J" : "1",
"_TRANSPORT" : "journal",
"_PID" : "6928",
"_UID" : "1001",
"_GID" : "1001",
"_COMM" : "ex1",
"_EXE" : "/home/max_posedon/Development/talks/systemd-journald/example",
"_CMDLINE" : "./ex1 param1",
"_SYSTEMD_CGROUP" : "/system/kdm@.service/tty7",
"_SYSTEMD_UNIT" : "kdm@tty7.service",
"_SOURCE_REALTIME_TIMESTAMP" : "1337625703074362",
"_BOOT_ID" : "97af7b9ccc9341a78bff939661d1e53b",
"_MACHINE_ID" : "be1598bd68baa268cb48e33d0000000f",
"_HOSTNAME" : "m_melnikau-vaio"
}
]
Здесь выполнен запрос одного сообщения (-n 1) в формате json и фильтрация сообщения по критерию I=1. Более подробную информацию можно получить, воспользовавшись командой man systemd-journalctl.
Рассмотрим подробнее сообщение в логе. В нем доступны следующие системные параметры:
- PID, UID, GID
-важные параметры, которые далеко не всегда логируются - COMM, EXE, CMDLINE
-описание того, какое приложение и как именно запускалась - SOURCE_REALTIME_TIMESTAMP
-время согласно приложению
Среди параметров, которые сохраняет сам демон journald - следующие:
- realtime
-время, когда сообщение попало в journald (немного позже, чем отметка времени, сделанная приложением) - monotonic
-системные часы иногда переводятся, и сохраненное значение монотонного таймера может оказаться важным для будущей отладки
И, наконец, бизнес-параметры:
- MESSAGE
-сообщение, понятное пользователю - MESSAGE_ID, I, J
-то же самое сообщение, но уже в виде, удобном для автоматической обработки - по параметрам MESSAGE_ID, I, J, а также по всем остальным удобно искать, фильтроват и агрегировать информацию
В последующих версиях systemd планируется расширить этот списко за счет следующих параметров:
- файл, строка, функция исходного файла, где вызывалась функция логирования
- audit и selinux контексты
Таким образом, объём сохраняемых данных многократно возрастает по сравнению с <<классическим>> подходом к логированию, но это не вызывает значительного роста занимаемого места благодаря бинарному формату и реляционному подходу к хранению данных. А семантический подход к хранению сообщений позволяет легко агрегировать, обрабатывать и находить необходимую информацию.
Заключение
Не факт, что systemd journald станет стандартом для логирования в мире Linux. Однако он демонстирует принципиально новый подход, решая современные проблемы автоматической обработки логов.
Текст тезисов доступен под лицензией Creative Commons Attribution-ShareAlike 3.0.
