Журналирование в systemd

1. Доступ к журналу
2. Чтение журнала
2.1 Просмотр логов по сети
3. Запись в журнал
4. Поиск информации в журнале
5. Примеры ведения лога в скрипте
(это не подробное руководство, здесь лишь описаны некоторые основные аспекты использования журнала в systemd)

1. Доступ к журналу
для доступа к журналу пользователь должен входить в одну из трёх групп: wheel, adm или systemd-journal.
Добавить пользователя в группу:
gpasswd -a $USER wheel
Чтобы посмотреть группы в которые входит пользователь наберите groups $USER
Также журнал доступен из под рута напрямую(su) либо косвенно(через sudo).
Файлы журнала располагаются по адресу:
/var/log/journal/... - находиться на жёстком диске, при удалении этой папки логи после перезагрузки пушиться в /run/log/journal/
вместо перезагрузки можно перезапустить сервис
systemctl restart systemd-journald
либо
/run/log/journal/... - находиться в оперативной памяти, как следствие полностью стирается после каждой перезагрузки компа.

Хочу заметить что иногда может возникнуть проблема с доступом к журналу из за того что все или часть файлов в папке с логами принадлежит группе root вместо группы systemd-journal.
Чтобы исправить это меняем группу:
chown -Rf root:systemd-journal /{var,run}/log/journal

Один из способов копирования логов с удалённого хоста имея ssh-доступ в текущую папку:
scp -r [email protected]:/var/log/journal .
естественно вместо [email protected] ставим нужные данные

2. Чтение журнала
Так как логи у нас хранятся в бинарном виде то для просмотра нужна утилита из состава systemd - journalctl.
Вывод последних 20-и (по умолчанию 10) сообщений из журнала:
journalctl -n 20
Отслеживания логов в реальном времени, предварительно также выводит последние 10 сообщений:
journalctl -f
Вывод всех сообщений с момента одной из последних загрузок:
journalctl -b    # последняя загрузка
journalctl -b -1    # предыдущая загрузка
...
journalctl -b -N    # N-я загрузка считаю от последней
Также при выводе можно указать приоритет выводимых сообщений (про виды приоритетов написано ниже):
journalctl -b -p 3    # выведет сообщения с последней загрузки приоритеты которых 3 и выше(2,1,0)
Показывает все сообщения определённого процесса:
journalctl _PID=N # где N номер процесса
Просмотр всех метаданных указанного процесса:
journalctl -o verbose _PID=N # где N номер процесса
Чтобы прочитать файлы журнала находящиеся не в стандартной директории (к примеру, скопировали логи с другого компа):
journalctl -D путь/к/папке/с/логами
более подробно можно глянуть в ArchWiki Journal

2.1 Просмотр логов по сети
Устанавливаем лёгкий HTTP сервер:
pacman -S libmicrohttpd
Создаём системного пользователя systemd-journal-gateway:
useradd --system systemd-journal-gateway
Запускаем:
systemctl start systemd-journal-gatewayd.socket
Проверяем:
curl 'http://127.0.0.1:19531/entries?boot'
или в адресной строке браузера:

http://127.0.0.1:19531/
http://127.0.0.1:19531/entries?boot

Более подробно можно почитать тут и тут

3. Запись в журнал
Для записи в журнал используется утилита входящая в состав systemd - systemd-cat.
(можно также использовать и logger утилита входящая в пакет util-linux, но здесь речь будет идти не о ней)
Самый простой способ записи в журнал:
systemd-cat echo "Текст сообщения"
Смотрим:
% journalctl -f
апр 18 01:14:13 arch1 echo[4822]: Текст сообщения

Теперь немного подробнее.
                                                        # Приоритет сообщения
systemd-cat -p 0 -t "Test" echo "0 - emerg"             # экстренный
systemd-cat -p 1 -t "Test" echo "1 - alert"             # тревога
systemd-cat -p 2 -t "Test" echo "2 - crit"              # критический
systemd-cat -p 3 -t "Test" echo "3 - err"               # ошибка
systemd-cat -p 4 -t "Test" echo "4 - warning"           # предупреждение
systemd-cat -p 5 -t "Test" echo "5 - notice"            # уведомление
systemd-cat -p 6 -t "Test" echo "6 - info (defaults)"   # информация
systemd-cat -p 7 -t "Test" echo "7 - debug"             # отладка
-p - указывается приоритет, либо словом либо цифрой, по умолчанию - 6 (информационный).
-t - указывается идентификатор сообщения, можно использовать потом для фильтрации нужной информации.
После ввода через консоль или скриптом в журнал попадут сообщения:

% journalctl -f
апр 18 01:23:52 arch1 Test[5052]: 0 - emerg
апр 18 01:23:52 arch1 Test[5053]: 1 - alert
апр 18 01:23:52 arch1 Test[5054]: 2 - crit
апр 18 01:23:52 arch1 Test[5055]: 3 - err
апр 18 01:23:52 arch1 Test[5056]: 4 - warning
апр 18 01:23:52 arch1 Test[5057]: 5 - notice
апр 18 01:23:52 arch1 Test[5058]: 6 - info (defaults)
апр 18 01:23:52 arch1 Test[5059]: 7 - debug
При появлении экстренного (0 - emerg) сообщения в журнале, информация о нём передаётся на все запущенные терминалы компьютера:
Broadcast message from systemd-journald@arch1 (Thu 2014-04-18 01:23:52 UTC):

Test[5052]: 0 - emerg
Ещё кое что о приоритетах в systemd: заметил что если в подряд записывать сообщения в журнал с высоким приоритетом(2,1,0) то эти сообщения могут не попасть в него ну или как минимум могут возникнуть проблемы с их выводом на экран. Проблема решается установкой секундной паузы между записями(sleep 1). Также заметил что при высоких приоритетах(2,1,0) нецелесообразно использовать многострочные записи в журнал, так как информация урезается до первой строки:
systemd-cat -p 2 -t Test cat <<EOF
1
2
EOF
выведет только единицу:

% journalctl -f
май 12 23:00:53 arch1 Test[16905]: 1

Для записи в журнал можно использовать также и конвейер, но это чревато потерей потока ошибок (stdrr):
% { echo "ok" 1>&1; echo "err" 1>&2; } | systemd-cat
err
поток ошибок выводиться на консоль, а поток вывода перенаправляется в журнал
% journalctl -f
апр 18 01:53:41 arch1 cat[2865]: ok

Чтобы перенаправлять в канал помимо стандартного потока вывода ещё и поток ошибок нужно использовать конструкцию "|&":
% { echo "ok" 1>&1; echo "err" 1>&2; } |& systemd-cat
% journalctl -f
апр 18 01:54:41 arch1 cat[2870]: ok
апр 18 01:54:41 arch1 cat[2870]: err
Либо вообще можно поменять потоки местами:
% { {echo "ok" 1>&1; echo "err" 1>&2;} 3>&1 1>&2 2>&3; } | systemd-cat
ok
поток ошибок попадёт в журнал, а стандартный поток вывода на консоль
% journalctl -f
апр 18 01:55:41 arch1 cat[2875]: err
man systemd-cat

4. Поиск информации в журнале
journalctl SYSLOG_IDENTIFIER=Test
выводит все сообщения имеющие идентификатор сообщения Test. (из примера выше про приоритеты сообщений)
Это и многое другое 1, 2
Помимо встроенных средств фильтрации можно использовать и стандартные:
journalctl | grep Test
Также будет полезно полистать русский перевод systemd для администраторов

5. Примеры ведения лога в скрипте
Пример 1.
создадим скрипт test1.sh
#!/usr/bin/env zsh

echo "ok"	     # команда выполнится с успехом
code=$?
echo Код завершения = $code
if [ "$code" = "0" ]
        then  systemd-cat -t "Test1" echo "Команда 1 выполнилась успешно"
        else  systemd-cat -p 3 -t "Test1" echo "Команда 1 завершилась с ошибкой"
fi

blabla 	             # такой команды нету, поэтому на консоль будет выведена ошибка
code=$?
echo Код завершения = $code
# код ниже аналогичен коду выше что заключён в if...fi
[ "$code" = "0" ] &&  systemd-cat -t "Test1" echo "Команда 2 завершилась успешно" || systemd-cat -p 3 -t "Test1" echo "Команда 2 завершилась с ошибкой"

Вывод в консоли где запускали нашу программу:
% ./test1.sh
ok
Код завершения = 0
zsh: command not found: blabla
Код завершения = 127

Для наглядности можно отслеживать журнал в реальном времени по нужному нам маркеру, для этого запустим отдельную консоль и введём команду:

% journalctl -f SYSLOG_IDENTIFIER=Test1
апр 20 22:33:26 arch1 Test1[5738]: Команда 1 завершилась успешно
апр 20 22:33:26 arch1 Test1[5740]: Команда 2 завершилась с ошибкой

