systemd in Action. Part 3

Ivan Shapovalov, Like-all, Pavlo Rudyi

Part 1 • Part 2 • Part 4

Journal - гибкий сборщик и хранитель системных сообщений. Он обрабатывает сообщения ядра, initrd, системных и пользовательских сервисов. Для начала стоит упомянуть, что его можно отключить и перенаправлять все логи в традиционный сервис syslog(опция ForwardToSyslog) или же использовать одновременно journal и syslog. Начиная с systemd версии 216 эта опция была отключена по-умолчанию, так как rsyslog и syslog-ng уже могут читать самостоятельно сообщения journal. Конфигурация journald хранится в /etc/systemd/journal.conf, а сами логи могут храниться как на диске(в директории /var/log/journal), так и в оперативной памяти или не храниться вообще. Рассмотрим основные опции конфигурационного файла journald:

Storage=	"volatile" — данные journal будут храниться только в оперативной памяти, точнее в каталоге /run/log/journal. "persistent" — данные будут храниться на диске в директории /var/log/journal, но во время ранней загрузки будут находиться в оперативной памяти. "auto" аналогично "persistent", но директория /var/log/journal не будет создана по необходимости. В случае недоступности директории /var/log/journal записи будут храниться в оперативной памяти. "none" выключает поддержку хранения логов, все данные будут уничтожены, но форвардинг в другие сервисы обработки логов будет работать.
Compress=	включает или выключает сжатие журнала
Seal=	настройка шифрования логов с помощью Forward Secure Sealing при условии, что ключ сгенерирован командой
SplitMode=	"uid" - сообщения каждого пользователя пишутся в отдельный файл, "login" - соответственно каждого залогиненого пользователя в системе, или "none" - нет разбиения по таким критериям.
RateLimitInterval=, RateLimitBurst=	Настройка ограничения скорости генерации сообщений. По умолчанию установлено значение 1000 сообщений за 30 секунд.
SystemMaxUse=, SystemKeepFree=, SystemMaxFileSize=, RuntimeMaxUse=, RuntimeKeepFree=, RuntimeMaxFileSize=	Ограничение на размер файлов данных journald. RuntimeMaxUse относится к хранению в оперативной памяти, System - к дисковому хранилищу. Данные опции относятся только к файлам "*.journal" или "*.journal ~".
MaxFileSec=	Максимальное время хранения отдельного файла журнала без ротации
MaxRetentionSec=	Максимальное время хранения записей журнала
SyncIntervalSec=	Интервал перед синхронизацией записей журнала на диск
ForwardToSyslog=, ForwardToKMsg=, ForwardToConsole=, ForwardToWall=	Настройки форвардинга сообщений. При перенаправлении в консоль можно указать TTY c помощью опции TTYPath=.
MaxLevelStore=, MaxLevelSyslog=, MaxLevelKMsg=, MaxLevelConsole=, MaxLevelWall=	Настройка типа регистрируемых сообщений( "emerg", "alert", "crit", "err", "warning", "notice", "info", "debug", или их значений 0..7) Сообщения ниже или ровно указанного уровня пересылаются, а уровнем выше - отбрасываются.

Вывод логов. Вопреки сложившемуся мнению о чрезвычайной сложности и хрупкости работы с логами в systemd,
дело обстоит совершенно наоборот. Но если беда таки случилась и прочитать логи с помощью journalctl невозможно,
на помощь спешит старая добрая утилита strings:

