Зачем нужен журнал?

Ведение журнала (logging)  —  крайне важно для любого веб-приложения независимо от используемой платформы и языка, включая Spring Boot, Node.js и .NET Core. Регистрация происходящих событий необходима для мониторинга работоспособности и контроля поведения приложения, она позволяет быстрее и эффективнее устранять неполадки. Из журнала разработчики получают ценную информацию о поведении работающего приложения. Это позволяет следить за структурой трафика, поведением пользователей и производительностью системы.

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

Общая схема

Чаще всего регистрация событий приложения включает инициализацию единого регистратора (обычно в файле или консоли), где объединяются журналы из различных частей приложения. Такой централизованный набор журналов упрощает мониторинг и анализ, поскольку обеспечивает единое представление о поведении и состоянии различных модулей и компонентов приложения. Но представьте, что журналы станут слишком большими  —  тогда просматривать их будет непросто. При этом одной из проблем (которую мы будем решать далее) является разделение между журналами регистрации ошибок и прочей информации.

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

Стандартная реализация

Для ведения журнала в обычном приложение Spring по умолчанию используется logback. Поэтому начнем с создания небольшого файла конфигурации под названием src/main/resources/logback.xml.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

<property name="logging.file.name" value="info-log" />
<property name="logging.file.path" value="./"/>

<!-- console log appender -->
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>

<!-- Normal log appender -->
<appender name="NORMAL_FILE" class="ch.qos.logback.core.FileAppender">
<file>${logging.file.path}/${logging.file.name}</file>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>

<root level="TRACE">
<appender-ref ref="NORMAL_FILE"/>
<appender-ref ref="CONSOLE"/>
</root>

</configuration>

Теперь создадим небольшой класс контроллера в src/main/java/<package>/LoggerDemoController.java.

package com.sparkdev.testlogging.controllers;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.http.MediaType;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

import java.util.HashMap;
import java.util.Map;

@RestController
public class LoggerDemoController {

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

@GetMapping(value = "/log", consumes = MediaType.ALL_VALUE)
public ResponseEntity<Object> loggerTest(@RequestParam("q") String q){
Map<String, String> response = new HashMap<>();
try {
LOGGER.info("started...");
response.put("message", "normal flow of the application");
if(q.equalsIgnoreCase("exception")){
throw new RuntimeException("Testing the exception logging mechanism");
}
LOGGER.info("before sending response");
LOGGER.trace("response: "+ response);
return ResponseEntity.ok(response);
}catch (Exception ex){
LOGGER.error("Exception: "+ex.getMessage());
return ResponseEntity.internalServerError().build();
}
}
}

Этот фрагмент кода определяет в приложении Spring Boot класс LoggerDemoController. Метка @RestController указывает на то, что это веб-контроллер. В этот класс входит частный статический финальный регистратор (logger), инициализируемый с помощью LoggerFactory.getLogger (как обычно принято для логирования в приложениях Java).

У контроллера есть конечная точка /log, обрабатывающая запросы GET всех медиа-типов. Метод loggerTest принимает параметр запроса q и регистрирует различные сообщения в зависимости от потока исполнения. Вначале регистрируется запуск процесса и создается карта откликов с сообщением по умолчанию. Если параметр q равен exception, генерируется RuntimeException для имитации сценария ошибки, который затем перехватывается и регистрируется как ошибка. В противном случае контроллер регистрирует намерение отправить ответ вместе с trace-level log для его содержимого. В зависимости от результата операции (successful или exception), возвращается либо ответ, либо внутренняя ошибка сервера. 

Приведенный код иллюстрирует основные методы ведения журнала в приложении Spring Boot, демонстрируя возможности регистрации различных уровней информации (информация, трассировка, ошибки) и обработки exceptions.

Журналы в файле и на консоли содержат одинаковые строки

Чтобы все записывалось в наш файл и консоль, в файле log configuration для корневого регистратора (root logger) обратите внимание на уровень журнала TRACE. В действительности порядок приоритета уровней журналов следующий: Trace < Debug < Info < Warn < Error < Fatal. Установив уровень журнала на INFO наблюдайте за изменениями непосредственно.

Усовершенствованная версия

Разработаем небольшой вспомогательный класс LoggerFactory, который расширит возможности регистрации и выбора методов ведения журнала.

src/main/java/<package>/LoggerFactory.java:

package com.sparkdev.testlogging.utils;

import org.slf4j.Logger;

import java.util.HashMap;
import java.util.Map;

public class LoggerFactory {

private static final Map<String, Logger> LOGGER_MAP = new HashMap<>();

private LoggerFactory() {
LOGGER_MAP.put("info_log", org.slf4j.LoggerFactory.getLogger("info_log"));
LOGGER_MAP.put("error_log", org.slf4j.LoggerFactory.getLogger("error_log"));
}

public static LoggerFactory getLogger() {
return new LoggerFactory();
}

public void info(String message) {
LOGGER_MAP.get("info_log").info(message);
}

public void error(String message) {
LOGGER_MAP.get("error_log").error(message);
}

public void error(String message, Throwable exception) {
LOGGER_MAP.get("error_log").error(message, exception);
}
}

Конечно, возможности у этого служебного класса достаточно ограниченные, но его можно расширить. Сначала рассмотрим изменения в конфигурации журналирования.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

<property name="logging.file.name" value="info-log" />
<property name="logging.file.path" value="./"/>
<property name="logging.error.file.name" value="error-log" />
<property name="logging.error.file.path" value="./"/>

<!-- console log appender -->
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>

