Зачем нужно логирование

Привет! При написании лекций я особо отмечаю, если какая-то конкретная тема обязательно будет использоваться в реальной работе. Так вот, ВНИМАНИЕ! Тема, которой мы коснемся сегодня, точно пригодится тебе на всех твоих проектах с первого дня работы. Мы поговорим о логировании. Логирование нужно для того, чтобы у программы осталась письменная память о собственной работе. Пока ты пишешь код, тебе видно все: отладчик, консоль, значения переменных на каждом шаге. На боевом сервере ничего этого нет, а разбираться с падением придется задним числом и часто по чужому описанию «оно не работает». Лог это единственный след, по которому можно восстановить, что программа делала перед сбоем: какие данные к ней пришли, какие шаги отработали, где именно вылетело исключение. Поэтому логи ведут во всех промышленных проектах, а в Java для этого берут фасад SLF4J и одну из библиотек под ним, чаще всего Log4j 2.Тема эта совсем не сложная (я бы даже сказал легкая). Но на первой работе и без того будет достаточно стресса, чтобы еще разбираться с очевидными вещами, поэтому лучше досконально разобрать ее сейчас :) Итак, начнем.

Кратко

• Логирование это запись хода работы программы в отдельное место, которое называют логом. Простейший его вид ты уже использовал в учебе: System.out.println().
• В реальных проектах пишут не в консоль, а в файл: его удобно хранить, передавать коллегам и искать по нему.
• В Java логируют через фасад SLF4J, а под ним работает конкретная библиотека, чаще всего Log4j 2. Код зависит только от SLF4J, поэтому библиотеку можно поменять, не трогая программу.
• Логгер это объект, который делает записи. Аппендер это место, куда они попадают: консоль, файл и так далее.
• У каждой записи есть уровень: TRACE, DEBUG, INFO, WARN, ERROR. Уровень в конфигурации работает как порог и отсекает все менее важное.
• Аппендер и уровень задают в файле log4j2.xml. Пока его нет, Log4j 2 пишет только ошибки и только в консоль.

Что такое логирование

Логирование это запись куда-то данных о работе программы. Место, куда эти данные записываются называется «лог». Возникает сразу два вопроса: куда и какие данные записываются?

Куда пишут логи

Записывать данные о работе программы можно во множество разных мест. Например, ты во время учебы часто выводил данные в консоль с помощью System.out.println(). Это настоящее логирование, хоть и самое простое. Конечно, для клиента или команды поддержки продукта это не очень удобно: они явно не захотят устанавливать IDE и мониторить консоль :) Есть и более привычный человеку формат записи информации: текстовый файл. Людям гораздо удобнее читать их в таком виде, и уж точно гораздо удобнее хранить!

Какие данные писать в лог

А вот здесь все зависит от тебя! Система логирования в Java очень гибкая. Ты можешь настроить ее таким образом, что в лог попадет весь ход работы твоей программы. Это, с одной стороны, хорошо. Но с другой стороны, представь себе, каких размеров могут достичь логи Facebook или Twitter, если туда писать вообще все. У таких крупных компаний наверняка есть возможность хранить даже такое количество информации. Но вообрази, как сложно будет искать информацию об одной критической ошибке в логах на 500 гигабайт текста? Это даже хуже, чем иголка в стоге сена. Поэтому логирование в Java можно настроить так, чтобы в журнал (лог) записывались только данные об ошибках. Или даже только о критических ошибках!

Почему в Java логируют через SLF4J

Хотя, говорить «логирование в Java» не совсем верно. Дело в том, что потребность ведения логов возникла у программистов раньше, чем этот функционал был добавлен в язык. И к тому времени, как в Java появился собственная библиотека для логирования, все уже пользовались библиотекой log4j. История появления логирования в Java на самом деле очень долгая и познавательная, на досуге можешь почитать этот пост на Хабре. Короче говоря, своя библиотека логирования в Java есть, но ей почти никто не пользуется :) Позже, когда появились несколько разных библиотек логирования, и все программисты начали пользоваться разными, возникла проблема совместимости. Чтобы люди не делали одно и то же с помощью десятка разных библиотек с разными интерфейсами, был создан абстрагирующий фреймворк slf4j (Simple Logging Facade for Java). Абстрагирующим он называется потому, что хотя ты и пользуешься классами slf4j и вызываешь их методы, под капотом у них работают все предыдущие фреймворки логирования: log4j, стандартный java.util.logging и другие. Если тебе в данный момент нужна какая-то специфическая фича log4j, которой нет у других библиотек, но ты не хотел бы при этом жестко привязывать проект именно к этой библиотеке, просто используй slf4j. А она уже «дернет» методы log4j. Если ты передумаешь и решишь, что фичи log4j тебе больше не нужны, тебе надо только перенастроить «обертку» (то есть slf4j) на использование другой библиотеки. Твой код не перестанет работать, ведь в нем ты вызываешь методы slf4j, а не конкретной библиотеки.

