Урок 13. Логирование программ Java с помощью SLF4J и Logback

На этом уроке из моего курса Java для новичков я расскажу о логировании. Этот термин идет от древних времен, когда капитан корабля записывал все, что происходило с кораблем. (например, скорость, с которой шел корабль, и его курс). Книга, в которую он записывал эту информацию, называлась "бортовой журнал". Часть слова log происходила от специального инструмента, которым матросы измеряли скорость судна, который состоял из катушки и веревки с бревном, привязанным за один конец.

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

Logback

В течение многих лет наиболее заметным фреймворком ведения журнала был Log4j. На данный момент LOGBack используется, потому что он более мощный. LOGBack был разработан как улучшение Log4j тем же разработчиком, который создал оба, Ceki Gülcü.

Как мы начнем вести журнал? Прежде всего, мы настраиваем зависимости с помощью Maven. Конфигурации требуют зависимостей org.SLF4J, logback-classic и logback-classic. Это реализация SLF4J и является основным кодом LOGBack, поэтому нам нужны эти три зависимости, чтобы войти в наш код.

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>com.mycompany</groupId>
    <artifactId>mavenproject2</artifactId>
    <version>1.0-SNAPSHOT</version>
    <packaging>jar</packaging>
    <dependencies>
        <dependency>
            <groupId>junit</groupId>
            <artifactId>junit</artifactId>
            <version>4.12</version>
            <type>jar</type>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.12</version>
            <type>jar</type>
        </dependency>
    </dependencies>
    <properties>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <maven.compiler.source>1.7</maven.compiler.source>
        <maven.compiler.target>1.7</maven.compiler.target>
    </properties>
</project>

Далее, в каталоге resources (src/main/resources)должен быть файл logback.xml, в котором мы можем определить некоторые вещи, например, как и где следует вести журнал (см код ниже). В этом случае предоставление класса ConsoleAppender позволит регистрировать код непосредственно на консоли. Существуют также другие реализации для ведения журнала, которые позволяют нам войти в файл, в базу данных или в электронную почту (чтобы назвать только некоторые из них). Мы также можем предоставить собственную реализацию для новых источников регистрации, которые не существуют.

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
          <encoder>     
               <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg %n
               </pattern>
          </encoder>
     </appender>

     <logger name="ru.upread.javacourse" level="debug"/>

     <root level="INFO">
          <appender-ref ref="STDOUT" />
     </root>
</configuration>

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

У нас есть разные уровни регистрации, которые в некоторой степени указывают на серьезность проблемы. Уровень ведения журнала DEBUG, как следует из названия, используется для отладки. Отладка - это процесс поиска и устранения ошибок в коде. Отладка должна использоваться нечасто, так как для отладки мы можем использовать отладчик, включенный в IDE, или мы можем писать тесты. Существуют также уровни регистрации информации и ошибок. Ошибка уровня регистрации используется, если в коде есть ошибка, а информация используется для общей информации, например для запуска или остановки сервера или приложения.

В Logback так.xml-файл (в разделе src/main/resources), мы указываем, что мы хотим войти на уровне отладки, и мы предоставляем имя пакета, которое будет указывать, что мы включаем ведение журнала для классов под этим конкретным пакетом.

Для уровня мы могли бы поставить ERROR вместо DEBUG, что означало бы " регистрировать его только в том случае, если это ошибка.” Мы также могли бы ввести информацию, что означало бы "только регистрировать ее, если это информация." Информация включает ошибки уровня информации, а DEBUG включает все три уровня – debug, info и error. Различные уровни делают механизм регистрации более гибким. Также можно использовать различные регистраторы для различных пакетов. Мы также должны установить тег для корневого уровня, который обычно устанавливается на информационный уровень.

Прежде всего, давайте перейдем к нашему классу CarService и добавим детали ведения журнала, как показано на рисунке 3. Нам нужно импортировать орг.slf4j.Логгер. SLF4J знает, как получить доступ к LOGBack, и он найдет зависимость LOGBack classic в файле конфигурации Maven. Мы также импортируем орг.slf4j. LoggerFactory (кстати, фабрика-это еще один тип шаблона дизайна. Короче говоря, фабрики позволяют централизовать место создания объекта, что позволяет более чистый код и предотвращает дублирование кода).

import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
 
public class CarService {
 
    private final Logger log = LoggerFactory.getLogger(CarService.class);
 
    public void process(String input) {
        if (log.isDebugEnabled()) {
            log.debug("processing car:" + input);
        }
    }
}

В классе CarService мы создаем частный конечный регистратор и называем его log. Тогда мы говорим LoggerFactory.getLogger(..). Обычно именно так вы определяете регистратор. На данный момент нам не нужно беспокоиться о том, как создается объект, так как фабрика умна и выполняет всю необходимую работу самостоятельно. Внутри конструктора мы передаем конструктору Logger имя того же класса, в котором он был определен, т. е. CarService класс. Мы использовали проверку if, чтобы убедиться, что наш регистратор был в режиме отладки, прежде чем мы вошли в систему, что является хорошей практикой, потому что в противном случае ваша отладка может привести к снижению производительности. Мы бы создавали строки, фактически не регистрируя их, что потребовало бы ненужных аппаратных ресурсов.

В примере ниже показан тест, который будет использовать службу логирования. Теперь логирование можно использовать в функции process() класса CarService.

import org.junit.Test;

