Логирование в Java: что, как, где и чем?

Всем привет, JavaRush сообщество! Сегодня поговорим о Java логировании:

1. Что это, зачем это. В каких случаях лучше использовать, а в каких не стоит.
2. Какие бывают реализации логирования в Java и что с этим разнообразием нам делать.
3. Уровни логирования. Обсудим, что такое appender и как его правильно настроить.
4. Узлы логирования и как правильно их настраивать, чтоб все работало так, как мы хотим.

Этот материал рассчитан на широкую аудиторию. Он будет понятен и тем, кто только знакомится с Java, и тем, кто уже работает, но разобрался только с logger.info(“log something”); Поехали! Если коротко: логирование это запись того, что происходит внутри приложения, в консоль, файл или базу, причем у каждой записи есть уровень важности. В Java оно устроено в два слоя: в коде вызывают фасад, чаще всего SLF4J, а саму запись делает подключенная отдельной зависимостью реализация, например Log4j, Logback или встроенный в JDK JUL. Уровень записи решает, попадет ли она в лог вообще, appender решает, куда именно она уйдет, а узел логирования позволяет настроить и то и другое отдельно для конкретного пакета.

Кратко

• Логирование это не System.out.println, а управляемая запись событий: у каждой строки есть уровень, а у приложения настройка, какие уровни писать и куда.
• В Java два слоя: фасад (SLF4J, JCL) и реализация (Log4j, Logback, JUL). В коде вызывают фасад, реализацию подключают зависимостью и меняют, не трогая код.
• Уровни по возрастанию строгости: TRACE, DEBUG, INFO, WARN, ERROR, FATAL, а по краям OFF и ALL. Заданный уровень пропускает сам себя и все, что выше.
• Appender отвечает за то, куда уходит лог: консоль, файл, база, сеть. Layout за то, как выглядит сама строка.
• Узел логирования это пакет или класс: настройки для com.github.romankh3 можно задать отдельно от всего остального, а RootLogger собирает все логи приложения.
• Логировать обязательно старт и остановку приложения, события безопасности и смену состояний. Нельзя персональные данные, и на логи не должно уходить больше 10 процентов нагрузки.

Для чего нужно логирование

Давайте разберем реальные случаи, в которых логирование решало бы проблему. Если тема для вас совсем новая, начать стоит с разбора зачем логирование вообще нужно. Вот пример из моей работы. Есть точки приложений, которые интегрируются с другими сервисами. Я использую логирование этих точек для “алиби”: если интеграция не сработает, будет легко разобраться, с какой стороны возникла проблема. Еще желательно логировать важную информацию, которая сохраняется в базу данных. Например создание пользователя администратора. Это как раз то, что хорошо бы логировать.

Инструменты для логирования в Java

Из известных решений по логированию в Java можно выделить:

• log4j
• JUL (java.util.logging)
• JCL (jakarta commons logging)
• Logback
• SLF4J (simple logging facade for java)

Про реализацию по умолчанию в Spring Boot: об этом сказано в справочнике фреймворка, «By default, if you use the starters, Logback is used for logging». Подробности про статус Log4j 1.x чуть ниже, в конце раздела.

System.err.println

Первоначально был, разумеется, System.err.println (вывод записи в консоль). Его и сейчас используют для быстрого получения лога при дебаге. Конечно, говорить о каких-то настройках здесь не приходится, поэтому просто запомним его и пойдем дальше.

Log4j

Это уже было полноценное решение, которое создавалось из потребностей разработчиков. Получился действительно интересный инструмент, который можно использовать. В силу разных обстоятельств это решение так и не попало в JDK, чем очень расстроило все комьюнити. В log4j были возможности по конфигурации таким образом, чтобы можно было включить логирование в пакете com.example.type и выключить его в подпакете com.example.type.generic. Это позволяло быстро отсечь то, что нужно логировать, от того, что не нужно. Здесь важно отметить, что есть две версии log4j: 1.2.х и 2.х.х, которые несовместимы друг с другом. log4j добавил такое понятие как appender, то есть инструмент, с помощью которого записываются логи, и layout, то есть форматирование логов. Это позволяет записывать только то, что нужно и как нужно. Больше о appender поговорим чуть позже.