Подключаем библиотеки к проекту

Небольшое отступление. Чтобы следующие примеры заработали, тебе нужно скачать библиотеку slf4j отсюда, и библиотеку log4j отсюда. Далее архив нужно распаковать и добавить нужные нам jar-файлы в classpath через IntelliJ IDEA:

1. распаковать скачанные архивы;
2. открыть пункты меню File -> Project Structure -> Libraries;
3. выбрать нужные jar-ники и добавить в проект (в архивах, которые мы скачали, лежит много jar’ников, посмотри нужные на картинках).

Примечание: эта инструкция для тех студентов, которые не умеют использовать Maven. Если ты умеешь им пользоваться, лучше попробуй начать с него: это обычно намного проще Если используешь Maven, добавь такую зависимость:

    	<dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-slf4j2-impl</artifactId>
            <version>2.26.1</version>
    	</dependency>

Пара слов про версии, раз уж мы их тут прописываем. Артефакт называется log4j-slf4j2-impl: это мост от SLF4J версии 2 к Log4j 2, и он сам подтянет за собой все остальное. Старое имя log4j-slf4j-impl в документации теперь идет под пометкой «Are you still using SLF4J 1.x?», так что новому проекту нужно первое. И тем более не переписывай номер версии со скриншотов выше: там log4j 2.11.2 и slf4j 1.7.26, снятые несколько лет назад. Все ветки Log4j 2 от 2.0-beta9 до 2.15.0 попали под уязвимость CVE-2021-44228, ту самую Log4Shell с максимальной оценкой опасности 10.0. Точные диапазоны перечислены на странице безопасности Apache, а качать всегда стоит текущую версию со страницы загрузки. Отлично, с настройками разобрались :) Давай рассмотрим, как работает slf4j.

Логгер и аппендер

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

Логгер

Начнем с первого. Логгер это объект, который полностью управляет ведением записей. Создать логгер очень легко: это делается с помощью статического метода LoggerFactory.getLogger(). В качестве параметра в метод нужно передать класс, работа которого будет логироваться. Запустим наш код:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class MyTestClass {

   public static final Logger LOGGER = LoggerFactory.getLogger(MyTestClass.class);

   public static void main(String[] args) {

       LOGGER.info("Test log record!!!");
       LOGGER.error("В программе возникла ошибка!");
   }
}

Вывод в консоль: ERROR StatusLogger No Log4j 2 configuration file found. Using default configuration (logging only errors to the console), or user programmatically provided configurations. Set system property 'log4j2.debug' to show Log4j 2 internal initialization logging. See https://logging.apache.org/log4j/2.x/manual/configuration.html for instructions on how to configure Log4j 2 15:49:08.907 [main] ERROR MyTestClass - В программе возникла ошибка! Что же мы тут видим? Сначала мы видим сообщение об ошибке. Она появилась, потому что сейчас у нас не хватает необходимых настроек. Поэтому наш логгер сейчас умеет выводить только сообщения об ошибках (ERROR) и только в консоль. Метод logger.info() выполнен не был. А вот logger.error() сработал! В консоли появилось время записи, имя потока, в котором работала программа (main), слово ERROR, имя логгера (MyTestClass) и наше сообщение! Имя потока тут легко принять за имя метода: они совпали случайно, потому что метод main() выполняется в потоке с тем же именем.

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

ERROR это уровень логирования. В общем, если запись в логе помечена словом ERROR, значит, в этом месте программы произошла ошибка. Если запись помечена словом INFO, значит, это просто текущая информация о нормальной работе программы. В библиотеке SLF4J довольно много разных уровней логирования, которые позволяют гибко настроить ведение журнала. Управлять ими очень легко: вся необходимая логика уже заложена в класс Logger. Тебе достаточно просто вызывать нужные методы. Если ты хочешь залогировать обычное сообщение, вызывай метод logger.info(). Сообщение об ошибке: logger.error(). Вывести предупреждение: logger.warn() Вот все уровни, которые есть в Log4j 2, от самого серьезного к самому подробному. Уровень, указанный в конфигурации, работает как порог: в лог попадают записи этого уровня и всех уровней важнее. Поставишь INFO и потеряешь DEBUG с TRACE, поставишь ERROR и останутся одни ошибки. Полный список уровней с приоритетами есть в документации Log4j 2. Обрати внимание на первую строку. FATAL есть в Log4j 2, а вот у SLF4J метода fatal() нет: его роль там отдана маркерам. Так что если пишешь через фасад, самый серьезный доступный уровень это ERROR.

Аппендер

Аппендер это место, куда приходят твои данные. Можно сказать, противоположность источнику данных, «точка B». По умолчанию данные выводятся в консоль. Обрати внимание, в предыдущем примере нам не пришлось ничего настраивать: текст появился в консоли сам, но при этом логгер из библиотеки log4j умеет выводить в консоль только сообщения уровня ERROR. Людям же, очевидно, удобнее читать логи из текстового файла и хранить логи в таких же файлах.

Настраиваем запись логов в файл

Чтобы изменить поведение логгера по умолчанию, нам нужно сконфигурировать свой файловый аппендер. Для начала, прямо в папке src нужно создать файл log4j2.xml, или в папке resources, если используешь Maven. Имя тут важно: Log4j 2 ищет в classpath файлы, которые называются log4j2 с расширением xml, json, yaml или properties, а привычное по первой версии библиотеки имя log4j.xml он просто не заметит и продолжит работать с настройками по умолчанию. Порядок поиска описан в документации. С форматом xml ты уже знаком, у нас недавно была лекция про него :) Вот таким будет его содержимое:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
   <Appenders>
       <File name="MyFileAppender" fileName="C:\Users\Username\Desktop\testlog.txt" append="true">
           <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
       </File>
   </Appenders>
   <Loggers>
       <Root level="INFO">
           <AppenderRef ref="MyFileAppender"/>
       </Root>
   </Loggers>
</Configuration>

Выглядит не особо-то и сложно :)

Разбираем конфигурацию по частям

Но давай все-таки пройдемся по содержимому.

<Configuration status="INFO">

Это так называемый status-logger. Он не имеет отношения к нашему логгеру и используется во внутренних процессах log4j. Можешь установить status=”TRACE” вместо status=”INFO”, и в консоль будет выводиться вся информация о внутренней работе log4j (status-logger выводит данные именно в консоль, даже если наш аппендер для программы будет файловым). Нам это сейчас не нужно, поэтому оставим все как есть.

<Appenders>
   <File name="MyFileAppender" fileName="C:\Users\Username\Desktop\testlog.txt" append="true">
       <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
   </File>
</Appenders>

Тут мы создаем наш аппендер. Тег <File> указывает что он будет файловым. name="MyFileAppender": имя нашего аппендера. fileName="C:\Users\Username\Desktop\testlog.txt": путь к лог-файлу, куда будут записываться все данные. append="true": нужно ли дозаписывать данные в конец файла. В нашем случае так и будет. Если установить значение false, при каждом новом запуске программы старое содержимое лога будет удаляться. <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> это настройки форматирования. Никаких регулярных выражений здесь нет: строка собрана из спецификаторов, и каждый подставляет свой кусочек записи. %d это дата и время, %t имя потока, %-5level уровень, выровненный по пяти символам, %logger{36} имя логгера, %msg само сообщение, %n перевод строки. Полный список спецификаторов есть в описании PatternLayout.

<Loggers>
       <Root level="INFO">
           <AppenderRef ref="MyFileAppender"/>
       </Root>
</Loggers>

Здесь мы указываем уровень логирования (root level). У нас установлен уровень INFO: то есть в лог попадут записи уровня INFO и всех уровней важнее его, а менее важные, DEBUG и TRACE (по таблице, которую мы рассматривали выше), отсеются. У нас в программе будет 3 сообщения: одно INFO, одно WARN и одно ERROR. С текущей конфигурацией все 3 сообщения будут записаны в лог. Если ты поменяешь значение root level на ERROR, в лог попадет только последнее сообщение из LOGGER.error(). Кроме того, сюда же помещается ссылка на аппендер. Чтобы создать такую ссылку, нужно внутри тега <Root> создать тег <AppenderRef> и добавить ему параметр ref=”имя твоего аппендера”. Имя аппендера мы создали вот тут, если ты забыл: <File name="MyFileAppender"

Программа целиком

А вот и код нашей программы!

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class MyTestClass {

   public static final Logger LOGGER = LoggerFactory.getLogger(MyTestClass.class);

   public static void main(String[] args) {

       LOGGER.info("Начало работы программы!!!");

       try {
           LOGGER.warn("Внимание! Программа пытается разделить одно число на другое");
           System.out.println(12/0);
       } catch (ArithmeticException x) {

           LOGGER.error("Ошибка! Произошло деление на ноль!");
       }
   }
}

