Эффективное ведение журнала для приложений Spring Boot

Published in

NOP::Nuances of Programming

6 min readMay 30, 2024

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

Ведение журнала (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. Весь объем работы выполняется служебным классом.

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

Создание вспомогательных (утилитных) классов сопряжено с целым рядом возможных ошибок. Их исправление может оказаться трудоемким процессом. Поэтому попытаемся настроить конфигурацию так, чтобы описанные выше задачи выполняли такие стандартные библиотеки, как 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. Ясное и структурированное ведение журнала — это не просто хороший стиль программирования, а еще и упрощенные отладка и обслуживание приложений в рабочей среде.