Некоторые пояснения. Каждая команда в языке линукс возвращает так называемый код завершения. Этот код в большинстве случаев при успешном завершении программы возвращает цифру 0, при неудаче возвращает число отличное от нуля.
$? - это специальный параметр который хранит код завершения последний команды.
Подробнее о кодах завершения тут и тут.

Пример 2.
Пример ф-и обёртки над systemd-cat.
Данная функция:
- обрабатывает код завершения команды
- при успешном или нет выполнении команды делать запись об этом в журнал
- также при ошибке поток ошибок направляется в журнал, а на стандартный вывод выводится предупреждение об ошибке
- направляет дополнительную (поясняющую) запись в журнал со стандартного потока вывода

Работа с функцией будет выглядеть примерно так:
echo "пояснение к записи в журнал" | [наша ф-я обработчик] [команда]


#!/usr/bin/env zsh

sName="${0}" # Имя скрипта

# Массив с собственным описанием кодов завершения
ERROR[10]="Неверно введены данные"
ERROR[99]="Операция завершилась с критической ошибкой"
# ...
ERROR[999]="Ошибка" # описание всех остальных ошибок не входящие в ошибки описанные выше
ERROR[1000]="Операция прошла успешно" # описание при отсутствии ошибки($?=0)

msg() {
	read sqarime    # пояснение к записи в журнал (можно также использовать и для отслеживания этапов выполнения программы)
	commanda="${@}" # команда которую обрабатываем
	error=`eval "${commanda}" 2>&1 1>$TTY` # хранит поток ошибок, а поток вывода(&1) отобразиться на консоле $TTY
	code="${?}"     # код завершения
	ID="Test2"      # Метка в журнале

	case "${code}" in
		0 ) systemd-cat -p 6 -t $ID echo "[  OK  ]  ${sqarime}: ${sName}: ${commanda}: ${ERROR[1000]}";;
		10) systemd-cat -p 4 -t $ID cat <<EOF
			[ FAIL ]  ${sqarime}: ${sName}: ${commanda}
			|         Код=${code}: ${ERROR[${code}]}
			|         ERROR: ${error}
EOF
			echo "Ошибка в ф-и ${commanda}! Проверьте журнал";;
		99) systemd-cat -p 3 -t $ID cat <<EOF
			[ FAIL ]  ${sqarime}: ${sName}: ${commanda}
			|         Код=${code}: ${ERROR[${code}]}
			|         ERROR: ${error}
EOF
			echo "Критическая ошибка в ф-и ${commanda}! Проверьте журнал"
			exit ${code};;
		* ) systemd-cat -p 4 -t $ID cat <<EOF
			[ FAIL ]  ${sqarime}: ${sName}: ${commanda}
			|         Код=${code}: ${ERROR[999]}
			|         ERROR: ${error}
EOF
			echo "Ошибка в ф-и ${commanda}! Проверьте журнал";;
	esac
	return ${code}
}

fn1() { # Тестовая ф-я 1
	echo "Отработала функция $0"
	return 0
}

fn2() { # Тестовая ф-я 2
	echo "Отработала функция $0"
	echo "Критическая ошибка" >&2
	return 99
}

echo "Работа команды blabla"    |msg blabla
echo "Вывод текущей даты"       |msg date -I
echo "Работа функции fn1()"     |msg fn1
echo "Работа функции fn2()"     |msg fn2
echo "Эта надпись не должна вывестись на экран"


% ./test2.sh
Ошибка в ф-и blabla! Проверьте журнал
2014-05-14
Отработала функция fn1
Отработала функция fn2
Критическая ошибка в ф-и fn2! Проверьте журнал


