Show log message about Rollback process

I am testing some rollback capabilities with Spring Data JDBC, but reviewing the logs from one test execution, I don´t see that log with something like "Rollback for xxx"

Log configuration:

logging.level.org.springframework.data=INFO
logging.level.org.springframework.jdbc.core.JdbcTemplate=TRACE
logging.level.org.springframework.transaction=TRACE
logging.level.org.springframework.transaction.interceptor=TRACE

Log output:

The logs represent a Service execution plus the execution of 2 EventListener executed in Serial. When the last Event Listener throw an Exception, I don´t see any log message about the Rollback process, but it is executed the rollback process under the hood in an effective way.

2022-01-04 09:36:47.685  INFO 11820 --- [o-auto-2-exec-1] c.d.b.application.BalanceServiceImpl     : Witdhdraw 10.00 for customer 1
2022-01-04 09:36:47.689 TRACE 11820 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Getting transaction for [org.springframework.data.jdbc.repository.support.SimpleJdbcRepository.findById]
2022-01-04 09:36:47.776 DEBUG 11820 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2022-01-04 09:36:47.777 DEBUG 11820 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT "BALANCE"."BALANCE" AS "BALANCE", "BALANCE"."ID_BALANCE" AS "ID_BALANCE", "BALANCE"."ID_CUSTOMER" AS "ID_CUSTOMER", "BALANCE"."LAST_UPDATE" AS "LAST_UPDATE", "BALANCE"."WITHDRAW_LIMIT" AS "WITHDRAW_LIMIT" FROM "BALANCE" WHERE "BALANCE"."ID_BALANCE" = ?]
2022-01-04 09:36:47.850 TRACE 11820 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Completing transaction for [org.springframework.data.jdbc.repository.support.SimpleJdbcRepository.findById]
2022-01-04 09:36:47.853 TRACE 11820 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Getting transaction for [org.springframework.data.jdbc.repository.support.SimpleJdbcRepository.save]
2022-01-04 09:36:47.899 DEBUG 11820 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL update
2022-01-04 09:36:47.900 DEBUG 11820 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [UPDATE "BALANCE" SET "BALANCE" = ?, "ID_CUSTOMER" = ?, "LAST_UPDATE" = ?, "WITHDRAW_LIMIT" = ? WHERE "BALANCE"."ID_BALANCE" = ?]
2022-01-04 09:36:47.913 TRACE 11820 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : SQL update affected 1 rows
2022-01-04 09:36:47.918 TRACE 11820 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Completing transaction for [org.springframework.data.jdbc.repository.support.SimpleJdbcRepository.save]
2022-01-04 09:36:47.919  INFO 11820 --- [o-auto-2-exec-1] c.d.s.application.BalanceEventListener   : New Event Received: MoneyWithDrewEvent Balance[balanceId=1, balance=90.00, customerId=null, lastUpdate=2022-01-04 09:36:47.852322144, withdrawLimit=null]
2022-01-04 09:36:47.933  INFO 11820 --- [o-auto-2-exec-1] c.d.s.application.BalanceEventListener2  : New Event Received: MoneyWithdrewEventStep2 Balance[balanceId=1, balance=90.00, customerId=null, lastUpdate=2022-01-04 09:36:47.852322144, withdrawLimit=null]
2022-01-04 09:36:47.934 TRACE 11820 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Completing transaction for [com.ddd.balance.application.BalanceServiceImpl.witdhdraw] after exception: java.lang.RuntimeException: Katakroker

Test:

//Initially the customer has a balance with 100
@Test
public void given_balanceController_when_withdraw_happy_path_Ok() {

    //Given
    String address2 = "http://localhost:" + port + "/api/withdraw";
    BigDecimal amount = new BigDecimal("10.00");
    WithdrawRequest widthDrawRequest = new WithdrawRequest(1L, amount);

    HttpHeaders headers = new HttpHeaders();
    HttpEntity<WithdrawRequest> request = new HttpEntity<>(widthDrawRequest, headers);

    //When
    ResponseEntity<String> result2 = this.restTemplate.postForEntity(address2, request, String.class);

    //Then
    WithdrawResponse expectedResponse = new WithdrawResponse(false);
    then(result2.getStatusCode()).isEqualTo(HttpStatus.OK);
    //then(result2.getBody()).contains(asJsonString(expectedResponse));

    //Internally raise an Exception

    //Step Verify

    //Given
    String address3 = "http://localhost:" + port + "/api/balance/1";

    //When
    ResponseEntity<BalanceResponse> result3 = this.restTemplate.getForEntity(address3, BalanceResponse.class);

    //Then
    then(result3.getStatusCode()).isEqualTo(HttpStatus.OK);
    then(result3.getBody().amount()).isEqualTo(new BigDecimal("100.00"));

}

Repository example:

https://github.com/jabrena/101-ddd/blob/feature/balance-iteration2/card-operations-example/src/test/java/com/ddd/balance/infrastructure/rest/BalanceControllerE2ETest.java

Spring Data JDBC execute the rollback internally but I don´t see the traces. How to enable it?

Solution

I was able to see the log with the following configuration:

logging.level.org.springframework.jdbc.support.JdbcTransactionManager=TRACE

Log message:

2022-01-04 10:59:08.417 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.support.JdbcTransactionManager  : Creating new transaction with name [com.ddd.balance.application.BalanceServiceImpl.witdhdraw]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2022-01-04 10:59:08.418 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.support.JdbcTransactionManager  : Acquired Connection [HikariProxyConnection@1551466954 wrapping conn10: url=jdbc:h2:mem:cf10c02a-8c7f-4667-b14a-9de91f7651a9 user=SA] for JDBC transaction
2022-01-04 10:59:08.420 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.support.JdbcTransactionManager  : Switching JDBC Connection [HikariProxyConnection@1551466954 wrapping conn10: url=jdbc:h2:mem:cf10c02a-8c7f-4667-b14a-9de91f7651a9 user=SA] to manual commit
2022-01-04 10:59:08.421 TRACE 2951 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Getting transaction for [com.ddd.balance.application.BalanceServiceImpl.witdhdraw]
2022-01-04 10:59:08.447  INFO 2951 --- [o-auto-2-exec-1] c.d.b.application.BalanceServiceImpl     : Witdhdraw 10.00 for customer 1
2022-01-04 10:59:08.449 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.support.JdbcTransactionManager  : Participating in existing transaction
2022-01-04 10:59:08.450 TRACE 2951 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Getting transaction for [org.springframework.data.jdbc.repository.support.SimpleJdbcRepository.findById]
2022-01-04 10:59:08.521 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2022-01-04 10:59:08.522 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT "BALANCE"."BALANCE" AS "BALANCE", "BALANCE"."ID_BALANCE" AS "ID_BALANCE", "BALANCE"."ID_CUSTOMER" AS "ID_CUSTOMER", "BALANCE"."LAST_UPDATE" AS "LAST_UPDATE", "BALANCE"."WITHDRAW_LIMIT" AS "WITHDRAW_LIMIT" FROM "BALANCE" WHERE "BALANCE"."ID_BALANCE" = ?]
2022-01-04 10:59:08.585 TRACE 2951 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Completing transaction for [org.springframework.data.jdbc.repository.support.SimpleJdbcRepository.findById]
2022-01-04 10:59:08.587 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.support.JdbcTransactionManager  : Participating in existing transaction
2022-01-04 10:59:08.588 TRACE 2951 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Getting transaction for [org.springframework.data.jdbc.repository.support.SimpleJdbcRepository.save]
2022-01-04 10:59:08.628 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL update
2022-01-04 10:59:08.629 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [UPDATE "BALANCE" SET "BALANCE" = ?, "ID_CUSTOMER" = ?, "LAST_UPDATE" = ?, "WITHDRAW_LIMIT" = ? WHERE "BALANCE"."ID_BALANCE" = ?]
2022-01-04 10:59:08.648 TRACE 2951 --- [o-auto-2-exec-1] o.s.jdbc.core.JdbcTemplate               : SQL update affected 1 rows
2022-01-04 10:59:08.653 TRACE 2951 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Completing transaction for [org.springframework.data.jdbc.repository.support.SimpleJdbcRepository.save]
2022-01-04 10:59:08.655  INFO 2951 --- [o-auto-2-exec-1] c.d.s.application.BalanceEventListener   : New Event Received: MoneyWithDrewEvent Balance[balanceId=1, balance=90.00, customerId=null, lastUpdate=2022-01-04 10:59:08.586936363, withdrawLimit=null]
2022-01-04 10:59:08.675  INFO 2951 --- [o-auto-2-exec-1] c.d.s.application.BalanceEventListener2  : New Event Received: MoneyWithdrewEventStep2 Balance[balanceId=1, balance=90.00, customerId=null, lastUpdate=2022-01-04 10:59:08.586936363, withdrawLimit=null]
2022-01-04 10:59:08.676 TRACE 2951 --- [o-auto-2-exec-1] o.s.t.i.TransactionInterceptor           : Completing transaction for [com.ddd.balance.application.BalanceServiceImpl.witdhdraw] after exception: java.lang.RuntimeException: Katakroker
2022-01-04 10:59:08.676 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.support.JdbcTransactionManager  : Initiating transaction rollback
2022-01-04 10:59:08.676 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.support.JdbcTransactionManager  : Rolling back JDBC transaction on Connection [HikariProxyConnection@1551466954 wrapping conn10: url=jdbc:h2:mem:cf10c02a-8c7f-4667-b14a-9de91f7651a9 user=SA]
2022-01-04 10:59:08.678 DEBUG 2951 --- [o-auto-2-exec-1] o.s.jdbc.support.JdbcTransactionManager  : Releasing JDBC Connection [HikariProxyConnection@1551466954 wrapping conn10: url=jdbc:h2:mem:cf10c02a-8c7f-4667-b14a-9de91f7651a9 user=SA] after transaction