JUL (java.util.logging)

Одно из ключевых преимуществ этого решения в том, что JUL включен в JDK (Java development kit). К сожалению, при его разработке за основу взяли не популярный log4j, а решение от IBM, что и повлияло на его развитие. По факту на данный момент JUL есть, но им никто не пользуется. Из “такого себе”: в JUL уровни логирования отличаются от того, что есть в Logback, Log4j, Slf4j, и это ухудшает понимание между ними. Создание логгера более менее похожее. Для этого нужно сделать импорт:

java.util.logging.Logger log = java.util.logging.Logger.getLogger(LoggingJul.class.getName());

Имя класса специально передается для того, чтобы знать, откуда идет логирование. Начиная с Java 8, можно передавать Supplier<String>. Это помогает считать и создавать строку только в тот момент, когда это действительно нужно, а не каждый раз, как это было до этого. Только с выходом Java 8 разработчики решили важные проблемы, после чего JUL по-настоящему стало возможно в использовании. А именно, методы с аргументом Supplier<String> msgSupplier, как показано ниже:

public void info(Supplier<String> msgSupplier) {
   log(Level.INFO, msgSupplier);
}

JCL (jakarta commons logging)

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

Logback

Как же тернист путь open-source… Logback написал тот же разработчик, что и log4j, чтобы создать ему преемника. В основе была та же идея, что и в log4j. Отличия были в том, что в logback:

• улучшена производительность;
• добавлена нативная поддержка slf4j;
• расширена опция фильтрации.

Стандартно logback не требует каких-либо настроек и записывает все логи начиная от уровня DEBUG и выше. Если нужна настройка, ее можно выполнить через xml конфигурацию:

<configuration> 
    <appender name="FILE" class="ch.qos.logback.core.FileAppender"> 
        <file>app.log</file> 
        <encoder> 
            <pattern>%d{HH:mm:ss,SSS} %-5p [%c] - %m%n</pattern> 
        </encoder> 
    </appender> 
    <logger name="org.hibernate.SQL" level="DEBUG" /> 
    <logger name="org.hibernate.type.descriptor.sql" level="TRACE" /> 
    <root level="info"> 
        <appender-ref ref="FILE" /> 
    </root> 
</configuration>

SLF4J (simple logging facade for java)

Где-то в 2006 году один из отцов-основателей log4j вышел из проекта и создал slf4j (Simple Logging Facade for Java), обертку вокруг log4j, JUL, commons-logging и logback. Как видим, прогресс дошел до того, что создали обертку над оберткой… Причем она делится на две части: API, который используется в приложении и реализация, которая добавляется отдельными зависимостями для каждого вида логирования. Например, slf4j-log4j12.jar, slf4j-jdk14.jar. Достаточно подключить правильную реализацию и все: весь проект будет работать с ней. Slf4j поддерживает все новые функции, такие как форматирование строк для логирования. До этого была такая проблема. Допустим, есть запись в лог:

log.debug("User " + user + " connected from " + request.getRemoteAddr());

В объекте user происходит неявное преобразование user.toString() из-за конкатенации строк, и это занимает время, которое тормозит систему. И все ок, если мы дебажим приложение. Проблемы начинаются, если для этого класса уровень логирования INFO и выше. То есть этот лог не должен быть записан, и конкатенация строк также не должна быть произведена. По идее это должна была решить сама библиотека логирования. Причем это и оказалось самой большой проблемой первой версии log4j. Решения нормального не завезли, а предложили делать вот так:

if (log.isDebugEnabled()) {
    log.debug("User " + user + " connected from " + request.getRemoteAddr());
}

