Простое логирование при помощи Log4j

Log4j - одна из первых библиотек, созданных для упрощения процедуры логирования. Эта библиотека прошла испытание временем, поэтому до сих широко используется в java-приложениях. В этой заметке я продемонстрирую минимальную настройку log4j для быстрого старта.

В большинстве информационных систем среди уровней логирования выделяют следующие (от более низкого к более высокому):

1. TRACE - сообщения самого низкого уровня, наиболее подробные
2. DEBUG - отладочные сообщения, менее подробные, чем TRACE
3. INFO - стандартные информационные сообщения
4. WARN - некритичные ошибки, не препятствующие работе приложения
5. ERROR - ошибки, которые могут привести к неверному результату
6. FATAL - ошибки, препятствующие дальнейшей работе приложения

При каждом последующем уровне количество выводимой информации уменьшается, но её критичность при этом должна увеличиваться.

В качестве примера рассмотрим простое приложение, состоящее всего из одного класса и одного конфигурационного файла. Если вы разрабатываете в Idea, то вот вам пошаговая инструкция:

1. File - New Project, там выберите тип проекта Java, убедитесь, что не отмечено ни одного пункта и жмите Next.
2. Здесь тоже ничего не надо отмечать, просто жмите Next.
3. Укажите какое-нибудь название для проекта. Рекомендую использовать только строчные буквы, а пробелы заменять дефисом. Жмите Finish.

Здесь среда разработки создаст самую простую структуру проекта. Прежде чем приступить к написанию кода нам нужно подключить библиотеку log4j в виде jar-файла. Вы можете либо скачать его вручную, либо загрузить из maven-репозитория при помощи Idea (если у вас настроен maven).

Как подключить стороннюю библиотеку к проекту. Открывайте File - Project Structure, затем в левой панели выберите Libraries, затем жмите на зелёный плюс. И тут у вас есть выбор: либо добавить jar-файл к проекту, указав его расположение в файловой системе, либо загрузив его из maven-репозитория. Чтобы загрузить библиотеку из репозитория, просто укажите её название и версию как указано на картинке ниже:

Обязательно отметьте пункт Download to, не меняя его значения по умолчанию - тогда библиотека будет загружена прямо в ваш проект.

Создайте в папке src вашего проекта какой-нибудь пакет (например, ru.nordmine), а в нём создайте класс SimpleMain с таким содержимым:

package ru.nordmine;

import org.apache.log4j.Logger;

public class SimpleMain {

private static final Logger logger = Logger.getLogger(SimpleMain.class);

public static void main(String[] args) {
for(int i = 0; i < 3; i++) {
try {
logger.info("result: " + divide(i));
} catch (Exception e) {
logger.error(e.getMessage(), e);
}
}
}

public static int divide(int x) {
logger.debug("divide method invoked; 2 / " + x);
if(x == 0) {
logger.warn("x = 0; exception may occur");
}
return 2 / x;
}
}

В классе SimpleMain логгер определён в виде приватного статического и неизменяемого поля. В качестве параметра метода, который его создаёт, передаём текущий класс. В самом методе main в цикле вызывается метод divide, который выполняет какую-то работу. Неважно какую, в качестве примера он делит 2 на то число, которое ему передали. Обратите внимание на уровни логирования.

В методе divide при старте выводится сообщение уровня debug о том, что метод запущен и с каким параметром. Предположим, что мы используем уровень логирования INFO, поэтому данное сообщение будет выводится не будет. И зачем, ведь нам не интересно знать о каждом выводе метода и с каким параметром.

Далее, поскольку метод делит 2 на то, что к нему пришло, есть некая вероятность деления на нуль (что и прозойдёт в нашем примере). Поэтому лучше проверять входные аргументы и выводить предупреждение, если что-то будет не так. Уровень WARN выше, чем INFO, поэтому при текущем уровне логирования предупреждение будет выведено.

В методе main в цикле мы вызываем метод divide, передавая ему последовательно аргументы от 0 до 2. Зная, что в вызываемом методе потенциально может возникнуть ошибка, обернём его вызов в конструкцию try-catch. Обратите внимание, что она внутри цикла, а не снаружи. То есть ошибочный аргумент метода не остановит весь цикл, а только одну итерацию, что логично. Если вызов пройдёт успешно, будет показан результат с уровнем INFO, если произойдёт исключение, то будет выведен текст ошибки с уровнем ERROR и полный stack trace, ведь мы передаём логгеру не только текст ошибки, но и объект исключения. И это правильно, т.к. среди однотипных записей лога гораздо быстрее обнаружить stack trace, чем неприметную запись ERROR.