$ strings /var/log/journal/12a62e9e12db4c6db3ac88797aa9460e/system.journal | grep -i message | head
MESSAGE=Runtime journal is using 8.0M (max allowed 91.2M, trying to leave 136.8M free of 904.5M available
MESSAGE
MESSAGE_ID=ec387f577b844b8fa948f33cad9a75e6
MESSAGE_ID
MESSAGE=CPU0 microcode updated early to revision 0x1b, date = 2014-05-29
MESSAGE=Initializing cgroup subsys cpuset
MESSAGE=Initializing cgroup subsys cpu
MESSAGE=Initializing cgroup subsys cpuacct
MESSAGE=Linux version 4.0.0-0.rc2.git0.1.fc22.x86_64 (mockbuild@bkernel01.phx2.fedoraproject.org) (gcc version 5.0.0 20150226 (Red Hat 5.0.0-0.18) (GCC) ) #1 SMP Tue Mar 3 21:24:17 UTC 2015

Перейдем к освещению работы утилиты journalctl, основной функцией которой является вывод логов в терминал.
Для начала достаточно запустить journalctl c правами суперпользователя(в некоторых случаях может работать от простого пользователя в зависимости от политик конкретного дистрибутива):

# journalctl

Сразу становится заметным неоднородность форматирования. Строки с приоритетами "emerg" (0), "alert" (1), "crit" (2), "err" (3) подсвечены красным цветом, "warning" (4), "notice" (5) - выделены жирным шрифтом. Также пространство между загрузками системы размечено специальной строкой. Рассмотрим наиболее интересные возможности journalctl:

-a	Показать данные полностью без обрезания строк
-b	Вывод информации начиная с момента последней загрузки
-e	Сразу перенести pager в конец вывода
-f	Вывод сообщений в реальном времени
-u	Вывод информации только об одном юните (напр., -u sshd)
-p	Вывод сообщений по приоритету (напр., -p err)
--since --until	Удобная сортировка по времени (напр., --since=yesterday)
-n	Число выводимых записей
-r, --reverse	Вывести сообщения в обратном порядке
--utc	Синхронизация вывода с UTC
-m, --merge	Вывести данные со всех доступных журналов, в том числе и от удаленных хостов
-k, --dmesg	Вывести только сообщения ядра
-c, --cursor=	Показать сообщения начиная от указанной позиции курсора
--system, --user	Показать соответственно системные или пользовательские сообщения
-M, --machine=	Показать сообщения от локального рабочего контейнера
--flush	Принудительная запись сообщений, которые хранятся в оперативной памяти, на диск
-o, --output=	Настройка формата вывода
-o short	Выводит сообщения в формате идентичном syslog
-o short-iso	Формат ISO 8601
-o short-precise	Вывод вместе с микросекундной временной разметкой
-o short-monotonic	Вывод с добавлением монотонных временных меток
-o verbose	Вывод полной структуры вместе с метаданными
-o export	Вывод в особый бинарный формат, удобный для резервного копирования
-o json, -o json-pretty, -o json-sse	Вывод в формат json, c опциями улучшения читаемости и поддержкой Server-Sent Events
--setup-keys	Генерация ключа для подписи логов
--verify	Проверка логов на целостность
--verify-key	Проверка подписанных логов на целостность

А теперь давайте перейдем к активным действиям. Например, у нас возникли проблемы с DHCP-клиентом и нужна информация:

# journalctl /sbin/dhclient
Mar 04 22:36:56 localhost.localdomain dhclient[987]: Created duid \000\001\000\001\034\212)h\224\336\200\032\332\257.
Mar 04 22:36:56 localhost.localdomain dhclient[987]: DHCPDISCOVER on enp2s0 to 255.255.255.255 port 67 interval 4 (xid=0x40438e34)
Mar 04 22:36:57 localhost.localdomain dhclient[994]: XMT: Solicit on enp2s0, interval 1040ms.
Mar 04 22:36:57 localhost.localdomain dhclient[994]: RCV: Advertise message on enp2s0 from fe80::fad1:11ff:fe5c:ba93.

Не лишним будет упомянуть также о поддержке автодополнения:

# journalctl -F _S
_SELINUX_CONTEXT            _SYSTEMD_CGROUP             _SYSTEMD_SESSION            
_SOURCE_REALTIME_TIMESTAMP  _SYSTEMD_OWNER_UID          _SYSTEMD_UNIT 
journalctl _KERNEL_DEVICE=
+acpi:device:00           c189:46                   c189:84                   +scsi:15:0:0:1
+acpi:device:01           c189:47                   c189:85                   +scsi:16:0:0:0
...

Можно также вывести логи в формат json:

