17. Работа с Journal

В свое время, я уже рассказывал о некоторых возможностях journal (см. главу 13), доступных из утилиты systemctl. Сейчас я попробую рассказать о journal более подробно, с упором на практическое применение его возможностей.
Если вы еще не в курсе, что такое journal: это компонент systemd, регистрирующий сообщения из системного журнала (syslog), сообщения ядра (kernel log) и initrd, а также сообщения, которые процессы служб выводят на STDOUT и STDERR. Полученная информация индексируется и предоставляется пользователю по запросу. Journal может работать одновременно с традиционными демоном syslog (например, rsyslog или syslog-ng), либо полностью его заменять. Более подробно см. в первом анонсе. Journal был включен в Fedora начиная с F17. В Fedora 18 journal вырос в мощный и удобный механизм работы с системным журналом. Однако, и в F17, и в F18 journal по умолчанию сохраняет информацию только в небольшой кольцевой буфер в каталоге /run/log/journal. Как и все содержимое каталога /run, эта информация теряется при перезагрузке (прим. перев.: разумеется, это никак не относится к традиционному демону системного лога, даже если он работает поверх journal). Такой подход сильно ограничивает использование полезных возможностей journal, однако вполне достаточен для вывода актуальных сообщений от служб в systemctl status. Начиная с Fedora 19, мы собираемся включить сохранение логов на диск, в каталог /var/log/journal. При этом, логи смогут занимать гораздо больше места (прим. перев.: в journal отдельно задаются ограничения на размер для логов во временном хранилище (/run) и в постоянном (/var). При превышении лимита старые журналы удаляются. Так как /run размещается на tmpfs, т.е. в оперативной памяти, для временного хранения по умолчанию установлены более жесткие ограничения. При необходимости, соответствующие настройки можно задать в файле journald.conf.), а значит, смогут вместить больше полезной информации. Таким образом, journal станет еще более удобным.

17.1 Сохранение логов на диск
В F17 и F18 вы можете включить сохранение логов на диск вручную:


# mkdir -p /var/log/journal


После этого рекомендуется перезагрузить систему, чтобы заполнить журнал новыми записями.
Так как теперь у вас есть journal, syslog вам больше не нужен (кроме ситуаций, когда вам совершенно необходимо иметь /var/log/messages в текстовом виде), и вы спокойно можете удалить его:


# yum remove rsyslog


17.2 Основы
Итак, приступим. Нижеприведенный текст демонстрирует возможности systemd 195, входящего в Fedora 18, так что, если некоторые из описанных трюков не сработают в F17 — пожалуйста, дождитесь F18.
Начнем с основ. Доступ к логам journal осуществляется через утилиту journalctl(1).
Чтобы просто взглянуть на лог, достаточно ввести


# journalctl


Если вы выполнили эту команду с полномочиями root, вы увидите все журнальные сообщения, включая исходящие как от системных компонентов, так и от залогиненных пользователей. Вывод этой команды форматируется в стиле /var/log/messages, но при этом добавлены кое-какие улучшения:

* Строки с приоритетом error и выше подсвечены красным.
* Строки с приоритетом notice и warning выделены жирным шрифтом.
* Все отметки времени сформированы с учетом вашего часового пояса.
* Для навигации по тексту используется просмотрщик (pager), по умолчанию less.
* Выводятся все доступные данные, включая информацию из файлов, прошедших ротацию (rotated logs).
* Загрузка системы отмечается специальной строкой, отделяющей записи, сгенерированные между (пере)загрузками.

Отметим, что в данной статье не приводятся примеры такого вывода — прежде всего, для краткости изложения, но также и для того, чтобы дать вам повод поскорее попробовать Fedora 18 с systemd 195. Надеюсь, отсутствие таких примеров не помешает вам уловить суть.

