Заметки о systemd, часть 4, системный журнал

Системный журнал

Ещё одно новшество от разработчиков и адаптаторов systemd (Леннарта Поттеринга, и тех, возможно, кто помогает ему в этой затее, и майнтеймеров свежих дистрибутивов) - это новая система ведения системного журнала Journal.

В одном из ранних сообщений о Journal утверждается следующее:

Journal будет частью systemd и не сможет использоваться обособленно. Все логи будут проиндексированы и хранится в специальной БД, к которой к сожалению будут неприменимы стандартные утилиты обработки текстовых файлов, такие как grep. Тем не менее, Journal не исключает параллельное использование традиционных syslog-служб, таких как rsyslog и syslog-ng.

Первым релизом, где осмелились опробовать Journal, как мне кажется, есть Fedora 17. Но и здесь интеграторам хватило здравого смысла (или не хватило смелости?) оставить работать две параллельно системы ведения журнала:

$ ps -A | grep journal
348 ? 00:00:00 systemd-journal

$ ps -A | grep log
...

667 ? 00:00:00 rsyslogd
...

Вот как видит соответствующие выполняющиеся сервисы сам systemd:

$ service rsyslog status
Redirecting to /bin/systemctl status  rsyslog.service
rsyslog.service - System Logging Service
 Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled)
 Active: active (running) since Tue, 23 Oct 2012 11:27:32 +0300; 1h 47min ago
Main PID: 639 (rsyslogd)
 CGroup: name=systemd:/system/rsyslog.service
 └ 639 /sbin/rsyslogd -n -c 5

$ service systemd-journald status

Redirecting to /bin/systemctl status  systemd-journald.service

systemd-journald.service - Journal Service

 Loaded: loaded (/usr/lib/systemd/system/systemd-journald.service; static)

 Active: active (running) since Tue, 23 Oct 2012 11:27:14 +0300; 1h 49min ago

   Docs: man:systemd-journald.service(8)

         man:systemd-journald.conf(5)

Main PID: 317 (systemd-journal)

 Status: "Processing requests..."

 CGroup: name=systemd:/system/systemd-journald.service

 └ 317 /usr/lib/systemd/systemd-journald

Служба system-journald при старте системы запущена существенно раньше традиционной rsyslog (PID). Система ведения журнала Journal записывает базу данных журнала (как теперь это называют разработчики) в формате, который теперь а).не текстовый и б).криптографированный. Если вы предварительно создадите каталог с именем /var/log/journal, то системный журнал будет записываться туда. Если такого каталога нет, то системный журнал будет записываться в /run/log/journal :

$ tree /run/log/journal

/run/log/journal

`-- dec47daacc0345f98702c28782126e50

    `-- system.journal

1 directory, 1 file

$ ls -l /run/log/journal/dec47daacc0345f98702c28782126e50/system.journal

-rw-r----- 1 root adm 413696 окт.  23 13:01 /run/log/journal/dec47daacc0345f98702c28782126e50/system.journal

В первом случае (/var/log/journal) журнал будет перманентным и будет сохраняться между сессиями перезагрузки, во втором (/run/log/journal - по умолчанию) журнал будет уничтожаться при завершении сессии.

P.S. Вообще то, отказ от текстового формата файла журнала - нарушение философии UNIX, где всегда считалось большим преимуществом текстовый формат всех конфигурационных и протокольных файлов. Подход Journal своей философией вызывает в памяти переход в Windows переход от набора файлов конфигураций к системному реестру.

Не пытайтесь непосредственно просматривать содержимое журнального файла, созданного Journal! Для просмотра и управления системным журналом созданы специальные утилиты, например systemd-journalctl (но, поскольку система находится в фазе активного развития и всё зыбко, то, наверняка, будут и другие средства) : 

# systemd-journalctl | tail -n5
Oct 19 17:01:01 notebook run-parts(/etc/cron.hourly)[6386]: finished mcelog.cron
Oct 19 17:11:30 notebook dbus-daemon[709]: dbus[709]: [system] Activating se...)
Oct 19 17:11:30 notebook dbus[709]: [system] Activating service name='org.f...r)
Oct 19 17:11:30 notebook dbus-daemon[709]: dbus[709]: [system] Successfully ...'
Oct 19 17:11:30 notebook dbus[709]: [system] Successfully activated service...t'