public class CarServiceTest {

     @Test
     public void shouldDemonstrateLogging(){
          CarService carService = new CarService();
          carService.process("BMW");
     }
}

Вход в метод process() задается как "BMW". Это создаст строку, которая будет объединена с “processing car: "и будет записана в журнал.

В этом случае не так уж плохо использовать ведение журнала без проверки, поскольку все, что произойдет, - это объединение аргументов двух строк. Но учтите, что входная строка имеет бесконечную длину. Это соединение двух строк, как бы глупо это ни звучало, может занять много времени. Здесь мы просто имеем очень простую, небольшую программу всего с одной строкой отладки.

Представьте себе тысячу пользователей, одновременно вызывающих этот метод, и это занимает 200 миллисекунд на вызов метода. 200 миллисекунд могут показаться не очень большим временем, но если метод вызывается тысячи раз, это может использовать много вычислительной мощности на сервере или ПК, что приведет к снижению производительности. Мы хотим только объединить строки и подготовить их к логированию, если логрование включено. Е. В результате конкатенация была бы сделана без необходимости. Это то, что мы хотели бы предотвратить, и является причиной, почему мы используем isDebugEnabled, isInfoEnabled или isErrorEnabled и так далее.

Несмотря на то, что логирование конкатенации строк уже достаточно просто с Log4j и SLF4J, существует более простой и разумный способ, как показано ниже в коде. Мы можем поставить фигурные скобки вместо переменных, заменить знак " + " запятой и затем записать входную строку. Платформа проверит, хочет ли пользователь войти в систему на уровне отладки. Если это так, он возьмет эти входные данные, преобразует их в строку, если это еще не строка, и объединит обе строки.

Но строки не будут объединены, если система не находится в режиме отладки, что помогает поддерживать вашу программу максимально эффективной. Здесь, однако, мы не должны использовать условное условие, чтобы проверить это, так как функция отладки внутренне связывает строку. Это стилистически лучше, потому что он занимает меньше строк, в то же время обеспечивая ту же функциональность и защиту от неэффективности.

public void process(String input) {
    log.debug("processing car: {}", input);
}

Здесь у нас есть входные данные, полученные из метода process, и мы хотим напечатать ”processing car:”, объединенный с входной строкой. В нашем тесте мы поставили BMW в качестве входной строки.

Документация Logger

Если вы посмотрите в документации Logger, в разделе «типичный шаблон использования», пример кода, который они показывают (см. пример ниже), будет очень похож на то, что мы сделали в нашем примере. Вы можете войти с помощью logger.isDebugEnabled(), как показано выше, или использовать лучшую альтернативу фигурных скобок. Они очень похожи, но первый способ использует три строки кода, которые загромождают ваш код, а другой - только одну строку, что делает ваш код чище и проще. Ведение журнала важно, но оно не должно мешать тому, чего вы пытаетесь достичь с помощью своего кода. Не забудьте прочитать документацию для лучшего понимания.

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

public class Wombat {
     final Logger logger = LoggerFactory.getLogger(Wombat.class);
     Integer t;
     Integer oldT;
     public void setTemperature(Integer temperature) {
          oldT = t;        
          t = temperature;
          logger.debug("Temperature set to {}. Old temperature was {}.", t, oldT);
          if(temperature.intValue() > 50) {
               logger.info("Temperature has risen above 50 degrees.");
          }
     }
}

Вход на разных уровнях

Теперь рассмотрим ведение журнала на разных уровнях, например, ERROR. Мы все еще на уровне DEBUG, и ERROR включен в DEBUG, потому что DEBUG - самый специфический уровень ведения журнала. В трассировках мы ожидаем увидеть ERROR, а не DEBUG, в качестве префикса для печатной строки журнала, чтобы различать, насколько важны некоторые события регистрации. Например, мы можем записать «Произошла какая-то ошибка» в случае ошибки. В нашем примере «обработка автомобиля:» не является ошибкой, поэтому мы не должны регистрировать это на уровне ОШИБКИ. Мы также можем войти на уровне WARN, в случае предупреждения. Мы будем использовать предупреждение для чего-то очень близкого к ошибке, но там, где это не критично для работы системы, и никто не должен вмешиваться физически. Например, INFO можно использовать при запуске сервера или программы, чтобы команда системного администратора знала, что все идет хорошо.

Appenders

Прежде чем закончить, я бы тоже хотел быстро просмотреть Appenders. Если вы хотите больше узнать, вы можете проверить документацию к приложению.

Существуют разные типы аппендеров. Вот несколько примеров: ConsoleAppender, FileAppender, RollingFileAppender, DBAppender и SMTPAppender. Мы уже использовали ConsoleAppender для записи в консоль. FileAppender используется для записи в файл. RollingFileAppender означает, что новые файлы создаются, когда файл имеет определенный размер, или, например, новый файл журнала создается в начале каждого дня. Это важно для серверов, потому что если мы всегда записываем один и тот же файл, размер файла может достигать тонн гигабайтов. Поэтому RollingFileAppender используется на серверах очень часто. DBAppender позволяет нам напрямую входить в базу данных и очень легко настраивается. SMTPAppender используется для регистрации и отправки электронной почты.

Есть много Appenders, которые вы можете использовать из коробки. Как упоминалось ранее, вы всегда можете расширить его и написать свой собственный Appender, который позволит вам войти в любой другой источник.