# journalctl -o json
{ "__CURSOR" : "s=1481bf6822c54ab7ae8cf606110e57ef;i=1;b=e3c6b53b76154b1cbb268a9f4e69b951;m=94f2b42b;t=504476ebcbda2;x=2edc00512fc9b015", "__REALTIME_TIMESTAMP" : "1412079730605474", "__MONOTONIC_TIMESTAMP" : "2498933803", "_BOOT_ID" : "e3c6b53b76154b1cbb268a9f4e69b951", "PRIORITY" : "6", "_TRANSPORT" : "driver", "MESSAGE" : "Permanent journal is using 8.0M (max allowed 1.8G, trying to leave 2.7G free of 11.8G available \uffffffe2\uffffff86\uffffff92 current limit 1.8G).", "MESSAGE_ID" : "ec387f577b844b8fa948f33cad9a75e6", "_PID" : "4345", "_UID" : "0", "_GID" : "0", "_COMM" : "systemd-journal", "_EXE" : "/usr/lib/systemd/systemd-journald", "_CMDLINE" : "/usr/lib/systemd/systemd-journald", "_CAP_EFFECTIVE" : "4402800cf", "_SYSTEMD_CGROUP" : "/system.slice/systemd-journald.service", "_SYSTEMD_UNIT" : "systemd-journald.service", "_SYSTEMD_SLICE" : "system.slice", "_SELINUX_CONTEXT" : "system_u:system_r:syslogd_t:s0", "_MACHINE_ID" : "2d60315531d6490297c146d9f1d42323", "_HOSTNAME" : "localhost.localdomain" }

Экспорт журнала в файл:

# journalctl -o export > logfile

Journal записывает метаданные с дополнительной информацией:

# journalctl -o verbose -n1
Tue 2015-03-17 12:39:40.660000 EET [s=66e1d194a2f64e2cb07e9f77febad66f;i=15f3b;b=4c7ca0fa14fc4cd6be38b25a1e4e927b;m=30
    _UID=0
    _MACHINE_ID=2d60315531d6490297c146d9f1d42323
    _HOSTNAME=localhost.localdomain
    _TRANSPORT=audit
    _PID=1
    _AUDIT_LOGINUID=4294967295
    _AUDIT_SESSION=4294967295
    AUDIT_FIELD_COMM=systemd
    AUDIT_FIELD_EXE=/usr/lib/systemd/systemd
    AUDIT_FIELD_HOSTNAME=?
    AUDIT_FIELD_ADDR=?
    AUDIT_FIELD_TERMINAL=?
    AUDIT_FIELD_RES=success
    _AUDIT_TYPE=1131
    _SELINUX_CONTEXT=system_u:system_r:init_t:s0
    AUDIT_FIELD_UNIT=NetworkManager-dispatcher
    MESSAGE= pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=Network
    _AUDIT_ID=558
    _BOOT_ID=4c7ca0fa14fc4cd6be38b25a1e4e927b
    _SOURCE_REALTIME_TIMESTAMP=1426588780660000

Флаг '-o verbose' позволяет нам увидеть системные сообщения вместе с метаданными. Это в основном текст в кодировке UTF-8, но также поддерживаются большие бинарные вставки. Давайте воспользуемся одним из индексов базы данных journald для поиска нужной нам информации:

# journalctl -b _PID=1 -n5
Mar 17 12:39:40 localhost.localdomain unknown[1]:  pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_
Mar 17 12:48:22 localhost.localdomain systemd[1]: Starting Network Manager Script Dispatcher Service...
Mar 17 12:48:22 localhost.localdomain systemd[1]: Started Network Manager Script Dispatcher Service.
Mar 17 12:48:22 localhost.localdomain unknown[1]:  pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_
Mar 17 12:48:33 localhost.localdomain unknown[1]:  pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_

Мы вывели пять последних сообщений из текущей сессии загрузки системы, касающиеся PID1, то есть systemd. Рассмотрим более сложный вариант, когда нам нужна информация о PID 1 и 100 на текущей машине и информация о процессе NetworkManager на хосте host125:

# journalctl -b _PID=1 _PID=100 + HOST=host125 COMM=NetworkManager

Также доступна фильтрация в виде категорий syslog:

# journalctl -f -l SYSLOG_FACILITY=10
Mar 21 20:21:22 localhost.localdomain unix_chkpwd[3843]: password check failed for user (root)
Mar 21 20:21:22 localhost.localdomain su[3841]: pam_unix(su-l:auth): authentication failure; logname=paul uid=1000 euid=0 tty=pts/1 ruser=paul rhost=  user=root
Mar 21 20:21:22 localhost.localdomain su[3841]: pam_succeed_if(su-l:auth): requirement "uid >= 1000" not met by user "root"
Mar 21 20:21:31 localhost.localdomain su[3851]: pam_unix(su-l:session): session opened for user root by paul(uid=1000)
Mar 21 21:15:29 localhost.localdomain su[3851]: pam_unix(su-l:session): session closed for user root
Mar 21 21:15:37 localhost.localdomain unix_chkpwd[5316]: password check failed for user (root)
Mar 21 21:15:37 localhost.localdomain su[5312]: pam_unix(su-l:auth): authentication failure; logname=paul uid=1000 euid=0 tty=pts/2 ruser=paul rhost=  user=root
...

Посмотреть все значения одного отдельного атрибута довольно просто:

# journalctl -F _COMM
unix_chkpwd
seahorse
evolution-calen
Xwayland
totem
swapoff
su
evolution-addre
run-parts
systemd-tmpfile
Gecko_IOThread
gnome-pty-helpe
bash
...

Так мы получили список всех значений COMM — полный список всех процессов, которые когда-либо писали сообщения в журнал.
Рассмотрим главные метаданные журнала:

__CURSOR=	Описывает текущую позицию в журнале, строковый тип данных
__REALTIME_TIMESTAMP=	Временная метка, описывает точное время получения сообщения журналом
MESSAGE=	Основной текст сообщения, в читаемом человеком формате
MESSAGE_ID=	128-битный уникальный идентификатор сообщения
PRIORITY=	Приоритет сообщения между 0 и 7, описывался выше
_TRANSPORT=	Описывает источник получения сообщения; значения - driver, syslog, journal, stdout, kernel

Рассмотрим подпись логов и qr-code. Само подписывание позволяет улучшить безопасность вашей системы, так как возможности модифицировать логи и скрыть следы присутствия или других нехороших вещей у злоумышленника не будет.

Для начала сгенерируем пару ключей:

# journalctl --setup-keys
Generating seed...
Generating key pair...
Generating sealing key...

The new key pair has been generated. The secret sealing key has been written to
the following local file. This key file is automatically updated when the
sealing key is advanced. It should not be used on multiple hosts.

 /var/log/journal/2d60315531d6490297c146d9f1d42323/fss

Please write down the following secret verification key. It should be stored
at a safe location and should not be saved locally on disk.

 36845c-867910-d1efb2-e67cc1/18319a-35a4e900

The sealing key is automatically changed every 15min.

The keys have been generated for host localhost.localdomain/2d60315531d6490297c146d9f1d42323.

To transfer the verification key to your phone please scan the QR code below:

█████████████████████████████████████████████████
█████████████████████████████████████████████████
████ ▄▄▄▄▄ █▀▄▄▄█  ▀▀ ▀▄█▄ ▄▄ ▄▀▀▀█▄▀█ ▄▄▄▄▄ ████
████ █   █ █▀█▀█ ▄▀▄ ▄▄█▀█▀█ ▄▀  ▀▄███ █   █ ████
████ █▄▄▄█ █▀▄ ▀▀▀█ ▀█ ▀▄▀█ ▀▀▀▄▄█ ▄▄█ █▄▄▄█ ████
████▄▄▄▄▄▄▄█▄█ █ █▄▀▄█ ▀ ▀ ▀▄█▄█▄█ █ █▄▄▄▄▄▄▄████
████ ▄ ▄▄█▄▄▄ █▄▄▄▄▄▄▄▄ ▄█▄ ▀ ▀▄▀▄ ▀▄▄▀▄▀▄█ █████
████▀ █▄▄▄▄██▄▀▄ █▀    █▄ █▀▀▄█  █▀█▄▀▄▀ ▄▄▀█████
█████▀ ▄▄ ▄▄ █▄█▄█▀ ▀▀█▄   ██▄ ▀▀ ▀ ▀▀▄▀▀▄ █▀████
████ █▄▄  ▄▀▀▀▀ ▄█▄█▀▄█▄█ ▀▄ ▄ ▀▀███████▄███▀████
████▀▀▄▄▄▄▄▄██ ▄ ▀▀█▀▄▀ ▄██▀▀ ▄██▄▀ ▄▀▀▄▀▄ ▄▀████
█████▄  ▄█▄██▄▄█  ▄▄▀  █ ▄▄█  █▄█▄▀▀  ▄█▄█▄▀▄████
████▄▄ ██▄▄▄▀█▄█▀█▄▀▄▀██▀▄ ▄██   ▄█▀▀█▀▀▀█ ▄▀████
█████ ▄  ▀▄  ▄▀█▀██ ▄██▄█  ▄ ▄▀▀██▀██▄▀█▀▀ ▀▀████
████▄█▀█  ▄▄██ ▀ ▄█▄▀ ▀ ▀█▀ ▀ ▄█▄▄▄ ▄ ▀▄▀▀ ▀█████
████ ▀▀ █▀▄▄▄ ▄ ██▀ ▄█▀█▀▄██▀▀█▄█ ▀▀▀ ▀▀▀▄▄ ▄████
████ █▄▀▄▀▄▄▀ ▀▄▄█▀▀▀█ █   ███ ▄▀███▀▀▄▀▀█  ▀████
████ █ █▀▀▄▄▄██ ▄▄██▀█▄ █▀▀  ▄▀█▀█▄ ██▄▀▀▀█▀█████
████▄█▄██▄▄█ ██▄▄▀ █▀ ▀▀▄█▀▀▀ ▀▄▀▄▀▀ ▄▄▄  ▀▀ ████
████ ▄▄▄▄▄ █▄▄▀ ▄ ▄ █ ▀█▄█▄▀█ ▄▄▀▀ ▄ █▄█ ▄▄▄▀████
████ █   █ █ ▄▄█▀▀▄▀▄█▀█▀ ▄▄▄█▄▄▀███▄ ▄ ▄▄ ▄ ████
████ █▄▄▄█ █ ▀██▀▄▀ ▄▄▄ ▀   ▄█▀█▀███ █ ▀▄▀  █████
████▄▄▄▄▄▄▄█▄███▄▄█▄█▄████▄█▄▄███▄█▄█▄██▄████████
█████████████████████████████████████████████████
█████████████████████████████████████████████████

Ура, мы получили ужасный qr-код, внедрение которого в systemd наделало столько шума. Но на самом деле цель его проста: верификационный ключ не должен храниться на машине в открытом виде, а храниться только на машине, на которой собственно подписываются логи. А сам ключ можно легко считать с помощью телефона. Если же qr-code по-прежнему вызывает у вас ужас и отвращение, то можно получить ключ в открытом виде:

# journalctl --setup-keys --force | cat
Generating seed...
Generating key pair...
Generating sealing key...
684fce-7a825e-ed34f1-39eaf9/18319b-35a4e900

Один из пары ключей записывается в /var/log/journal, а второй выводится на екран в виде qr-кода или текста.

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

# journalctl --verify --verify-key '684fce-7a825e-ed34f1-39eaf9/18319b-35a4e900'

Иногда полезно посмотреть размер данных journal:

# journalctl --disk-usage
Archived and active journals take up 128.0M on disk.

В следующей части мы продемонстрируем чтение поврежденного журнала и транспортирование логов между хостами.

Part 1 • Part 2

Примечание: комментарии лучше оставлять на основном сайте.

Part 1 • Part 2 • Part 4