А поскольку у нас в системе работают две параллельные и независимые системы ведения системного журнала, то они создают очень похожий, но не идентичный набор записей журнала (в /var/log/messages нет записи с меткой 17:01:01 - /etc/cron.hourly):

# cat /var/log/messages | tail -n5
Oct 19 16:23:29 notebook dbus-daemon[709]: ** Message: No devices in use, exit
Oct 19 17:11:30 notebook dbus-daemon[709]: dbus[709]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Oct 19 17:11:30 notebook dbus[709]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Oct 19 17:11:30 notebook dbus-daemon[709]: dbus[709]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Oct 19 17:11:30 notebook dbus[709]: [system] Successfully activated service 'org.freedesktop.PackageKit'

Журнал с точки зрения программного кода

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

#include <stdio.h>
#include <stdlib.h>
#include <syslog.h>

int main( int argc, char **argv, char **envp ) {
   int i;
   openlog( argv[ 0 ], LOG_NDELAY, LOG_USER );
   // LOG_EMERG=0, LOG_ALERT=1, LOG_CRIT=2, LOG_ERR= 3
   // LOG_WARNING=4, LOG_NOTICE=5, LOG_INFO=6, LOG_DEBUG=7
   for( i = LOG_EMERG; i <= LOG_DEBUG; i++ ) {
      syslog( i, "log. level = %d", i );
      printf( "done: log. level = %d\n", i );
   }
   closelog();
   return( EXIT_SUCCESS );
}

Предварительно скомпилировав, выполним эту программу:

$ ./mylogs 
done: log. level = 0

done: log. level = 1
done: log. level = 2
done: log. level = 3
done: log. level = 4
done: log. level = 5
done: log. level = 6
done: log. level = 7
$ 
Message from syslogd@notebook at Oct 23 21:44:16 ...
 ./mylogs: log. level = 0

И вот что мы обнаружим в двух журналах, формируемых двумя различными механизмами (сервисами):

$ sudo systemd-journalctl | tail -n9 
Oct 23 21:44:16 notebook ./mylogs[8227]: log. level = 0
Oct 23 21:44:16 notebook ./mylogs[8227]: log. level = 1
Oct 23 21:44:16 notebook ./mylogs[8227]: log. level = 2
Oct 23 21:44:16 notebook ./mylogs[8227]: log. level = 3
Oct 23 21:44:16 notebook ./mylogs[8227]: log. level = 4
Oct 23 21:44:16 notebook ./mylogs[8227]: log. level = 5
Oct 23 21:44:16 notebook ./mylogs[8227]: log. level = 6
Oct 23 21:44:16 notebook ./mylogs[8227]: log. level = 7
Oct 23 21:44:56 notebook sudo[8234]: olej : TTY=pts/5 ; PWD=/home/olej/2012...tl

$ sudo cat /var/log/messages | tail -n7

Oct 23 21:44:16 notebook ./mylogs: log. level = 0

Oct 23 21:44:16 notebook ./mylogs: log. level = 1

Oct 23 21:44:16 notebook ./mylogs: log. level = 2

Oct 23 21:44:16 notebook ./mylogs: log. level = 3

Oct 23 21:44:16 notebook ./mylogs: log. level = 4

Oct 23 21:44:16 notebook ./mylogs: log. level = 5

Oct 23 21:44:16 notebook ./mylogs: log. level = 6

Как видно, результат программного вызова syslog() поступает в обе журнальные системы, но обрабатывается ними несколько по-разному:

• сообщение уровня 0 (LOG_EMERG) на терминал задублировано только журнальным сервисом rsyslog;
• порог занесения сообщений в журнал 6 (LOG_INFO), установленный для rsyslog (в конфигурационном файле /etc/rsyslog.conf) не действует для systemd-journald;