Всем привет, JavaRush сообщество! Логирование: что, как, где и чем? - 1Сегодня поговорим о логировании:
  1. Что это, зачем это. В каких случаях лучше использовать, в каких — нет.
  2. Какие бывают реализации логирования в Java и что с этим разнообразием нам делать.
  3. Уровни логирования. Обсудим, что такое appender и как его правильно настроить.
  4. Узлы логирования и как правильно их настраивать, чтоб все работало так, как мы хотим.
Этот материал рассчитан на широкую аудиторию. Он будет понятен и тем, кто только знакомится с Java, и тем, кто уже работает, но разобрался только с logger.info(“log something”); Поехали!

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

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

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

Логирование: что, как, где и чем? - 2Из известных решений по логированию в Java можно выделить:
  • log4j
  • JUL — java.util.logging
  • JCL — jakarta commons logging
  • Logback
  • SLF4J — simple logging facade for java
Обзорно рассмотрим каждое из них, а в практической части материала возьмем за основу связку Slf4jlog4j. Сейчас это может показаться странным, но не переживайте: к концу статьи все будет понятно.

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, common-loggins и 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(). Благодаря чему, только в случае, если уровень логирования позволяет записывать в лог, это сообщение конкатенировать в единое. После этого SJF4J стал быстро расти в популярности, и на данный момент это лучшее решение. Поэтому будем рассматривать логирование на примере связки slf4j-log4j12.

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

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

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

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

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

x: Visible
FATAL ERROR WARN INFO DEBUG TRACE ALL
OFF
FATAL x
ERROR x x
WARN x x x
INFO x x x x
DEBUG x x x x x
TRACE x x x x x x
ALL x x x x x x x
Что такое уровни логирования? Для того, чтоб как-то ранжировать логи, нужно было дать определенные обозначения и разграничения. Для этого ввели уровни логирования. Уровень задается в приложении. Если запись относится к уровню ниже обозначенного, она не вносится в лог. Например, у нас есть логи, с помощью которых дебажат приложение. В нормальной работе на продакшене (когда приложение используют по назначению), такие логи не нужны. Поэтому уровень логирования будет выше, чем для дебага. Давайте рассмотрим уровни на примере 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.
Есть еще несколько реализаций: полный список можно получить здесь. Кстати, если нужного аппендера не будет, это не проблема. Можно написать свой аппендер, имплементировав интерфейс Appender, который как раз принимает log4j. Логирование: что, как, где и чем? - 3

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

Для демонстрации будем использовать интерфейс 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. Это узел, который принимает все логи всего приложения. Остальные можно изобразить, как показано ниже: Логирование: что, как, где и чем? - 4Аппендеры настраивают свою работу именно на узлы логирования. Сейчас на примере log4j.properties будем смотреть, как их настроить.

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

Сейчас мы поэтапно все настроим и посмотрим, что можно сделать:
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.proterties файл.

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

  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
Смотрите также мои другие статьи: