SQL‑лог в data‑тестах

1. Роль SQL‑лога в @DataJpaTest

Если вы когда‑нибудь смотрели на падение JPA‑теста и думали: «Ладно… что именно пошло не так?», то вы уже готовы к SQL‑логу. В data‑тестах мы проверяем persistence‑поведение, а оно всегда в итоге превращается в SQL. И когда тест упал, полезно увидеть не только “Exception happened”, но и “какой именно запрос пытались выполнить и почему база сказала «нельзя»”.

Представьте, что JPA — это очень старательный официант. Вы говорите: «Принеси мне статью, сохрани её, обнови заголовок», а официант куда‑то уходит на кухню (в базу) и возвращается с результатом. Иногда он приносит не то (ошибка мэппинга), иногда кухня отказывается готовить (constraint violation), иногда официант вообще не сходил на кухню, потому что вы забыли попросить его «вынести заказ» (flush()). SQL‑лог — это возможность заглянуть на кухню и увидеть: что реально приготовили и в какой момент повар бросил половник.

Полезная мысль: SQL‑лог нужен не чтобы «стать DBA за 10 минут», а чтобы в тестах перестать угадывать. В JPA много скрытой магии, и магию лучше не ненавидеть, а делать наблюдаемой.

Небольшая схема того, что мы хотим «подсветить»:

flowchart TD
    T["JUnit test (@DataJpaTest)"] --> PC["Persistence Context managed entities"]
    PC --> |"flush()"| SQL["SQL statements (insert/update/select)"]
    SQL --> DB["(Database)"]
    DB -->|constraints / errors| EX["Exception"]
    DB -->|data| R["Result set"]
    R --> T

2. Два источника SQL в Spring Boot

Когда новички впервые включают SQL‑вывод, они часто делают это «как получится», а потом удивляются, почему консоль превратилась в водопад текста. В Spring Boot обычно есть два популярных пути: быстрый и грубый (spring.jpa.show-sql=true) и чуть более взрослый (логирование через категории Hibernate). Оба полезны, если понимать, чего вы от них хотите.

spring.jpa.show-sql=true — это как включить лампочку “покажи мне SQL прямо сейчас”. Оно выводит запросы довольно прямолинейно, часто с префиксом вроде Hibernate:. Это удобно для первого знакомства и быстрых расследований. Но у этого режима есть особенности: он часто пишет не туда же, куда обычные логи (может писать в stdout), хуже контролируется по уровню, и формат бывает не самым читаемым.

Логирование Hibernate через logging.level... — это более «командный» путь, потому что вы управляете уровнем логов как всеми остальными логами приложения. Плюс вы можете отдельно включить сами запросы (SQL), отдельно значения параметров (bind parameters), отдельно ошибки. Этот подход чаще всего приятнее, когда вы хотите «включить SQL только на один тестовый класс» и потом спокойно его выключить.

Есть ещё одна важная грань: SQL‑строки часто выглядят как ... values (?, ?, ?) — с вопросиками вместо значений. Это нормально: JDBC использует prepared statements. Иногда вам достаточно видеть сам факт INSERT/UPDATE/SELECT. А иногда нужно понять, какие значения реально ушли в параметры (особенно когда ловите null в not‑null колонке). Тогда включают логирование биндинга параметров. Это мощно, но шумно — и в реальном проде так делать опасно (можно случайно залогировать чувствительные данные). В тестах обычно можно позволить себе чуть больше откровенности.

Для рабочего пути ниже возьмём logger‑based вариант через logging.level.org.hibernate.SQL=DEBUG: он лучше вписывается в обычные логи теста и его удобно включать точечно на один класс. show-sql, bind‑логи и application-test.yml полезны как альтернативы, но не обязаны занимать половину внимания.

3. Включение SQL‑лога для одного теста

Для обычного расследования в @DataJpaTest достаточно одного default path: включить Hibernate SQL как обычный logger прямо в аннотации теста. Тогда запросы идут тем же каналом, что и остальные тестовые логи, их легко локально включить и так же легко убрать.

import org.springframework.boot.test.autoconfigure.orm.jpa.DataJpaTest;

// Рекомендуемый default: SQL идёт как часть обычных логов этого тестового класса
@DataJpaTest(properties = {
        "logging.level.org.hibernate.SQL=DEBUG",
        "spring.jpa.properties.hibernate.format_sql=true"
})
class ArticleRepositoryDataJpaTest {
}

format_sql=true здесь только делает вывод читаемее. Этого уже достаточно, чтобы связать строку теста с insert/update/select и быстро понять, где именно JPA сходила в БД.

