Логирование из Java в Journald

Posted on

Недавно обнаружил одну интересную особенность journald, которую сразу же решил использовать в r2cloud.

Для начала немного о том, как вообще работает логирование. Большинство Linux дистрибутивов перешли на systemd. Эта система имеет множество различных фич, в том числе поддержку логирования - journald. Чем же это логирование лучше syslog:

  1. Структурированные логи. Каждая запись в логе имеет некоторую мета-информацию. Например, уровень (INFO, DEBUG, ERROR), дату, сообщение и пр. В syslog же, запись в логе это строка текста, которую нужно правильно парсить.
  2. Бинарные файлы логов. С помощью специальной команды journalctl можно фильтровать логи по разным полям из мета информации. Например, можно посмотреть все ошибки за последний день, показать ошибки авторизации в sshd и пр.
  3. Интеграция с systemd. stderr и stdout каждого юнита по-умолчанию парсится и отправляется в journald.

Изначально я писал логи в отдельный файл, как принято в старом добром enterprise. Однако, со временем понял, что лучше писать в stdout/stderr, где эти логи попадут в journald. Это хорошо по нескольким причинам:

  1. Все логи в одном месте. Можно посмотреть что происходило в системе в момент, когда приложение упало или потеряло сеть.
  2. Ротация и централизованное хранение логов. Если приложение сойдёт с ума и начнёт слать безумное количество логов, то существует единая настройка в системе, которая контролирует сколько места будет отведено под логи.
  3. Удобный поиск по логам с помощью journalctl.

Я написал простейший конфиг для java.util.logging:

handlers=java.util.logging.ConsoleHandler
.level=INFO
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=[%4$s] %5$s%6$s [%2$s]%n

Тут самое важное - это конфигурация formatter. Я оставил только минимальное количество информации: уровень лога, сообщение, stacktrace, название класса и метод. Дату я убрал, так как она уже будет выводиться в journalctl. Результат получился следующий:

Aug 15 17:40:09 raspberrypi java[481]: [INFO] ================================= [ru.r2cloud.R2Cloud start]
Aug 15 17:40:09 raspberrypi java[481]: [INFO] =========== started ============= [ru.r2cloud.R2Cloud start]
Aug 15 17:40:09 raspberrypi java[481]: [INFO] ================================= [ru.r2cloud.R2Cloud start]

Какое-то время меня устраивало как выглядят логи. Однако, со временем у меня скопилось достаточно большое количество серверов и захотелось отправлять нотификации в телеграм, как только случиться ошибка. Но прежде, чем делать централизованное логирование, необходимо сделать так, чтобы приложение правильно проставляло уровень логирования.

К сожалению, все логи из stdout и stderr попадают с PRIORITY=6, что значит INFO. Нужно как-то из самой библиотеки логирования указать journald какой уровень у каждого сообщения.

И вот тут-то я и нашёл одну интересную особенность journald. Оказывается, если сообщение начинается на <номер>, то journald попытается его распарсить согласно RFC-5424. Согласно этому RFC, этот номер будет указывать на уровень логирования.

Я написал небольшую библиотечку journald-formatter, которая форматирует java.util.logging.Level в соответствующий номер из RFC. Если указать следующую конфигурацию:

handlers=java.util.logging.ConsoleHandler
.level=INFO
java.util.logging.ConsoleHandler.formatter=ru.r2cloud.logging.JournaldFormatter
java.util.logging.JournaldFormatter.format=<%4$s>%5$s%6$s [%2$s]%n

То она позволит journald правильно распарсить уровень логирования:

Sep 03 21:00:51 raspberrypi java[1352]: ================================= [ru.r2cloud.R2Cloud start]
Sep 03 21:00:51 raspberrypi java[1352]: =========== started ============= [ru.r2cloud.R2Cloud start]
Sep 03 21:00:51 raspberrypi java[1352]: ================================= [ru.r2cloud.R2Cloud start]

И ошибки теперь легко искать в логах:

journalctl -u r2cloud -p err -n 10

-- Logs begin at Thu 2016-11-03 17:16:42 GMT, end at Tue 2019-09-03 22:09:24 BST. --
Sep 03 22:09:24 raspberrypi java[1869]: unable to get weather tle

Что дальше?

  1. Неплохо было бы передавать время из JUL напрямую в journald. Сейчас journald проставляет время получения события, а не время, когда оно произошло внутри JVM.
  2. Настроить централизованное логирование с нотификациями через телеграм. Кто знает как, пишите в комментариях.