Существует много способов развёртывания веб-приложений и примерно столько же подходов к логгированию. В этой статье хочу показать подход к логгированию из Java бэкенда, развёрнутого как systemd service, в journald с помощью Logback и FFM API.
Статья не является попыткой агитации за использование такого подхода — скорее я хотел показать, что такой подход в принципе существует и кому-то он может оказаться полезен, но необходимо держать в голове, что использование FFM API влечёт риски, так что применяйте осознанно. Кроме того, у меня нет информации о степени производительности такого подхода — могу лишь предположить, что работа journald API заключается в формировании бинарного сообщения и его записи в Unix socket, что должно быть довольно быстро.
Предполагается, что вы знакомы с systemd, journald, разработкой на Java и с использованием Logback в частности.
Как работает логгирование в stdout с journald по умолчанию
У меня есть небольшое веб-приложение на Spring Boot, развёрнутое на VPS с помощью systemd. Приложение пишет логи в stdout с помощью Logback — я намеренно отказался от записи логов в файлы. Systemd, в свою очередь, пробрасывает логи из stdout в journald. Пробрасывание логов stdout в journald работает просто — каждая строчка stdout становится отдельным сообщением в journald, а каждое такое сообщение будет иметь один и тот же уровень INFO.
С таким сетапом логгирования имеются различные неприятности. Для их иллюстрации вместо вышеупомянутого веб-приложения запустим с помощью systemd вот такую простейшую программу на Java:
public final class LogbackJournaldFfmApi { private static final Logger log = LoggerFactory.getLogger(LogbackJournaldFfmApi.class); public static void main(final String[] args) { log.debug("This is a debug message"); log.info("This is an information message"); log.warn("This is a warning"); try { methodThatThrowsException(); } catch (final IllegalStateException e) { log.error("Error with an exception", e); } } private static void methodThatThrowsException() { throw new IllegalStateException("Some exception"); }}
Для логгирования в stdout используется Slf4J API и Logback в качестве реализации. После запуска мы можем посмотреть логи с помощью journalctl:
Jan 1 00:00:00 hostname logback-journald-ffm-api[73619]: main com.github.LogbackJournaldFfmApi.main(14) - This is a debug messageJan 1 00:00:00 hostname logback-journald-ffm-api[73619]: main com.github.LogbackJournaldFfmApi.main(15) - This is an information messageJan 1 00:00:00 hostname logback-journald-ffm-api[73619]: main com.github.LogbackJournaldFfmApi.main(16) - This is a warningJan 1 00:00:00 hostname logback-journald-ffm-api[73619]: main com.github.LogbackJournaldFfmApi.main(21) - Error with an exceptionJan 1 00:00:00 hostname logback-journald-ffm-api[73619]: java.lang.IllegalStateException: Some exceptionJan 1 00:00:00 hostname logback-journald-ffm-api[73619]: at com.github.LogbackJournaldFfmApi.methodThatThrowsException(LogbackJournaldFfmApi.java:26)Jan 1 00:00:00 hostname logback-journald-ffm-api[73619]: at com.github.LogbackJournaldFfmApi.main(LogbackJournaldFfmApi.java:19)
Неприятности заключаются в следующем. Во-первых, тут не получится пофильтровать логи по уровню, поскольку при пробрасывании из stdout в journald уровень сообщения теряется. Без фильтрации придется читать все логи вместо того, чтобы обращать внимание только на важные сообщения. Кроме того, каждая строка вывода приложения станет отдельным сообщением в логе, что некорректно для любого сообщения, состоящего из нескольких строк — например, для стектрейсов исключений. В этой ситуации сообщения могут перемешиваться между собой, что ещё более усложнит понимание происходящего.
Вот как логи должны выглядеть:
Jan 1 00:00:00 hostname java[73619]: main com.github.LogbackJournaldFfmApi.main(14) — This is a debug messageJan 1 00:00:00 hostname java[73619]: main com.github.LogbackJournaldFfmApi.main(15) — This is an information message# представьте, что сообщение выделено желтым цветом))Jan 1 00:00:00 hostname java[73619]: main com.github.LogbackJournaldFfmApi.main(16) — This is a warning# а тут красным))Jan 1 00:00:00 hostname java[73619]: main com.github.LogbackJournaldFfmApi.main(21) — Error with an exception java.lang.IllegalStateException: Some exception at com.github.LogbackJournaldFfmApi.methodThatThrowsException(LogbackJournaldFfmApi.java:26) at com.github.LogbackJournaldFfmApi.main(LogbackJournaldFfmApi.java:19)
Видно уровни сообщений (trust me bro), многострочные сообщения отображаются корректно.
Некоторое время я жил с первым типом логов, но в конце концов мне это надоело, так что я решил как-то это исправить. Я не нашел простого и эффективного способа настроить systemd service unit, чтобы в journald попадали структурированные логи. В процессе поиска решения я наткнулся на документацию libsystemd, в которой в том числе описаны функции работы с journald. Примерно в тот же момент вышел JDK 22, в составе которого было выпущено Foreign Functions And Memory API, и картинка в моей голове наконец сложилась.
Важно: если вы ранее никогда не работали с нативными функциями и всё же решите использовать этот подход в своём приложении, то вы должны знать, что ошибка в результате вызова нативного API (например, segmentation fault) крашнет процесс JVM. Такое не отловить в try-catch. И это не пустая вероятность — мое приложение крашилось из-за undefined behavior, которое я случайно допустил в наивной реализации работы с FFM API.
Реализация
Общая схема реализации довольно проста (вот пример). Сначала мы пишем обёртку для нужной нам нативной функции (об этом ниже) — в нашем случае это sd_journal_send_with_location. Эта функция позволяет отправить в journald сообщение с указанием уровня и некоторых других полезных данных, вроде места вызова логгера в коде приложения.
Далее, пишем кастомный ch.qos.logback.core.Appender, который будет вызывать нашу обёртку:
public class JournaldAppender extends AppenderBase<ILoggingEvent> { // пример упрощённый, см. репозиторий с примером @Override protected void append(final ILoggingEvent eventObject) { final var invoker = SystemdJournal.sd_journal_send_with_location.makeInvoker( // само сообщение SystemdJournal.C_POINTER, // уровень SystemdJournal.C_POINTER, // trailing null pointer (API использует varargs) SystemdJournal.C_POINTER ); final String codeFile = getCodeFile(eventObject); final String codeLine = getCodeLine(eventObject); final String codeFunc = getCodeFunc(eventObject); final String message = getMessage(eventObject); final String priority = getPriority(eventObject); try (final var arena = Arena.ofConfined()) { invoker.apply( arena.allocateFrom(codeFile), arena.allocateFrom(codeLine), arena.allocateFrom(codeFunc), arena.allocateFrom("MESSAGE=%s"), arena.allocateFrom(message), arena.allocateFrom(priority), MemorySegment.NULL ); } catch (final Exception e) { addError("Failed to invoke sd_journal_send_with_location", e); } }}
Наконец, указываем наш appender в конфигурации Logback:
<?xml version="1.0" encoding="UTF-8"?><configuration> <appender class="com.github.JournaldAppender" name="journald"> <encoder> <pattern>%thread %logger.%M\(%line{5}\) - %msg%n</pattern> </encoder> </appender> <root level="debug"> <appender-ref ref="journald"/> </root></configuration>
Если в логах пусто — вполне возможно, что в appender-е возникает исключение. Для отладки Logback можно использовать опцию debug="true":
<?xml version="1.0" encoding="UTF-8"?><configuration debug="true"> <!-- конфигурация из примера выше --></configuration>
Вот в целом и всё. Единственная сложность — правильно описать обёртку нативного вызова. Обёртка сводится к описанию memory layouts для разных типов данных (от int-ов до структур) и конструированию вызовов нативных функций. Звучит не слишком сложно, но ошибиться весьма легко, и ошибки эти могут стоить нашему JVM-процессу жизни.
Есть два способа описывать обёртки нативных функций. Способ первый — вручную (или с помощью LLM): почитать документацию FFM API и нативной библиотеки, написать код, потестировать, исправить возникающие ошибки — в общем, как мы обычно и разрабатываем программы. Подход опасен тем, что обертки представляют собой приличную массу boilerplate-кода, в котором легко допустить ошибку. Вот пример неопределённого поведения, с которым я столкнулся при ручной реализации:
final var invoker = SystemdJournal.sd_journal_send_with_location.makeInvoker( // сообщение SystemdJournal.C_POINTER, // уровень SystemdJournal.C_POINTER, // trailing null pointer. Здесь должен быть C_POINTER SystemdJournal.C_INT);try (final var arena = Arena.ofConfined()) { invoker.apply( arena.allocateFrom(codeFile), arena.allocateFrom(codeLine), arena.allocateFrom(codeFunc), arena.allocateFrom("MESSAGE=%s"), arena.allocateFrom(message), arena.allocateFrom(priority), 0 // А тут должно быть MemorySegment.NULL );}
Вместо 8-байтового NULL-указателя я передавал 4-байтный ноль. Если в какой-то момент оставшиеся 4 байта были не-нулями — получаем адрес на произвольную область памяти и, как следствие, segfault. В результате приложение падает, но не сразу, а лишь через несколько десятков (или сотен, или тысяч) вызовов функции логгирования — типичный пример неопределённого поведения. Элементарная ошибка для программиста на C; мне же пришлось основательно покопаться, чтобы дойти до сути проблемы — и всё это лишь потому, что я не смог в момент написания обёртки найти нужную константу (MemorySegment.NULL), отчего начал придумывать костыли.
Таким образом, чем меньше мы пишем кода с использованием FFM API — тем лучше. Здесь нам на помощь приходит второй способ создания обёрток нативных функций: jextract. Это утилита генерации кода обёрток, которая принимает на вход путь к заголовочному файлу, название функции и некоторые другие параметры:
./jextract-22/bin/jextract \ --target-package com.github \ --header-class-name SystemdJournal \ --output src/main/java \ --library systemd \ --include-function sd_journal_send_with_location \ /usr/include/systemd/sd-journal.h`
В результате получим исходник ./src/main/java/com/github/SystemdJournal.java с обёртками нужных нам функций — остаётся лишь вызвать их с нужными аргументами.
Помимо всего прочего, код вызова нативной функции предварительно должен динамически загружать нужную нам библиотеку. Для генерации этого кода мы указываем параметр --library со значением systemd. Загружать библиотеку можно как по пути к .so/.dll, так и по названию, как в нашем примере (в этом случае библиотека должна быть правильно установлена в системе).
Библиотеки могут содержать сотни функций, но что если нам требуется всего одна-две? Генерировать обёртки для всех функций было бы лишним, поэтому jextract предоставляет несколько параметров фильтрации: --include-function, --include-struct и т.д. В нашем примере мы генерируем обёртку для единственной нужной нам функции с помощью --include-function sd_journal_send_with_location.
Также стоит отметить, что интегрировать запуск jextract в процесс сборки приложения не требуется, в отличие от других утилит генерации кода, таких как OpenAPI Generator или jOOQ. В случае с jextract достаточно один раз сгенерировать код обёрток и сохранить его в репозитории. Запускать генерацию заново нужно только если обновилась библиотека или сама jextract. Вот цитата из usage guide:
Jextract assumes that the version of a native library that a project uses is relatively stable. Therefore, jextract is intended to be run once, and then for the generated sources to be added to the project. Jextract only needs to be run again when the native library, or jextract itself are updated.
Заключение
С момента реализации прошло больше года; процесс не крашится, на VPS логи смотреть удобно, есть поддержка загрузки логов из journald в системы агрегации логов (например, с помощью fluent bit). Меня такой подход полностью устраивает, однако мнение субъективное и связано это с тем, что мне удобен подход развёртывания небольших приложений через systemd.—
ссылка на оригинал статьи https://habr.com/ru/articles/1068800/