4. Как читать лог: «строка теста → SQL → эффект в БД»

Включить SQL‑лог — это только половина победы. Вторая половина — научиться его читать так, чтобы он отвечал на вопрос «почему тест упал», а не превращался в бессмысленный шум. Хорошая новость: в data‑тестах паттерны очень повторяемые. Если вы понимаете, где в тесте происходит flush, где clear, и где повторное чтение, вы начинаете буквально “видеть” SQL глазами.

Полезно держать в голове простую таблицу «действие в тесте → что обычно происходит на SQL‑уровне»:

Ниже draftArticle("...") — это сокращение для той же минимально валидной Article, где обязательные поля и Category уже собраны helper-ом. Для SQL‑лога нам важен не сам setup, а след insert/update/select.

Теперь закрепим это на небольшом, но показательно «пошаговом» тесте. Он специально написан так, чтобы по коду было видно, что именно мы ожидаем увидеть в логе.

import org.junit.jupiter.api.Test;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.autoconfigure.orm.jpa.DataJpaTest;
import org.springframework.boot.test.autoconfigure.orm.jpa.TestEntityManager;

// Включаем вывод SQL локально, чтобы этот тест читался как сценарий + «рентген»
@DataJpaTest(properties = "spring.jpa.show-sql=true")
class ArticleSqlLogDataJpaTest {

    @Autowired TestEntityManager entityManager;

    @Test
    void sqlLog_showsInsertUpdateSelect() {
        // Фикстура создаёт валидную статью по умолчанию
        var article = draftArticle("java-basics");

        // Persist сам по себе может не дать SQL — поэтому сразу делаем flush()
        entityManager.persist(article);
        entityManager.flush(); // ожидаем INSERT

        // Меняем managed entity: UPDATE будет только при flush()
        article.setTitle("Updated title");
        entityManager.flush(); // ожидаем UPDATE

        // Хотим «честный» SELECT из БД, а не из persistence context
        entityManager.clear();
        entityManager.find(article.getClass(), article.getId()); // ожидаем SELECT
    }
}

Да, здесь есть “магия” в draftArticle(...) — мы используем тестовую фикстуру, чтобы не расписывать обязательные поля статьи каждый раз. В логах (в упрощённом виде) вы обычно увидите что‑то очень похожее на:

Hibernate: insert into articles (...) values (?, ?, ?, ...)
Hibernate: update articles set title=? ... where id=?
Hibernate: select a1_0.id, a1_0.title, a1_0.slug ... from articles a1_0 where a1_0.id=?

Три строки лога — и у нас уже есть “рентген” поведения. Если тест падает, вы сразу понимаете, на каком шаге проблема: на insert, update или select.

Ещё один полезный микроприём: оставляйте в тесте маленькие комментарии вроде “ожидаем INSERT”. Это не для красоты. Это делает тест читабельным как сценарий и резко облегчает сопоставление «строка теста → строка SQL».

Если стандартного лога мало

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

— spring.jpa.show-sql=true — самый быстрый способ быстро взглянуть на SQL, но он грубее управляется и часто пишет в stdout;

— лог параметров вроде logging.level.org.hibernate.orm.jdbc.bind=TRACE — полезен, когда вы охотитесь за null или неверными bind values; название категории зависит от версии Hibernate, а шумит этот режим очень сильно;

— application-test.yml — удобен, если одинаковый SQL‑лог нужен целому набору тестов, а не одному локальному расследованию.

5. Кейсы падений data‑тестов по SQL‑логу

Сейчас будет часть, похожая на детектив. Но без шляп и лупы — только JUnit, JPA и ваш внутренний голос, который шепчет: «Ну почему оно упало именно сейчас?». В каждом кейсе мы специально будем держать тест коротким, чтобы лог читался легко. Когда тест превращается в “универсальный сценарий на всё”, SQL‑лог становится нечитаемым. Поэтому мы будем дисциплинированными, хотя очень хочется быть творческими.

Кейс 1: unique по slug — ошибка возникает «не там», где ожидаешь

Классика ContentHub: slug должен быть уникальным. Мы сохраняем одну статью с slug = "same-slug", всё хорошо. Потом сохраняем вторую с тем же slug — и ждём, что ошибка появится “на второй строке persist”. Но чаще всего она появляется… на flush(). Потому что именно flush() реально отправляет SQL в базу.

import org.junit.jupiter.api.Test;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.autoconfigure.orm.jpa.DataJpaTest;
import org.springframework.boot.test.autoconfigure.orm.jpa.TestEntityManager;