<!-- Normal log appender -->
<appender name="NORMAL_FILE" class="ch.qos.logback.core.FileAppender">
<file>${logging.file.path}/${logging.file.name}</file>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>

<!-- Error log appender -->
<appender name="ERROR_FILE" class="ch.qos.logback.core.FileAppender">
<file>${logging.error.file.path}/${logging.error.file.name}</file>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>

<!-- Logger definitions for info -->
<logger name="info_log" level="info">
<appender-ref ref="NORMAL_FILE"/>
</logger>

<!-- Logger definitions for error -->
<logger name="error_log" level="error">
<appender-ref ref="ERROR_FILE"/>
</logger>

</configuration>

Теперь изменим контроллер для доступа к утилите LoggerFactory вместо пакета slf4j.

package com.sparkdev.testlogging.controllers;

import com.sparkdev.testlogging.utils.LoggerFactory;
import org.springframework.http.MediaType;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

import java.util.HashMap;
import java.util.Map;

@RestController
public class LoggerDemoController {

private static final LoggerFactory LOGGER = LoggerFactory.getLogger();

@GetMapping(value = "/log", consumes = MediaType.ALL_VALUE)
public ResponseEntity<Object> loggerTest(@RequestParam("q") String q){
Map<String, String> response = new HashMap<>();
try {
LOGGER.info("started...");
response.put("message", "normal flow of the application");
if(q.equalsIgnoreCase("exception")){
throw new RuntimeException("Testing the exception logging mechanism");
}
LOGGER.info("before sending response");
return ResponseEntity.ok(response);
}catch (Exception ex){
LOGGER.error("Exception: "+ex.getMessage());
return ResponseEntity.internalServerError().build();
}
}
}

В этой реализации получаем 2 файла, а именно Info_log и error_log. Интуитивно понятно, что все ошибки регистрируются в error_log, а все информационные журналы записываются в info_log. Весь объем работы выполняется служебным классом.

Журналы exception и обычных сообщений

Финальная версия

Создание вспомогательных (утилитных) классов сопряжено с целым рядом возможных ошибок. Их исправление может оказаться трудоемким процессом. Поэтому попытаемся настроить конфигурацию так, чтобы описанные выше задачи выполняли такие стандартные библиотеки, как slf4j и log4j2.

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="WARN">

<property name="logging.error.file.name" value="error-log" />
<property name="logging.error.file.path" value="./"/>
<property name="logging.file.name" value="info-log" />
<property name="logging.file.path" value="./"/>

<!-- Normal log appender -->
<appender name="INFO_FILE" class="ch.qos.logback.core.FileAppender">
<file>${logging.file.path}/${logging.file.name}</file>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>INFO, DEBUG, TRACE</level>
</filter>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>ERROR, WARN</level>
<onMatch>DENY</onMatch>
<onMisMatch>NEUTRAL</onMisMatch>
</filter>
</appender>

<!-- Error log appender -->
<appender name="ERROR_FILE" class="ch.qos.logback.core.FileAppender">
<file>${logging.error.file.path}/${logging.error.file.name}</file>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>ERROR, WARN</level>
</filter>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO, DEBUG, WARn</level>
<onMatch>DENY</onMatch>
<onMisMatch>NEUTRAL</onMisMatch>
</filter>
</appender>

<root level="INFO">
<appender-ref ref="INFO_FILE"/>
<appender-ref ref="ERROR_FILE"/>
</root>

</configuration>

Приведенная выше конфигурация позволяет исключить утилиту LoggerFactory, используя стандартный класс LoggerFactory из библиотеки slf4j. Контроллер выглядит так:

package com.sparkdev.testlogging.controllers;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.http.MediaType;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

import java.util.HashMap;
import java.util.Map;

@RestController
public class LoggerDemoController {

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

@GetMapping(value = "/log", consumes = MediaType.ALL_VALUE)
public ResponseEntity<Object> loggerTest(@RequestParam("q") String q){
Map<String, String> response = new HashMap<>();
try {
LOGGER.info("started...");
response.put("message", "normal flow of the application");
if(q.equalsIgnoreCase("exception")){
throw new RuntimeException("Testing the exception logging mechanism");
}
LOGGER.info("before sending response");
return ResponseEntity.ok(response);
}catch (Exception ex){
LOGGER.error("Exception: "+ex.getMessage());
return ResponseEntity.internalServerError().build();
}
}
}

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

Заключение

Значительно более удобное и понятное ведение журнала в приложении Spring Boot обеспечивает настройка с раздельными уровнями и файлами. Гибкая мощная система ведения журналов Logback позволяет эффективно разделять в отдельные файлы журналы уровней INFO и ERROR. Такой подход упрощает анализ журналов и устранение неполадок, поскольку позволяет быстро получить доступ к журналам определенного типа, которые нужны для повседневного мониторинга или исследования ошибок.

Простота и эффективность этой конфигурации делают ее незаменимой для любого надежного приложения Spring Boot. Ясное и структурированное ведение журнала  —  это не просто хороший стиль программирования, а еще и упрощенные отладка и обслуживание приложений в рабочей среде.

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

Читайте нас в Telegram, VK и Дзен


Перевод статьи M K Pavan Kumar: Effective Logging Practices for Spring Boot Applications

Предыдущая статьяИтоги 8 лет с Kubernetes в продакшене: два крупных сбоя кластера, отказ от самостоятельного управления, сокращение затрат на кластер, инструментарий и многое другое
Следующая статьяОтложенная загрузка на уровне шаблонов в Angular