% journalctl -f SYSLOG_IDENTIFIER=Test2
май 14 21:29:28 arch1 Test2[12186]: [ FAIL ] Работа команды blabla: ./test2.sh: blabla
май 14 21:29:28 arch1 Test2[12186]: |.........Код=127: Ошибка
май 14 21:29:28 arch1 Test2[12186]: |.........ERROR: (eval):1: command not found: blabla
май 14 21:29:28 arch1 Test2[12190]: [ OK ] Вывод текущей даты: ./test2.sh: Операция прошла успешно: date -I
май 14 21:29:28 arch1 Test2[12193]: [ OK ] Работа функции fn1(): ./test2.sh: Операция прошла успешно: fn1
май 14 21:29:28 arch1 Test2[12196]: [ FAIL ] Работа функции fn2(): ./test2.sh: fn2
май 14 21:29:28 arch1 Test2[12196]: |.........Код=99: Операция завершилась с критической ошибкой
май 14 21:29:28 arch1 Test2[12196]: |.........ERROR: Критическая ошибка
journalctl SYSLOG_IDENTIFIER=TEST
Вот выдает journalctl SYSLOG_IDENTIFIER=TEST
-- Logs begin at Сб 2014-04-19 15:03:33 , end at Вс 2014-04-20 20:06:38
И что я должен увидеть.Вы уж напишите,для такого как я,кто не читает wiki и не использует переводчик.Что значит параметр SYSLOG_IDENTIFIER в wiki это написано так......,а для чего я должен запускать такjournalctl SYSLOG_IDENTIFIER=TEST,что я увижу?Легче было спросить,как вы используете journalctl и какие параметры применяете,а потом систематизировать вот и все.Спасибо.
Последний крик моды - эхо 30-летней давности.
tchgefest
а для чего я должен запускать так journalctl SYSLOG_IDENTIFIER=TEST,что я увижу?
tchgefest
Что значит параметр SYSLOG_IDENTIFIER

red
journalctl SYSLOG_IDENTIFIER=TEST
выводит все сообщения имеющие идентификатор сообщения TEST.
red
-t - указывается идентификатор сообщения, можно использовать потом для фильтрации нужной информации.
также там после описания параметра -t чуть ниже показан сам вывод, вот такой же вывод у вас должен получиться если бы вместо прочтения попробовали ввести пример где рассказывалось про приоритеты сообщений.

если чуть подробнее то поле SYSLOG_IDENTIFIER - это идентификатор хранящий маркер вашего сообщения который вы даёте ему при отправке его в журнал посредством параметра -t в утилите systemd-cat (к примеру вот так: systemd-cat -t "TEST" echo "Текст сообщения"). По этому маркеру можно легко найти ваше сообщение или сообщения.
Используя grep при поиске ключевого слова(маркера) можно тоже вывести все сообщения с ним, но это также может вывести и сообщения которые не содержат в своём идентификаторе нашего маркера, а похожее словосочетание может просто встретиться в теле самого сообщения.
то есть используя SYSLOG_IDENTIFIER мы ведём поиск только по полям где находятся маркеры сообщений, а используя grep мы ведём поиск по всем полям, в том числе и по маркерам.

tchgefest
Легче было спросить,как вы используете journalctl и какие параметры применяете,а потом систематизировать вот и все.
Журналирование пока в процессе изучения, по сути оно мне понадобилось при написании программы для которой нужно вести логи. Для решения данной задачи решил воспользоваться средствами systemd.

Статью скорее всего я ещё буду дополнять и подправлять, так что если по написанному тексту есть вопросы, задавайте, с радостью отвечу.
Самое главное забыли
journalctl --boot
Последний крик моды - эхо 30-летней давности.
tchgefest
Самое главное забыли
journalctl --boot
ок, добавил
1. А чем журнал загрузки systemd отличается от dmesg?
This Must Be The Place I Waited Years To Leave
pethead, сравните - увидите. )
dmesg - лог сообщений ядра, многое из него дублируется в лог systemd, но если вам удобнее первое - не вопрос.
Aivar
pethead, многое из него дублируется в лог systemd,
Я ведь не праздно спрашивал, а принципиально.
Что значит "многое", и где остальное, и почему нужно дублирование.
если бы он вбирал в себя весь лог ядра + свое тогда понятно, а то "многое". Слишком неоднозначно.

Сравнил. Весь лог ядра в этом журнале только время реальное а не от старта системы + вперемежку с логами самого демона.

Вопрос такой. А где посмотреть лог который на экран выводится если нет флага quiet? Там еще выводится Welcome to ArchLinux. :)
Или как его сделать чтоб тоже в файл кидался, если нет в файле.
This Must Be The Place I Waited Years To Leave
pethead
А где посмотреть лог который на экран выводится если нет флага quiet?
В таком же виде - нигде. Считайте, что сообщения "не молчаливой" загрузки - это интерпретация journalctl -b.
Тогда перефразирую где подправить "Welcome to Arch Linux!" на свое? :)
Нашел
http://cgit.freedesktop.org/systemd/systemd/tree/src/shared/util.c?id=v205#n3035
This Must Be The Place I Waited Years To Leave
 
Зарегистрироваться или войдите чтобы оставить сообщение.