17.3 Контроль доступа
Итак, мы получили удобный и эффективный метод просмотра логов. Но для полного доступа к системным сообщениям требуются привилегии root, что не всегда удобно — в наше время администраторы предпочитают работать от имени непривилегированного пользователя, переключаясь на root только при крайней необходимости. По умолчанию, непривилегированные пользователи могут просматривать в journal только свои собственные логи (сообщения, сгенерированные их процессами). Чтобы предоставить пользователю доступ ко всем системным логам, нужно включить его в группу adm:


# usermod -a -G adm lennart


Разлогинившись, а затем вновь залогинившись под именем lennart58, я могу просматривать сообщения от всех пользователей и системных компонентов:


# journalctl


17.4 Отслеживание логов в реальном времени
Когда вы запускаете программу journalctl без параметров, она выводит все сообщения, сгенерированные на текущий момент, и возвращает управление оболочке. Однако, иногда бывает полезно отслеживать их появление в режиме реального времени. В классической реализации rsyslog это осуществлялось командой tail -f /var/log/messages.
В journal ее аналог выглядит так:


$ journalctl -f


И работает он точно так же: выводит последние десять сообщений, после чего переходит в режим ожидания, и выводит новые сообщения по мере их появления.

17.5 Простейшие методы выборки записей
При вызове journalctl без параметров, она выводит все сообщения, начиная с самого первого из сохраненных. Разумеется, это огромный объем информации. На практике иногда бывает достаточно ограничиться сообщениями, сгенерированными с момента последней загрузки системы:


$ journalctl -b


Но часто даже после такой фильтрации записей остается довольно много. Что ж, мы можем ограничиться только наиболее важными. Итак, все сообщения с приоритетом error и выше, начиная с момента последней загрузки:


$ journalctl -b -p err


Если вы уже успели перезагрузить систему после того, как произошли интересующие вас события, целесообразнее будет воспользоваться выборкой по времени:


$ journalctl --since=yesterday


В результате мы увидим все сообщения, зарегистрированные начиная со вчерашнего дня вплоть до настоящего момента. Прекрасно! Разумеется, этот критерий отбора можно комбинировать с другими, например, с -p err. Но, допустим, нам нужно узнать о чем-то, что случилось либо 15-го октября, либо 16-го:


$ journalctl --since=2012-10-15 --until="2011-10-16 23:59:59"


Отлично, мы нашли то, что искали. Но вот вам сообщают, что сегодня ранним утром наблюдались проблемы с CGI-скриптами Apache. Ладно, послушаем, что нам скажет индеец:


$ journalctl -u httpd --since=00:00 --until=9:30


Да, мы нашли это. Хм, похоже, что причиной стала проблема с диском /dev/sdc. Посмотрим, что с ним случилось:


$ journalctl /dev/sdc


Кошмар, ошибка ввода-вывода! Нужно срочно заменить диск, пока не начались более серьезные проблемы. Ладно, пойдем дальше. Что у нас там случилось с процессом vpnc?


$ journalctl /usr/sbin/vpnc


Хм, ничего подозрительного. Но, кажется, проблема где-то во взаимодействии между vpnc и dhclient. Посмотрим объединенный и отсортированный по времени список сообщений от этих процессов:


$ journalctl /usr/sbin/vpnc /usr/sbin/dhclient


Отлично, мы нашли причину проблемы!

17.6 Продвинутые методы выборки
Да, это все, конечно, здорово, но попробуем подняться еще на ступеньку выше. Чтобы понять описанные ниже приемы, нужно знать, что systemd добавляет к каждой лог-записи ряд скрытых метаданных. Эти метаданные по структуре напоминают набор переменных окружения, хотя на самом деле дают даже больше возможностей: во-первых, метаданные могут включать большие бинарные блоки данных (впрочем, это скорее исключение — обычно они содержат текст в кодировке UTF-8), и во-вторых, в пределах одной записи поле метаданных может содержать сразу несколько значений (и это тоже встречается нечасто — обычно поля содержат по одному значению). Эти метаданные автоматически собираются и добавляются для каждой лог-записи, безо всякого участия пользователя. И вы легко можете их использовать для более тонкой выборки записей.
Посмотрим, как они выглядят:

(Чтобы не утомлять вас огромным количеством текста, ограничимся одной записью. Ключ -n позволяет задать число выводимых записей, в нашем случае 1. Если указать его без параметра, будут показаны 10 последних записей.)

Задав параметр -o verbose, мы переключили формат вывода — теперь, вместо скупых строчек, копирующих /var/log/messages, для каждой записи выводится полный перечень всех метаданных. В том числе, информация о пользователе и группе, контекст SELinux, идентификатор компьютера и т.д. Полный список общеизвестных полей метаданных приведен на соответствующей странице руководства. База данных Journal индексируется по всем этим полям! И мы можем использовать любое из них в качестве критерия выборки:


$ journalctl _UID=70


Как нетрудно догадаться, в результате будут выведены все сообщения от процессов пользователя с UID 70. При необходимости, критерии можно комбинировать:


$ journalctl _UID=70 _UID=71


Указание нескольких значений для одного и того же поля эквивалентно логическому ИЛИ. Таким образом, будут выведены записи как от процессов с UID 70, так и от процессов с UID 71.


$ journalctl _HOSTNAME=epsilon _COMM=avahi-daemon


А вот указание нескольких различных полей дает эффект логического И. В результате, будут выведены записи только от процесса avahi-daemon, работающего на хосте с именем epsilon. Но мы этим не ограничимся! Мы же суровые компьютерщики, нам нужны сложные логические выражения!


$ journalctl _HOSTNAME=theta _UID=70 + _HOSTNAME=epsilon _COMM=avahi-daemon


При помощи плюса мы можем явно задать логическое ИЛИ, применяя его к разным полям и даже И-выражениям. Поэтому наш пример выведет как записи с хоста theta от процессов с UID 70, так и с хоста epsilon от процесса avahi-daemon (прим. перев.: стоит отметить, что приоритет логических операций стандартный: сначала выполняются операции И, и только потом — операции ИЛИ. Используемая в journalctl система записи выражений аналогична принятой в классической алгебре: умножение, имеющее более высокий приоритет, не указывается знаком операции, а обозначается просто последовательной записью величин).

17.7 И немного магии
Уже неплохо, правда? Но есть одна проблема — мы же не сможем запомнить все возможные значения всех полей журнала! Для этого была бы нужна очень хорошая память. Но journalctl вновь приходит к нам на помощь:


$ journalctl -F _SYSTEMD_UNIT


Эта команда выведет все значения поля _SYSTEMD_UNIT, зарегистрированные в базе данных журнала на текущий момент. То есть, имена всех юнитов systemd, которые писали что-либо в журнал. Аналогичный запрос работает для всех полей, так что найти точное значение для выборки по нему — уже не проблема. Но тут самое время сообщить вам, что эта функциональность встроена в механизм автодополнения оболочки (прим. перев.: в исходной статье речь идет только о bash, однако, начиная с релиза systemd 196, аналогичная функциональность доступна и для zsh)! Это же просто прекрасно — вы можете просмотреть перечень значений поля и выбрать из него нужно прямо при вводе выражения. Возьмем для примера метки SELinux. Помнится, имя поле начиналось с букв SE. . .


$ journalctl _SE


и оболочка сразу же дополнит:


$ journalctl _SELINUX_CONTEXT=


Отлично, и какое там значение нам нужно?

Ага, нас интересуют записи с меткой PolicyKit! Пользуясь дополнением, вводим:


$ journalctl _SELINUX_CONTEXT=system_u:system_r:policykit_t:s0


Очень просто, не правда ли! Пожалуй, самое простое из действий, связанных с SELinux ;-) Разумеется, такое дополнение работает для всех полей Journal.
На сегодня все. Впрочем, на странице руководства journalctl(1) можно узнать и о многих других возможностях, не описанных здесь. Например, о том, что journalctl может выводить данные в формате JSON, или в формате /var/log/messages, но с относительными метками времени, как в dmesg.

Содержание
Вперед - Управление ресурсами с помощью cgroups
Назад - Запуск getty на последовательных (и не только) консолях