Теперь осталось сконфигурировать логгер. Его конфигурация может быть в двух форматах: обычном текстовом property-файле (log4j.properties) и в формате xml (log4j.xml). Начнём с более простого текстового. Положите файл log4j.properties со следующим содержимым в корень вашего проекта:

# Root logger option
log4j.rootLogger=INFO, stdout

# Direct log messages to stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

Это пожалуй самый простой вариант настройки логгирования, при котором сообщения в указанном формате будут выводить только на консоль, причём только если уровень не ниже INFO.

А теперь давайте сконфигурируем логгер таким образом, чтобы сообщения выводились в консоль и в файл. Поместим эту конфигурацию в файл log4j.xml, который положим в корень папки src.

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration PUBLIC
        "-//APACHE//DTD LOG4J 1.2//EN"
        "http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/xml/doc-files/log4j.dtd">
<log4j:configuration debug="false">
    <appender name="ConsoleAppender" class="org.apache.log4j.ConsoleAppender">
        <param name="Encoding" value="utf-8"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n"/>
        </layout>
    </appender>
    <appender name="FileAppender" class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="messages"/>
        <param name="DatePattern" value="'-'yyyy-MM-dd"/>
        <param name="Encoding" value="utf-8"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n"/>
        </layout>
    </appender>
    <root>
        <priority value="INFO"/>
        <appender-ref ref="ConsoleAppender"/>
        <appender-ref ref="FileAppender"/>
    </root>
</log4j:configuration>

В этой конфигурации мы отключаем вывод отладочной информации самого логгера (иногда это тоже может пригодиться). Для добавления записи в лог используется так называемый аппендер. В библиотеке определено множество различных типов аппендеров, мы же здесь рассмотрим два из них: ConsoleAppender (вывод в консоль) и DailyRollingFileAppender (запись в файл).

Если с консолью всё понятно, то почему был выбран именно DailyRollingFileAppender? Дело в том, что этот тип аппендера позволяет не просто записывать в файл, а ещё и автоматически архивировать эти файлы. Например, создавать каждые сутки новый файл для лога. Имя файла, а заодно и правила ротации, задаёт параметр DatePattern. В нашем примере файлы будут создаваться каждые сутки. Имя файла будет иметь формат "messages-ГГГГ-ММ-ДД". Файл, в который в настоящий момент ведётся запись, имеет имя "messages" (параметр File) без метки времени. Можно настроить ротацию также каждый час и даже каждую минуту. В зависимости от того, как много записей добавляется в лог.

В конце указываем минимальный корневой уровень логирования (INFO) для обоих аппендеров. Записи ниже этого уровня добавляться не будут.

Теперь, если запустить наше приложение, мы увидим только одну строку с уровнем INFO (в файл была добавлена точно такая же строка):

2014-06-02 20:40:36 WARN  SimpleMain:22 - x = 0; exception may occur
2014-06-02 20:40:36 ERROR SimpleMain:14 - / by zero
java.lang.ArithmeticException: / by zero
at ru.nordmine.SimpleMain.divide(SimpleMain.java:24)
at ru.nordmine.SimpleMain.main(SimpleMain.java:12)
2014-06-02 20:40:36 INFO  SimpleMain:12 - result: 2
2014-06-02 20:40:36 INFO  SimpleMain:12 - result: 1

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

2014-06-02 20:41:33 DEBUG SimpleMain:20 - divide method invoked; 2 / 0
2014-06-02 20:41:33 WARN  SimpleMain:22 - x = 0; exception may occur
2014-06-02 20:41:33 ERROR SimpleMain:14 - / by zero
java.lang.ArithmeticException: / by zero
at ru.nordmine.SimpleMain.divide(SimpleMain.java:24)
at ru.nordmine.SimpleMain.main(SimpleMain.java:12)
2014-06-02 20:41:33 DEBUG SimpleMain:20 - divide method invoked; 2 / 1
2014-06-02 20:41:33 INFO  SimpleMain:12 - result: 2
2014-06-02 20:41:33 DEBUG SimpleMain:20 - divide method invoked; 2 / 2
2014-06-02 20:41:33 INFO  SimpleMain:12 - result: 1