import static org.assertj.core.api.Assertions.assertThatThrownBy;

@DataJpaTest(properties = "spring.jpa.show-sql=true")
class ArticleSlugUniqueSqlLogTest {

    @Autowired TestEntityManager entityManager;

    @Test
    void duplicateSlug_failsOnFlush() {
        // Вставка №1 проходит успешно
        entityManager.persist(draftArticle("same-slug"));
        entityManager.flush(); // INSERT №1

        // Вставка №2 с тем же slug должна взорваться на flush(), а не на persist()
        entityManager.persist(draftArticle("same-slug"));
        assertThatThrownBy(entityManager::flush) // INSERT №2 -> boom
                // Здесь нам важен сам факт падения на втором INSERT;
                // точный тип исключения зависит от провайдера и обёрток.
                .isInstanceOf(Exception.class);
    }
}

Если включён SQL‑лог, вы увидите примерно такую историю:

Hibernate: insert into articles (...) values (?, ?, ?, ...)
Hibernate: insert into articles (...) values (?, ?, ?, ...)
-- дальше исключение о нарушении уникальности

И вот здесь лог даёт вам самое ценное: подтверждение, что проблема действительно в втором insert, а не где‑то в стороннем месте. Даже если stacktrace огромный и оборачивается в несколько исключений, SQL‑лог показывает реальную последовательность событий.

Важный нюанс: текст ошибки у разных баз может отличаться. Где‑то будет “duplicate key”, где‑то “unique index violation”. Не зацикливайтесь на формулировке. Ваша задача как автора теста — понять, какой запрос нарушил инвариант, и доказать, что инвариант реально enforced базой.

Кейс 2: not null — вставка “почти правильной” статьи и загадочный null

Второй популярный сценарий: статья выглядит «почти нормальной», но вы где‑то забыли поле, которое в БД не может быть null. Например, title. В Java это легко пропустить, потому что объект “создался”, сеттеры работают, компилятор не ругается. Но база — не психолог, она не верит в потенциал.

import org.junit.jupiter.api.Test;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.autoconfigure.orm.jpa.DataJpaTest;
import org.springframework.boot.test.autoconfigure.orm.jpa.TestEntityManager;

import static org.assertj.core.api.Assertions.assertThatThrownBy;

@DataJpaTest(properties = "spring.jpa.show-sql=true")
class ArticleNotNullSqlLogTest {

    @Autowired TestEntityManager entityManager;

    @Test
    void nullTitle_failsOnInsertFlush() {
        // Создаём валидный объект и ломаем ровно одно правило — title становится null
        var article = draftArticle("java-basics");
        article.setTitle(null);

        entityManager.persist(article);
        // Ошибка прилетит именно на flush(), потому что именно там уходит INSERT в БД
        assertThatThrownBy(entityManager::flush)
                .isInstanceOf(Exception.class);
    }
}

SQL‑лог здесь помогает по‑простому: вы видите, что действительно был insert. Это важно, потому что иногда новички думают: “JPA же умный, наверное, не вставлял ничего”. Но вставлял — и база отказалась.

Если вы включили лог параметров (bind), то вы можете даже увидеть, какой параметр ушёл как null. Это особенно полезно, когда объект большой, а not‑null ограничений много, и по одному stacktrace не всегда понятно, какое поле реально оказалось пустым.

Именно здесь начинаешь ценить draftArticle(...) как фикстуру: она должна создавать максимально валидный объект по умолчанию. А тест должен ломать ровно одно правило, чтобы расследование было коротким.

Кейс 3: «Где мой UPDATE?» — тест падает из‑за пропущенного flush()

Этот сценарий особенно коварный, потому что он не “про ограничение базы”, а про нашу дисциплину flush. Вы обновили поле у managed entity и уверены, что “ну оно же поменялось, значит в базе поменялось”. А потом делаете clear() и перечитываете — и видите старое значение. Тест падает, и вы чувствуете себя обманутым. Но на самом деле это вы забыли попросить официанта отнести изменения на кухню.

import org.junit.jupiter.api.Test;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.autoconfigure.orm.jpa.DataJpaTest;
import org.springframework.boot.test.autoconfigure.orm.jpa.TestEntityManager;

import static org.assertj.core.api.Assertions.assertThat;

@DataJpaTest(properties = "spring.jpa.show-sql=true")
class ArticleUpdateSqlLogTest {

    @Autowired TestEntityManager entityManager;