То есть вместо одной строки логирования предлагали писать 3(!). Логирование должно минимизировать изменения в коде, и три строки явно противоречили общему подходу. У slf4j не было проблем совместимости с JDK и API, поэтому сходу возникло красивое решение:

log.debug("User {} connected from {}", user, request.getRemoteAddr());

где {} обозначают вставки аргументов, которые передаются в методе. То есть первая {} соответствует user, вторая {} это request.getRemoteAddr(). Благодаря чему, только в случае, если уровень логирования позволяет записывать в лог, это сообщение конкатенировать в единое. После этого SLF4J стал быстро расти в популярности, и на данный момент это лучшее решение. Поэтому будем рассматривать логирование на примере связки slf4j-log4j12. Важная оговорка, которой в 2019 году еще не требовалось. Log4j 1.x снят с поддержки: комитет проекта объявил end of life 5 августа 2015 года, и на официальной странице Log4j 1.2 прямо написано, что перечисленные там уязвимости исправлены не будут. То же самое повторяет страница безопасности Log4j 2: все, о чем сообщили после августа 2015 года, для первой ветки не проверяется и не чинится. Сама зависимость slf4j-log4j12 тоже уже не та, что в статье: судя по списку релизов SLF4J, начиная с версий 1.7.35 и 2.0.0-alpha7 она автоматически подменяется на slf4j-reload4j, где вместо Log4j 1.2 работает его пропатченный форк reload4j. Для нового проекта сегодня берут SLF4J плюс Logback либо SLF4J плюс Log4j 2. Заодно разведем две вещи, которые постоянно путают: нашумевший Log4Shell (CVE-2021-44228) бил по Log4j 2 версий с 2.0-beta9 по 2.14.1 и был закрыт в 2.17.1, а к первой ветке отношения не имеет. У Log4j 1.x свой набор дыр, и его особенность в том, что он просто не закрывается. На пользу разбора ниже это не влияет: уровни, аппендеры, layout и узлы логирования устроены одинаково во всех трех библиотеках, различается только синтаксис конфигурации.

Что нужно логировать

Разумеется, логировать все подряд не стоит. Иногда это и не нужно, и даже опасно. Например, если залогировать чьи-то личные данные и это каким-то образом всплывет на поверхность, будут реальные проблемы, особенно на проектах, ориентированных на Запад. Но есть и то, что логировать обязательно:

1. Начало/конец работы приложения. Нужно знать, что приложение действительно запустилось, как мы и ожидали, и завершилось так же ожидаемо.
2. Вопросы безопасности. Здесь хорошо бы логировать попытки подбора пароля, логирование входа важных юзеров и т.д.
3. Некоторые состояния приложения. Например, переход из одного состояния в другое в бизнес процессе.
4. Некоторая информация для дебага, с соответственным уровнем логирования.
5. Некоторые SQL скрипты. Есть реальные случаи, когда это нужно. Опять-таки, умелым образом регулируя уровни, можно добиться отличных результатов.
6. Выполняемые нити (Thread) могут быть логированы в случаях с проверкой корректной работы.

Популярные ошибки в логировании

Нюансов много, но можно выделить несколько частых ошибок:

1. Избыток логирования. Не стоит логировать каждый шаг, который чисто теоретически может быть важным. Есть правило: логи могут нагружать работоспособность не более, чем на 10%. Иначе будут проблемы с производительностью.
2. Логирование всех данных в один файл. Это приведет к тому, что в определенный момент чтение/запись в него будет очень сложной, не говоря о том, что есть ограничения по размеру файлов в определенных системах.
3. Использование неверных уровней логирования. У каждого уровня логирования есть четкие границы, и их стоит соблюдать. Если граница расплывчатая, можно договориться какой из уровней использовать.

Уровни логирования

