Способы логирования Hibernate

Приветствую, дорогие друзья! Меня зовут Алексей, и я backend java developer. На одном из моих проектов была задача -  предоставлять по требованию SQL запросы уходящие в БД, для этого их решили логировать.  В этой статье я постараюсь поделиться несколькими способами, которыми можно достичь данной задачи.

Проект был написан на Spring, поэтому все примеры будут на нём. Запросы были написаны с использованием JPA или сгенерированы через Spring Repository.

Первый и самый проcтой способ: залогировать запросы Hibernate

Указать в application.properties: spring.jpa.show-sql=true

или spring.jpa.properties.hibernate.show_sql=true

Пример ввода:

Так мы можем быстро решить проблему с локальным поиском багов, но есть несколько очевидных минусов:

1. Вывод SQL не проходит через наш логгер и не имеет необходимый для нас формат. Запрос просто уходит в System.out.

2. Вместо параметров запроса мы видим вопросики.

Второй подход: установка уровня логирования

Пример на основе application.properties: logging.level.org.hibernate.SQL=debug

Изменение уровня логов пакета SQL на debug добавит в наш лог sql запросы.

logging.level.org.hibernate.type.descriptor.sql.BasicBinder=trace

Изменение же уровня BasicBinder на trace добавит нам параметры запросы, правда в слегка непривычной форме -  поочередное перечислением после самого запроса.

Пример вывода:

Третий подход: использование proxy драйвера

Например log4jdbc или p6spy. Оба прокси рабочие и на них есть стартеры, хотя на log4jdbc давно не было коммитов на момент написание статьи.

<dependency>
    <groupId>com.integralblue</groupId>
    <artifactId>log4jdbc-spring-boot-starter</artifactId>
</dependency>
<dependency>
    <groupId>com.github.gavlyukovskiy</groupId>
    <artifactId>p6spy-spring-boot-starter</artifactId>
</dependency>

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

Во-первых у нас есть ограничение в самой библиотеке.

В properties можно указать pattern по которому будут фильтроваться л��гируемые запросы.

Например:

decorator.datasource.p6spy.log-filter.pattern=.*insert.*

покажет нам все insert запросы.

Но иногда нам нужно выводить в лог всего один или несколько методов. Сделаем реализацию такой аннотации сами. Объявим аннотацию:

@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface LogP6Spy {
}

По сути нам нужно отфильтровать нужные логи по какому то признаку. Я решил сделать это с помощью MDC, у него область видимости как раз ThreadLocal, что нам на руку. Сделаем фильтр:

public class FilterMdc extends Filter<ILoggingEvent> {
    @Override
    public FilterReply decide(ILoggingEvent event) {
        if (Objects.isNull(MDC.get("Enable"))) {
            return FilterReply.DENY;
        }
        return FilterReply.ACCEPT;
    }
}

Обработчик аннотации я сделал через аспект:

@Aspect
@Component
public class AspectLogP6Spy {

    @Pointcut("@annotation(com.equant.transaction.LogP6Spy)")
    public void annotated() {}

    @Before("annotated()")
    public void before() {
        MDC.put("Enable", "true");
    }

    @After("annotated()")
    public void after() {
        MDC.remove("Enable");
    }
}

ну и конфигурация на примере Logback:

<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <appender name="STDOUT_FILTER" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.equant.transaction.FilterMdc">
        </filter>
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>
    <logger name="p6spy" level="info" additivity="false">
        <appender-ref ref="STDOUT_FILTER"/>
    </logger>
    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

Создадим дополнительный appender с фильтром и пропустим через него логи p6spy уровня info и не забудем указать additivity=«false», что бы root appender не обрабатывал этот же пакет. Вот и всё.

Не забываем, что мы сделали это через proxy, а значит у нас есть ограничения в выборе методов, над которыми можно ставить новую аннотацию.

Заключение: Как мы видим в логирование Hibernate нет ничего сложного. Последний подход даёт возможность легко помечать аннотацией только те методы которые нужны.

Была ли у Вас необходимость логировать запросы? Какой подход использовали? Пишите в комментариях.

На этом всё. Не болейте!