Он, конечно, немного кривоватый (перехват RuntimeException это так себе идея, подробности в статье про исключения в Java), но для наших целей отлично подойдет :) Давай запустим наш метод main() 4 раза подряд и посмотрим на наш файл testlog.txt. Создавать его заранее не нужно: библиотека сделает это автоматически. Все заработало! :) Теперь у тебя есть настроенный логгер. Ты можешь поиграться с какими-то написанными тобой ранее программами, добавив вызовы логгера во все методы, и посмотреть на получившийся журнал:)

Две привычки, которые стоит завести сразу

Первая касается того, как собирается текст сообщения. Вот так делать не надо:

LOGGER.debug("Пользователь " + name + " заказал " + count + " товаров");

А надо вот так:

LOGGER.debug("Пользователь {} заказал {} товаров", name, count);

Фигурные скобки это места для подстановки, аргументы встают в них по порядку. Разница не только в том, что читать удобнее. В первом варианте строка склеивается всегда, даже когда уровень DEBUG выключен и запись никуда не пойдет: число превратят в текст, куски соединят, результат выбросят. Во втором библиотека сначала смотрит на уровень и только потом берется за аргументы. В цикле, который крутится миллионы раз, это уже заметно. Подробнее об этом в SLF4J FAQ, в пункте про самый быстрый способ ничего не логировать. Вторая привычка про объявление самого логгера. У нас в примерах он public, так короче, но в рабочем коде его почти всегда пишут вот так:

private static final Logger LOGGER = LoggerFactory.getLogger(MyTestClass.class);

private потому, что логгер это внутреннее дело класса и снаружи он никому не нужен. static потому, что одного объекта на весь класс достаточно, незачем создавать его заново с каждым экземпляром. final потому, что подменять его после создания нечем и незачем.

Что почитать дальше

В качестве дополнительного чтения загляни в раздел документации Log4j 2 про аппендеры. Там разобраны все виды аппендеров, и за один раз прочитать этот раздел будет непросто. Но в нем содержится очень много полезной дополнительной информации. Например, ты научишься настраивать RollingFileAppender так, чтобы логгер заводил новый текстовый файл, когда наш testlog.txt дорос до определенного размера :) Если хочется того же на русском и с примерами из реальных проектов, есть отдельный разбор: Логирование в Java: что, как, где и чем? А наше занятие на этом завершено! Ты сегодня познакомился с очень важной темой, и эти знания точно пригодятся тебе в дальнейшей работе. До новых встреч! :)

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

Зачем логировать, если можно все вывести через System.out.println()?

System.out.println() это тоже логирование, но самое примитивное. Вывод в консоль исчезает вместе с закрытой консолью, его нельзя приглушить без правки кода, и в нем нет ни времени, ни уровня важности, ни имени класса. Библиотека логирования дает все это сразу: запись уходит в файл, у нее есть уровень, а объем вывода меняется правкой конфигурации, без пересборки программы.

Чем SLF4J отличается от Log4j 2?

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

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

В Log4j 2 их шесть: FATAL, ERROR, WARN, INFO, DEBUG и TRACE, от самого серьезного к самому подробному. У SLF4J их пять, метода fatal() там нет. Уровень, указанный в конфигурации, работает как порог: в лог попадают записи этого уровня и всех уровней важнее. На боевом сервере обычно ставят INFO или WARN, а при отладке опускают до DEBUG.

Как настроить запись логов в файл?

Нужен файл конфигурации log4j2.xml в папке src или resources. В нем описывают аппендер типа File с путем к файлу и шаблоном строки, а потом ссылаются на этот аппендер из тега Root, где заодно указывают уровень логирования. Сам файл лога создавать заранее не нужно, библиотека сделает это сама.

Что такое аппендер?

Аппендер это адресат записи, то есть место, куда логгер отправляет готовую строку. Бывает консольный, файловый, аппендер с ротацией файлов по размеру или дате, отправка в базу или во внешнюю систему сбора логов. У одного логгера может быть сразу несколько аппендеров, тогда одна и та же запись уйдет в несколько мест.

Почему логи идут в консоль, а не в файл?

Почти всегда причина одна: Log4j 2 не нашел файл конфигурации и включил настройки по умолчанию. Об этом прямо говорит строка «No Log4j 2 configuration file found» в начале вывода. Проверь, что файл называется именно log4j2.xml, а не log4j.xml, и лежит в папке, которая попадает в classpath.

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

• Логирование в Java: что, как, где и чем?
• Подключаем к нашему JavaRush проекту логирование (slf4j и log4j)
• Как обрабатывать исключения в Java
• XML в Java: что это?