Что такое уровни логирования? Для того, чтоб как-то ранжировать логи, нужно было дать определенные обозначения и разграничения. Для этого ввели уровни логирования. Уровень задается в приложении. Если запись относится к уровню ниже обозначенного, она не вносится в лог. Например, у нас есть логи, с помощью которых дебажат приложение. В нормальной работе на продакшене (когда приложение используют по назначению), такие логи не нужны. Поэтому уровень логирования будет выше, чем для дебага. Давайте рассмотрим уровни на примере log4j. Остальные решения, кроме JUL, используют такие же уровни. Вот они в порядке уменьшения:

• OFF: никакие логи не записываются, все будут проигнорированы;
• FATAL: ошибка, после которой приложение уже не сможет работать и будет остановлено, например, JVM out of memory error;
• ERROR: уровень ошибок, когда есть проблемы, которые нужно решить. Ошибка не останавливает работу приложения в целом. Остальные запросы могут работать корректно;
• WARN: обозначаются логи, которые содержат предостережение. Произошло неожиданное действие, несмотря на это система устояла и выполнила запрос;
• INFO: лог, который записывает важные действия в приложении. Это не ошибки, это не предостережение, это ожидаемые действия системы;
• DEBUG: логи, необходимые для отладки приложения. Для уверенности в том, что система делает именно то, что от нее ожидают, или описания действия системы: “method1 начал работу”;
• TRACE: менее приоритетные логи для отладки, с наименьшим уровнем логирования;
• ALL: уровень, при котором будут записаны все логи из системы.

Получается, что если в приложении в каком-то месте включен уровень логирования INFO, будут логироваться все уровни, начиная с INFO и до FATAL. Если будет уровень логирования FATAL, будут записаны только логи с этим уровнем.

Запись и отправка логов: Appender

Этот процесс будем рассматривать на примере log4j: он предоставляет широкие возможности для записи/отправки логов:

• для записи в файл: DailyRollingFileAppender;
• для получения данных в консоль приложения: ConsoleAppender;
• для записи логов в базу данных: JDBCAppender;
• для контроля передачи через TCP/IP: TelnetAppender;
• для того, чтобы запись логов не била по быстродействию: AsyncAppender.

Список выше это аппендеры Log4j 1.x, полный набор лежит в javadoc пакета org.apache.log4j. В Log4j 2 набор другой: там нет DailyRollingFileAppender, его роль выполняет RollingFile с политикой TimeBasedTriggeringPolicy. Таблица соответствий приведена в руководстве по миграции, а актуальный список аппендеров второй ветки в ее документации. Кстати, если нужного аппендера не будет, это не проблема. Можно написать свой аппендер, имплементировав интерфейс Appender, который как раз принимает log4j.

Узлы логирования

Для демонстрации будем использовать интерфейс slf4j, а реализацию от log4j. Создать логгер очень просто: нужно написать в классе с именем MainDemo, в котором будет логирование, следующее:

org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(MainDemo.class);

Это и создаст нам логгер. Чтобы сделать запись в лог, можно использовать множество методов, которые показывают, с каким уровнем будут записи. Например:

logger.trace("Method 1 started with argument={}", argument);
logger.debug("Database updated with script = {}", script);
logger.info("Application has started on port = {}", port);
logger.warn("Log4j didn't find log4j.properties. Please, provide them");
logger.error("Connection refused to host = {}", host);

Хоть мы и передаем класс, по итогу записывается именно полное имя класса с пакетами. Это делается, чтобы потом можно было разделить логирование на узлы, и для каждого узла настроить уровень логирования и аппендер. Например, имя класса: com.github.romankh3.logginglecture.MainDemo, в нем создался логгер. И вот таким образом его можно разделить на узлы логирования. Главный узел это нулевой RootLogger. Это узел, который принимает все логи всего приложения. Остальные можно изобразить, как показано ниже: Аппендеры настраивают свою работу именно на узлы логирования. Сейчас на примере log4j.properties будем смотреть, как их настроить.

Пошаговая настройка Log4j.properties

