Hibernate zgubił moją zmianę

Eventy, które nie chcą przejść

Pierwsze zadanie w nowej pracy: „sprawdź, czemu zdarzenia w kolejce nie mogą zostać przetworzone”. Super zadanie na początek, by zaznajomić się z narzędziami w firmie – i kompletnie niezwiązane z Hibernate’em, w którego kodzie ostatecznie wylądowałem. Kod w skrócie: w jednej transakcji oznaczamy rekord nadrzędny i jego rekordy jako usunięte (soft delete) + zapisujemy transactional outbox (otwiera się w nowej karcie) z eventem o każdym usuniętym rekordzie.

No dobra, sprawdzam logi, monitoring. Na DLT lądował późniejszy event, który wymagał, żeby wszystkie te dane były już usunięte. Wygląda na to, że w bazie jest jakaś niespójność. Pierwsze podejrzenie – błąd w kodzie albo race condition przez izolację Read Committed. Niestety nie: kod wyglądał w 100% dobrze i nie zmienił się, odkąd pojawił się ten event.

Ostatnie logi przed śmiercią poda

Zauważyłem, że logi z tej operacji były jednymi z ostatnich na podzie, bo autoscaling akurat go zatrzymywał. Ale nie to było najciekawsze. Inny serwis odczytał event o usunięciu rekordu, a u nas ten rekord wcale nie był usunięty… Co ciekawe, ostatni event z tej transakcji dotyczył akurat rekordu, którego zmiana zniknęła.

Skoro kod wyglądał dobrze, zapytałem bazę. Usunięcie to u nas flaga deleted, więc wiersze dalej tam leżały. Dowiedziałem się, że każdy wiersz w Postgresie ma ukrytą kolumnę xmin, czyli id transakcji, która zapisała jego aktualną wersję. Z age(xmin) można się dowiedzieć, ile transakcji temu to było.

1
SELECT id, deleted, age(xmin) AS transactions_ago
2
FROM record
3
WHERE parent_id = 42;

Rekord nadrzędny i usunięte rekordy – świeży xmin, z transakcji z incydentu. Rekord, który nie został usunięty – xmin sprzed setek milionów transakcji. Czyli nikt tego wiersza nie dotykał od bardzo dawna. A więc UPDATE nie został nadpisany przez inną transakcję – Postgres po prostu nigdy go nie dostał. Za to w tej samej transakcji dostał i zatwierdził wiersz outboxa z eventem o usunięciu tego rekordu.

„Łącząc kropki” i wykluczając błąd w kodzie lub w bazie danych, zacząłem podejrzewać Hibernate’a. Z pomocą AI trafiłem na ciekawy fragment w beforeTransactionCompletion(). Ale po kolei – najpierw: kiedy Hibernate w ogóle wysyła zmiany do bazy?

Jak Hibernate zapisuje zmiany

Jeśli wiesz, jak działa persistence context i kiedy Hibernate robi flush, tę sekcję możesz pominąć – dalej jest sekcja 1.4.

W wielkim skrócie – Hibernate (jeśli może) trzyma zmiany Entity w “persistence context” i wysyła je do bazy dopiero przy flushu. Flush wykonywany jest przed zapytaniem, które mogłoby te zmiany przeczytać, i zawsze tuż przed commitem (a przynajmniej tak myślałem).

Nie wszystko jednak czeka na flush. Od razu do bazy lecą1:

• INSERT Entity z id IDENTITY, bo id nadaje baza
• ręcznie pisane update/delete w JPQL albo natywnym SQL
• wszystko, co idzie zwykłym JDBC
• zmiany, które wysłał już wcześniejszy flush

Cała reszta – zmienione pola Entity, remove(), nowe Entity z sekwencją – czeka w pamięci na flush. Czyli gdyby flush przy commicie się nie wykonał, w bazie zostałoby tylko to, co poleciało do niej wcześniej.

Ten ostatni punkt tłumaczy, czemu u nas zginął akurat ostatni rekord. Hibernate robi flush nie tylko przy commicie, ale też przed zapytaniem, jeśli to zapytanie czyta tabelę, w której coś czeka na zapis. Nasz kod wyglądał mniej więcej tak:

1
for (Long recordId : recordIds) {
2
    Record record = recordRepository.findActiveById(recordId); // zapytanie do tabeli record
3
    record.setDeleted(true);                                     // czeka w pamięci
4
    outbox.save(new RecordDeletedEvent(recordId));               // JDBC, leci od razu
5
}