    @Test
    void updateIsNotInDbWithoutFlush() {
        var article = draftArticle("java-basics");
        entityManager.persist(article);
        entityManager.flush(); // INSERT

        // Меняем поле у managed entity...
        article.setTitle("Changed only in memory");
        // ...и тут же «теряем» изменения, потому что очищаем контекст ДО flush()
        entityManager.clear(); // мы очистили контекст раньше, чем flush()

        // Честно читаем из БД: там остался старый title, потому что UPDATE не было
        var reloaded = entityManager.find(article.getClass(), article.getId());
        assertThat(reloaded.getTitle()).isEqualTo("Java Basics");
    }
}

Если посмотреть на SQL‑лог, то расследование происходит само собой. Вы увидите insert, потом select — и никакого update между ними. Это и есть ответ на вопрос “почему база не увидела изменения”.

Hibernate: insert into articles (...) values (?, ?, ?, ...)
Hibernate: select ... from articles ... where id=?

Становится очевидно: чтобы update попал в БД, надо было сделать второй flush() после изменения поля, а clear() оставить после него.

Этот кейс — отличный пример того, как SQL‑лог превращает «кажется, JPA сломалась» в «ага, я пропустил шаг в сценарии».

6. SQL‑лог — не assertion

Когда вы впервые увидите SQL‑лог, появляется соблазн: «О! Давайте проверим, что был ровно один INSERT и ровно один SELECT». Выглядит логично, но в большинстве обычных data‑тестов это плохая идея. SQL — это деталь реализации вашего persistence слоя, и она может меняться из‑за вещей, которые не ломают бизнес‑поведение: смена диалекта, обновление Hibernate, изменение стратегии генерации имён, даже мелкие изменения мэппинга.

Пока наша цель — научиться делать JPA‑поведение наблюдаемым и честным, а не привязать тесты к конкретному тексту запросов. Поэтому SQL‑лог — это инструмент диагностики и понимания, а assertions мы строим на более стабильных вещах: на повторном чтении данных, на факте нарушения ограничения, на наличии записи и корректности полей.

Хорошая внутренняя формула на сегодня звучит так: «Я читаю SQL глазами, но проверяю поведение через репозиторий и повторное чтение». Лог помогает объяснить падение, а не стать целью теста.

7. Типичные ошибки при чтении SQL‑лога

Почти у всех сначала SQL‑лог вызывает две реакции: либо «Ого, теперь я всё понимаю!», либо «Что за шум, я ничего не понимаю!». Обычно проблема не в вас и не в JPA, а в нескольких типичных привычках, которые делают лог бесполезным. Если их отловить заранее, вы будете расследовать падения намного спокойнее — и, что важно, быстрее.

Ошибка №1: включить SQL‑лог для всего test suite и утонуть.
Если вы включили show-sql или Hibernate SQL‑лог глобально, консоль превращается в сериал на 300 сезонов: вроде интересно, но жизни не хватит. SQL‑лог лучше включать точечно на один тестовый класс или на короткое время расследования. Тогда вы читаете несколько строк и сразу связываете их с шагами сценария.

Ошибка №2: ожидать SQL после persist() и удивляться, что его нет.
persist() делает объект managed, но не обязан сразу отправлять insert. JPA может копить изменения до flush(). Поэтому «в логе тишина» после persist() — часто нормальная ситуация, а не баг. Если вы хотите увидеть момент реальной записи, ставьте flush() в том месте сценария, где вы ожидаете DB‑поведение.

Ошибка №3: забыть про clear() и ждать select, которого не будет.
Если вы сделали find() и не увидели select — это не значит, что JPA “не читает базу”. Возможно, она уже знает этот объект и возвращает его из persistence context. Для честного повторного чтения делайте clear(), а потом читайте заново. Тогда select обычно появится, и лог начнёт соответствовать вашему мысленному сценарию.

Ошибка №4: читать исключение, не привязывая его к конкретному SQL‑шагу.
В JPA и Spring исключения часто оборачиваются слоями: JDBC → Hibernate → Spring. В итоге stacktrace длинный, а “где оно упало” неочевидно. SQL‑лог лечит это, но только если вы сознательно смотрите: какой запрос был последним перед ошибкой, и на каком flush (или чтении) он был вызван.

Ошибка №5: пытаться «проверять SQL» вместо проверки результата в базе.
SQL‑лог может измениться, даже если ваше поведение осталось корректным. Поэтому лучше держать лог как инструмент объяснения, а проверку — как честный read‑back через clear и повторное чтение. Если тест начал зависеть от текста SQL, он становится хрупким и будет ломаться по поводу вещей, которые вообще не являются регрессией продукта.