Сразу уточним, что дальше все примеры относятся к Log4j 1.x: файл называется log4j.properties, а все свойства начинаются с log4j.. В Log4j 2 конфигурация лежит в log4j2.xml или log4j2.properties и имена свойств другие, в Logback это logback.xml. Устройство при этом везде одно и то же: зарегистрировать аппендер, задать ему layout, назначить уровень узлу логирования. Поэтому смотреть дальше стоит именно на схему, а не заучивать конкретные строки. Сейчас мы поэтапно все настроим и посмотрим, что можно сделать:

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender

Эта строка говорит, что мы регистрируем аппендер CONSOLE, который использует реализацию org.apache.log4j.ConsoleAppender. Этот аппендер записывает данные в консоль. Далее зарегистрируем еще один аппендер, который будет записывать в файл:

log4j.appender.FILE=org.apache.log4j.RollingFileAppender

Важно отметить, что аппендеры нужно будет еще настроить. Когда у нас уже есть зарегистрированные аппендеры, мы можем определить, какой будет уровень логирования в узлах и какие аппендеры будут при этом использоваться.

log4j.rootLogger=DEBUG, CONSOLE, FILE

• log4j.rootLogger означает, что будем настраивать главный узел, в котором находятся все логи;
• после знака равно первое слово говорит о том, с каким уровнем и выше будут записываться логи (в нашем случае это DEBUG);
• далее после запятой указываются все аппендеры, которые будут использоваться.

Чтобы настроить определенный узел логирования, нужно использовать такую запись:

log4j.logger.com.github.romankh3.logginglecture=TRACE, OWN, CONSOLE

где log4j.logger. используется для настройки определенного узла, в нашем случае это com.github.romankh3.logginglecture. А теперь поговорим о настройке CONSOLE аппендера:

# CONSOLE appender customisation
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.threshold=DEBUG
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=[%-5p] : %c:%L : %m%n

Здесь мы видим, что можно задать уровень, с которого будет обрабатывать именно аппендер. Реальная ситуация: сообщение с уровнем info принял узел логирования и передал аппендеру, который к нему приписан, а вот уже аппендер, с уровнем warn и выше, лог этот принял, но ничего с ним не сделал. Далее нужно определиться с тем, какой шаблон будет в сообщении. Я использую в примере PatternLayout, но там существует множество решений. В данной статье они не будут раскрыты. Пример настройки FILE аппендера:

# File appender customisation
log4j.appender.FILE=org.apache.log4j.RollingFileAppender
log4j.appender.FILE.File=./target/logging/logging.log
log4j.appender.FILE.MaxFileSize=1MB
log4j.appender.FILE.threshold=DEBUG
log4j.appender.FILE.MaxBackupIndex=2
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=[ %-5p] - %c:%L - %m%n

Здесь можно настроить, в какой именно файл будут записываться логи, как видно из

log4j.appender.FILE.File=./target/logging/logging.log

Запись идет в файл logging.log. Чтобы не было проблем с размером файла, можно настроить максимальный: в данном случае 1МБ. MaxBackupIndex говорит о том, сколько будет таких файлов. Если создается больше этого числа, то первый файл будет удален. Чтоб посмотреть на реальный пример, где настроено логирование, можно перейти на открытый репозиторий на GitHub.

Закрепим результат

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

• Создайте свой проект по типу того, что есть в примере выше.
• Если есть знания использования Maven, используем, если нет, то вот ссылка на статью, где описано как подключить библиотеку.

Подведем итоги

1. Мы поговорили о том, какие бывают решения в Java.
2. Почти все известные библиотеки по логированию написали под управлением одного человека :D
3. Мы узнали, что нужно логировать, а что не стоит.
4. Разобрались с уровнями логирования.
5. Познакомились с узлами логирования.
6. Рассмотрели, что такое аппендер и для чего он.
7. Поэтапно настроили файл log4j.properties.

Вопросы и ответы

Чем логирование лучше System.out.println?

Тем, что им можно управлять, не переписывая код. У записи в лог есть уровень, и на продакшене вы одной строчкой в настройках оставляете только WARN и выше, а на своей машине включаете DEBUG. Кроме того, лог уходит не только в консоль: appender умеет писать в файл с ротацией, в базу или по сети. С System.out.println у вас нет ни уровней, ни выбора места записи, ни формата, а убрать такие строки перед релизом можно только руками.

Что такое фасад логирования и зачем он нужен?

Фасад это API, к которому обращается ваш код, ничего не зная о том, кто на самом деле пишет логи. Самый распространенный фасад в Java это SLF4J. Вы вызываете его методы, а реализацию подключаете отдельной зависимостью: Logback, Log4j или JUL. Смысл в том, что подключенные к проекту библиотеки тянут за собой свои логгеры, и без общего фасада все это придется настраивать по отдельности. С фасадом реализацию можно поменять, не тронув ни строчки кода.

Какие есть уровни логирования и чем они отличаются?

В порядке от самого подробного к самому строгому: TRACE, DEBUG, INFO, WARN, ERROR, FATAL. TRACE и DEBUG нужны при отладке, INFO это ожидаемые действия системы, WARN это неожиданность, которую приложение пережило, ERROR это проблема, которую надо решать, FATAL это ошибка, после которой приложение останавливается. По краям стоят два служебных значения: OFF выключает логи целиком, ALL пропускает вообще все. Заданный уровень пропускает сам себя и все, что строже: при INFO в лог попадут INFO, WARN, ERROR и FATAL.

Что такое appender и layout?

Appender это то, куда уходит запись. В Log4j есть готовые: ConsoleAppender пишет в консоль, DailyRollingFileAppender в файл, JDBCAppender в базу данных, TelnetAppender передает по TCP/IP, а AsyncAppender нужен, чтобы запись не била по быстродействию. Layout это то, как выглядит сама строка лога: время, уровень, класс, номер строки, текст сообщения. Если нужного appender нет, можно написать свой, реализовав интерфейс Appender.

Что нельзя писать в логи?

Персональные данные в первую очередь: если чьи-то личные сведения утекут через лог, это обернется реальными проблемами, особенно на проектах, ориентированных на Запад. Туда же пароли, токены и номера карт. Второе ограничение количественное: логи не должны нагружать приложение больше чем на 10 процентов, поэтому логировать каждый шаг подряд не стоит. И не стоит писать все в один файл: рано или поздно читать и дописывать его станет тяжело, а в некоторых системах есть жесткий предел на размер файла.

Почему в SLF4J пишут log.debug("User {} connected", user), а не конкатенацию?

Из-за лишней работы, которая делается впустую. В строке log.debug("User " + user + " connected") конкатенация, а вместе с ней и user.toString(), выполняется всегда, даже если уровень логирования выше DEBUG и запись в лог не попадет. В Log4j это лечили обертыванием в if (log.isDebugEnabled()), то есть тремя строками вместо одной. SLF4J вместо этого принимает шаблон с {} и аргументы отдельно, и подставляет их только тогда, когда запись действительно будет сделана.

Читайте также

• Зачем нужно логирование
• Java Логирование. Размотать клубок стектрейса
• Исключения в Java
• Ошибки в обработке исключений в Java

Дополнительные материалы

1. JavaRush: Логирование. Размотать клубок стектрейса
2. JavaRush: Logger lecture
3. Хабр: Java logging. Hello world
4. Хабр: Java logging: история кошмара
5. Youtube: Головач курсы. Логирование. Часть 1, Часть 2, Часть 3, Часть 4
6. Log4j: appender
7. Log4j: layout

Смотрите также мои другие статьи:

• Как тестовое задание на собеседование превратилось в open-source библиотеку
• Создание системы мониторинга цен на авиабилеты: пошаговое руководство [Часть 1]
• Гайд по созданию клиента для Skyscanner API и его публикации в jCenter и Maven Central [Часть 1]
• Debug в Intellij IDEA: гайд для новичков