I teraz krok po kroku, dla trzech rekordów:

1. Zapytanie o rekord 1 – nic jeszcze nie czeka, więc nie ma flusha. Rekord 1 dostaje deleted = true w pamięci, event idzie do outboxa.
2. Zapytanie o rekord 2 czyta tabelę record, a w niej czeka zmiana rekordu 1 – więc Hibernate najpierw robi flush i UPDATE rekordu 1 idzie do bazy. Potem to samo z rekordem 2 i eventem.
3. Zapytanie o rekord 3 wypycha w ten sam sposób zmianę rekordu 2. Rekord 3 zostaje oznaczony w pamięci, event idzie do outboxa.
4. Koniec pętli. Nie ma już żadnego zapytania o rekordy, więc zmiana rekordu 3 czeka na flush przy commicie…
5. …który się nie wykonuje. Do bazy trafiają eventy wszystkich trzech rekordów, ale UPDATE tylko dwóch pierwszych.

Dokładnie to, co pokazał xmin.

Zostaje pytanie: czemu flush przy commicie się nie wykonał?

Kiedy Hibernate pomija flush przy commicie

I tu wraca beforeTransactionCompletion(). Przy commicie woła ono managedFlush(), a ten sprawdza, czy sesja jest otwarta. Tak to wygląda w Hibernate 7.4.5:

1
private void managedFlush() {
2
    if ( !isOpenOrWaitingForAutoClose() ) {
3
        SESSION_LOGGER.skippingAutoFlushSessionClosed(); // TRACE
4
    }
5
    else {
6
        SESSION_LOGGER.automaticallyFlushingSession();
7
        fireFlush();
8
    }
9
}
10

11
// inherited from AbstractSharedSessionContract
12
public boolean isOpenOrWaitingForAutoClose() {
13
    return !closed && factory.isOpen()
14
        || waitingForAutoClose;
15
}

Gdy fabryka jest zamknięta, każda jej sesja liczy się jako zamknięta, więc managedFlush() loguje Skipping auto-flush since the session is closed na TRACE2 i wraca, a Connection.commit() leci do Postgresa, który zatwierdza wszystko, co dostał. Co gorsze – nic nie rzuca wyjątku, jedynym śladem jest ten jeden log na poziomie TRACE (!).

Do odtworzenia nie trzeba ani Springa, ani nawet drugiego wątku. W teście niżej Payment ma id IDENTITY, więc jego INSERT leci przy persist(), a nowy status zamówienia czeka na flush. Zamykamy fabrykę, robimy commit i… płatność jest, a zamówienie dalej NEW.

1
@Test
2
void closeAndCommitOnTheSameThreadAlsoSaveOnlyPartOfTheTransaction() throws Exception {
3
    Session session = sessionFactory.openSession();
4
    Transaction transaction = session.beginTransaction();
5
    Payment payment = new Payment();
6
    payment.orderId = 1L;
7
    session.persist(payment);
8
    session.find(Order.class, 1L).status = "PAID";
9

10
    sessionFactory.close();
11
    transaction.commit();
12
    session.close();
13

14
    assertEquals(1, count("select count(*) from payments where orderId = 1"), "the INSERT was committed");
15
    assertEquals("NEW", status(), "the UPDATE was never executed, yet the transaction was committed");
16
}

Odtworzyłem to na Hibernate 6.6.53, 6.6.59, 7.4.5 i 7.4.13 z PostgreSQL oraz na 7.4.13 i 8.0.0.Beta3 z H2 (na szablonie testów od Hibernate’a). Starszych wersji niż 6.6 nie sprawdzałem.

Zostaje pytanie: kto zamyka fabrykę w środku transakcji?

Co się dzieje przy SIGTERM

Pamiętasz, że autoscaling akurat zatrzymywał poda? Po otrzymaniu SIGTERM Spring Boot zamyka się w dwóch etapach. Najpierw (faza SmartLifecycle) zatrzymuje to, co może tworzyć nowe zadania: endpointy HTTP, listenery/konsumery itp. + daje im ograniczony czas na dokończenie pracy (domyślnie: kontener Kafki czeka 10 s, RabbitMQ 5 s, a każda faza zamykania w Spring Boot maksymalnie 30 s). Potem niszczy beany, w tym nasze EntityManagerFactory, a na końcu DataSource.

Problem w tym, że drugi etap zakłada, że pierwszy wszystko zakończył, a handler, który czeka na wolne zewnętrzne API, może się nie zmieścić w czasie. Spring, mimo że wątek dalej działa, idzie do kolejnej fazy i zaczyna niszczyć beany. Wątek w końcu dostaje odpowiedź, wychodzi z metody @Transactional, a Hibernate robi commit bez flusha, bo EntityManagerFactory jest już zamknięte.

Pokażę to na aplikacji demo (GitHub, otwiera się w nowej karcie): mały sklep, w którym jedna metoda @Transactional pobiera zamówienie, zapisuje płatność, oznacza zamówienie jako opłacone i woła wolne sprawdzenie pod kątem oszustwa (tak, normalnie rozdzielilibyśmy to na kilka wiadomości, ale to dobry przykład, żeby pokazać problem z Hibernate’em). Poniżej ta transakcja krok po kroku – w kroku 4, w trakcie czekania, Spring zamyka fabrykę. Przełącznik strażnika (o nim później) na razie zostaw wyłączony.

A tak to wygląda w czasie – wątek roboczy i zamykający się Spring obok siebie:

Co zabawne, przy SIGKILL połączenie się zrywa i Postgres robi rollback. Częściowy commit wymaga właśnie „grzecznego” (SIGTERM) zamknięcia.

Może to jakiś błąd tylko w naszej aplikacji?

Początkowo myślałem, że to błąd konfiguracji w naszym serwisie, więc zbudowałem czystą aplikację Spring Boot (GitHub, otwiera się w nowej karcie) + Spring JPA + Spring Kafka/AMQP. Wynik – zaskakujący. Tam też ten błąd odtworzyłem, co oznacza, że może to dotyczyć każdej aplikacji (przy odrobinie [nie]szczęścia).

Repo to ten sam sklep co w demach wyżej: Spring Boot 4 + Hibernate 7 + Postgres, ze Spring MVC, Kafką i RabbitMQ. Każdy test wpuszcza płatność innym wejściem, zatrzymuje poda w trakcie sprawdzenia, a na koniec zagląda do bazy, żeby zweryfikować wynik.

Jedna rzecz jest tu celowo „oszukana”: bean MetricsExporter zamyka się 0.5 s i jest wpięty tak, że Spring niszczy go między Hibernate’em a pulą. To rozciąga okno (o nim w kolejnej sekcji) z ~1.2 ms do pół sekundy, więc testy trafiają w nie za każdym razem i są deterministyczne. Reszta – Spring, Hibernate, HikariCP, kontenery listenerów – działa bez zmian. Test, który mierzy samo okno czasowe, działa już bez tego triku – taki też mamy :)

Wyniki (kolumna „Ze strażnikiem” będzie jasna za dwie sekcje):

Do odpalenia testów potrzebujesz Dockera i Javy 21+:

1
$ git clone https://github.com/Mixonn/hibernate-partial-commit-on-shutdown.git
2
$ cd hibernate-partial-commit-on-shutdown
3
$ mvn -B test -Dtest=KafkaPaymentShutdownTest

Okno 1.2 ms

Jest jeden warunek. Commit musi wypaść po zamknięciu Hibernate’a, ale przed zamknięciem puli połączeń. Jak pula zamknie już połączenie, commit się nie uda i Postgres zrobi rollback.

W zwykłej aplikacji Spring Boot 4.1 z HikariCP ta przerwa trwa ok. 1.2 ms (sprawdź sam (GitHub, otwiera się w nowej karcie)), mierzone na laptopie z lokalną bazą3. Jeśli COMMIT wyjdzie w pierwszych ~0.5 ms okna, kończy się cichym częściowym commitem. Później COMMIT dalej dociera do Postgresa, ale HikariCP zamyka socket, zanim przyjdzie odpowiedź, i aplikacja dostaje Socket closed. Czyli dane zapisane do połowy + błąd, który zachęca do ponowienia czegoś, co jest już w połowie zrobione. Możesz przeciągnąć commit na demo niżej i zobaczyć, gdzie co się dzieje.

Niby niewiele, ale pody zamykane są często, a okno może się wydłużyć przy ograniczonym CPU, wolnej sieci itp.

Czemu nikt tego nie zauważa? Po pierwsze, przy krótkich transakcjach dzieje się to niezwykle rzadko. Po drugie, nawet jeśli się zdarzy, kod biznesowy widzi udany commit, a w drugiej części okna – błąd połączenia przy zamykaniu poda (czyli coś, co jest „standardowe”). Jedyny log, który mówi prawdę, jest na poziomie TRACE. Czyli go nie ma.

Zostają niespójne dane. My zauważyliśmy swoje tylko dzięki temu eventowi na DLT. Bez tego wiersz dalej by sobie leżał, a ewentualne niezgodności uznalibyśmy za „cannot reproduce” albo „pewnie kiedyś kod miał buga, teraz wszystko wygląda OK”.

Nasz przypadek nie był krytyczny, ale co w sytuacji, w której do akcji wkraczają pieniądze, albo jakieś krytyczne reguły biznesowe u ważnych klientów? Wg mnie to niedopuszczalne zachowanie Hibernate’a.

Jak się przed tym zabezpieczyć

Obejściem jest strażnik, który nie pozwala na commit, gdy fabryka jest już zamknięta. W każdej transakcji rejestruje Synchronization, którą Hibernate woła po flushu (albo jego pominięciu), a przed Connection.commit(). Jeśli fabryka jest już zamknięta, strażnik rzuca wyjątek i Hibernate robi rollback.

W Springu najprościej zrobić z niego TransactionExecutionListener – wystarczy jeden @Component, Spring Boot sam podpina takie beany do menedżera transakcji, a afterBegin wykonuje się na początku każdej transakcji. Cały kod pokazuje listing 1.4.

1
@Component
2
public class PartialCommitGuard implements TransactionExecutionListener {
3

4
    private static final Logger log = LoggerFactory.getLogger(PartialCommitGuard.class);
5

6
    /** Called at the start of every transaction. */
7
    @Override
8
    public void afterBegin(TransactionExecution transaction, Throwable beginFailure) {
9
        if (beginFailure != null || !transaction.isNewTransaction()) {
10
            return;
11
        }
12
        try {
13
            for (Object resource : TransactionSynchronizationManager.getResourceMap().values()) {
14
                if (resource instanceof EntityManagerHolder holder) {
15
                    Session session = holder.getEntityManager().unwrap(Session.class);
16
                    session.getTransaction().registerSynchronization(new Guard(session));
17
                }
18
            }
19
        } catch (RuntimeException e) {
20
            // Never throw from here: it would break the start of the transaction.
21
            log.warn("Could not add the guard to the transaction", e);
22
        }
23
    }
24

25
    /** The guard. Hibernate calls beforeCompletion() right before committing the transaction. */
26
    static final class Guard implements Synchronization {
27

28
        private final Session session;
29

30
        Guard(Session session) {
31
            this.session = session;
32
        }
33

34
        @Override
35
        public void beforeCompletion() {
36
            if (session.getSessionFactory().isClosed() && !readOnly()) {
37
                throw new HibernateClosedBeforeCommitException();
38
            }
39
        }
40

41
        @Override
42
        public void afterCompletion(int status) {
43
        }
44

45
        /** In read-only transactions Hibernate writes nothing anyway, so there is nothing to guard. */
46
        private boolean readOnly() {
47
            try {
48
                return session.getHibernateFlushMode() == FlushMode.MANUAL;
49
            } catch (RuntimeException e) {
50
                return false;
51
            }
52
        }
53
    }
54

55
    public static final class HibernateClosedBeforeCommitException extends IllegalStateException {
56

57
        HibernateClosedBeforeCommitException() {
58
            super("Hibernate was closed before the transaction was committed: rolling it back instead of saving only part of the data");
59
        }
60
    }
61
}

Na diagramie niżej widać, gdzie dokładnie strażnik wchodzi w commit.

Puściłem też test, który zamykał fabrykę w różnych momentach wokół commitu – 1000 przebiegów. Bez strażnika 2–4% transakcji zapisało się częściowo, ze strażnikiem żadna.

Zamknięta fabryka nigdy się ponownie nie otwiera, a strażnik działa już po decyzji o flushu, więc pominięty flush zawsze na niego trafi. W drugą stronę może się pomylić: jeśli fabryka zamknie się tuż po pełnym flushu, strażnik wycofa transakcję, która była OK.

Decyzja należy do Ciebie4 – czy wolisz częściowo zapisaną transakcję, czy wycofanie takiej, która mogła się jeszcze udać tuż przed zamknięciem poda?

Możesz też wrócić do demka z sekcji o SIGTERM i włączyć w nim strażnika.

Skąd to się wzięło i co dalej

W 2013 roku pojawiło się zgłoszenie HHH-8586 (otwiera się w nowej karcie): commit JTA po EntityManagerFactory.close() odpalał flush, który rzucał wyjątek. Poprawka (fa6a222 (GitHub, otwiera się w nowej karcie), wersja 4.3.0.Beta5) zmieniła isClosed() na closed || factory.isClosed() i od tamtej pory flush po zamknięciu fabryki jest po cichu (tak, log TRACE) pomijany, zamiast kończyć się wyjątkiem i rollbackiem. W testach do tej poprawki nie było niczego do flushowania, więc nie było też czego „zgubić”, a w zgłoszeniu nikt o tym nie wspomina. Obstawiam więc, że utrata danych to przeoczenie, a nie czyjaś decyzja.

Co ciekawe, prawie każde inne wywołanie na sesji po zamknięciu fabryki przechodzi przez checkOpen(). Gdyby w drodze do commitu było jeszcze jedno persist(), dostałbyś IllegalStateException: Session/EntityManager is closed i czysty rollback. Tylko flush przy commicie po cichu pomija swoją pracę i idzie dalej.

A co na to JPA? Specyfikacja (Jakarta Persistence 3.2) tego przypadku wprost nie opisuje: EntityManagerFactory.close() mówi, że po zamknięciu fabryki wszystkie jej entity managery są zamknięte, a EntityTransaction.commit() ma „writing any unflushed changes to the database” i RollbackException, gdy commit się nie uda. Dla mnie commit, który nie może zapisać zmian, to nieudany commit. Hibernate wypełnia tę lukę – tylko akurat po tej stronie, po której giną dane.

Zgłosiłem to jako HHH-21038 (otwiera się w nowej karcie) (Improvement, 22 października 2026), w chwili pisania dalej ma status New. Zaproponowałem, żeby managedFlush() rzucał wyjątek, jeśli sesja może mieć jeszcze jakieś zmiany (zakolejkowane akcje albo zarządzane Entity), a cichy commit zostawał tylko wtedy, gdy nie ma czego flushować – czyli przypadek z HHH-8586. Jeśli to nie przejdzie, to przynajmniej logować na WARN/ERROR zamiast TRACE.

Oba reproduktory są publiczne: z H2 na szablonie testów Hibernate’a (GitHub, otwiera się w nowej karcie) (commit 96be59a) i z PostgreSQL (GitHub, otwiera się w nowej karcie).

Co muszę teraz zrobić?

Nie panikuj. Ten przypadek występuje tylko wtedy, kiedy jakiś wątek działa dłużej, niż pozwala mu na to SmartLifecycle, a okno czasowe w zwykłej aplikacji to ok. 1.2 ms (w serwisach na produkcji raczej dłużej).

Ogólnie warto trzymać transakcje krótkie. Wolne zewnętrzne API, HTTP do innego serwisu, długie obliczenia – lepiej przed transakcją albo po niej, a w środku tylko zapis do bazy. Do tego timeouty na takich wywołaniach krótsze niż czas, jaki Spring daje na zamknięcie.

Tylko że ludzie popełniają błędy. Ktoś doda wywołanie innego serwisu „na chwilę”, ktoś nie zauważy, że metoda wyżej jest @Transactional, timeout zostanie domyślny (czyli często nieskończony5), albo zupełnie inny bug – deadlock, wolne zapytanie, zawieszony klient – przytrzyma wątek dłużej, niż zakładaliśmy. I wtedy i tak nadziejemy się na ten problem. Dlatego najlepszą ochroną dalej jest strażnik.

Co więc zrobić?

1. Sprawdź w metrykach, ile trwają Twoje transakcje – każda dłuższa to potencjalny kandydat do tego błędu.
2. Wyciągnij z transakcji wywołania zewnętrznych API, HTTP do innych serwisów i długie operacje. Tam, gdzie się nie da, ustaw timeouty krótsze niż czas zamykania.
3. Wdróż strażnika (GitHub, otwiera się w nowej karcie). Jeśli Twoje transakcje trwają długo – nie zastanawiałbym się długo i wdrażał. Jeśli są krótkie – bez pośpiechu, ale nadal warto wdrożyć i nie ryzykować straceniem części transakcji.
4. Obserwuj HHH-21038 (otwiera się w nowej karcie) – jeśli Hibernate to naprawi, strażnika można usunąć.

„Częściowy commit”, na dodatek cichy, bez błędu w logach, to jeden z największych problemów, jakie mogą się nam przytrafić. Nie znajdziemy tego błędu w kodzie, dane będą niespójne, a na dodatek nikt tego nie zauważy.