hi, I am using Spring 6.1.4 and Spring Boot 3.2.2 Everything works well, but I thought it would be great to make the logs more explicit. In a JUnit test, I would like to know when my transactions are created and rolled back.

Inside application.properties, I have enabled Transaction tracing as follows:

logging.level.org.springframework.transaction=trace

Inside my JUnit test, I have 2 simple test cases:

@BeforeEach
    public void setup() {
        this.studentRepository.save(new Student(0L, "Steve", "Lukather"));
    }

    @Test @Transactional
    public void shouldFindStudent() {
        var student = this.studentRepository.findByFirstName("Steve").orElse(null);
        assertThat(student.getFirstName()).isEqualTo("Steve");
    }

    @Test @Transactional
    public void shouldFindStudent2() {
        var student = this.studentRepository.findByFirstName("Steve").orElse(null);
        assertThat(student.getFirstName()).isEqualTo("Steve");
    }

I am getting the following logs:

TRACE 26401 --- [           main] o.s.t.i.TransactionInterceptor           : Getting transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
Hibernate: select s1_0.id,s1_0.first_name,l1_0.id,l1_0.name,s1_0.last_name,c1_0.student_id,c1_0.id,c1_0.name from student s1_0 left join laptop l1_0 on l1_0.id=s1_0.laptop_id left join course c1_0 on s1_0.id=c1_0.student_id where s1_0.id=?
2024-03-08T06:08:38.322+08:00 TRACE 26401 --- [           main] org.hibernate.orm.jdbc.bind              : binding parameter (1:BIGINT) <- [0]
Hibernate: insert into student (first_name,laptop_id,last_name,id) values (?,?,?,default)
2024-03-08T06:08:38.324+08:00 TRACE 26401 --- [           main] org.hibernate.orm.jdbc.bind              : binding parameter (1:VARCHAR) <- [Steve]
2024-03-08T06:08:38.324+08:00 TRACE 26401 --- [           main] org.hibernate.orm.jdbc.bind              : binding parameter (2:BIGINT) <- [null]
2024-03-08T06:08:38.324+08:00 TRACE 26401 --- [           main] org.hibernate.orm.jdbc.bind              : binding parameter (3:VARCHAR) <- [Lukather]
2024-03-08T06:08:38.325+08:00 TRACE 26401 --- [           main] o.s.t.i.TransactionInterceptor           : Completing transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]
2024-03-08T06:08:38.326+08:00 TRACE 26401 --- [           main] o.s.t.i.TransactionInterceptor           : No need to create transaction for [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findByFirstName]: This method is not transactional.
Hibernate: select s1_0.id,s1_0.first_name,s1_0.laptop_id,s1_0.last_name from student s1_0 where s1_0.first_name=?
2024-03-08T06:08:38.328+08:00 TRACE 26401 --- [           main] org.hibernate.orm.jdbc.bind              : binding parameter (1:VARCHAR) <- [Steve]
  1. There is no log when transactions are rolled back. Would it be possible to add a log message on that? I believe it's useful for educational purpose, people can understand better what happened.
  2. No need to create transaction for [..findByFirstName]: This message may be confusing. There is already an existing transaction running. May be it would help to rephrase it with something like No need to create new transaction for or [..findByFirstName] will participate in the exisitng transaction

I'll be happy to provide a sample test project if needed.

Great thanks!

Comment From: snicoll

1 and 2 are unrelated so we can't handle these in the same issue. Yes, please attach a sample project and we can look at it. From a quick glance, 1 can be due to the fact the TCF is rollbacking the transaction outside the boundary of the test method itself but a sample would help make sure we're talking about the same thing.

Comment From: jhoeller

@michaelisvy with the "org.springframework.transaction" category, you are only going to see the rather trace-y TransactionInterceptor interaction logs. And as @snicoll pointed out: in a test scenario, TransactionInterceptor really just participates in a TCF-managed outer transaction and does not initiate a commit/rollback itself which is why you are not seeing any rollback message from that component. Overall, those TransactionInterceptor log messages are not really worth much reconsideration, not least of it all since they are trace level to begin with.

The more relevant logs for actual transaction tracking come out of the chosen transaction manager which logs at debug level into "org.springframework.jdbc" or "org.springframework.orm", depending on JDBC/JPA/etc. This should provide all you expect there; let us know if that is sufficient for your purposes. We can probably simply close this issue then, not sure what we could refine beyond that.

Comment From: michaelisvy

hello @snicoll , @jhoeller , thanks a lot for your quick answer!

Actually I followed your advice and configured my logs as below (for a JPA Transaction manager):

logging.level.org.springframework.orm.jpa=DEBUG

It's all good now, thanks! I had tried it a while ago and was surprised that it didn't work, but I guess my mistake was to use orm.hibernate instead of orm.jpa or something like that. All good now, please feel free to close my ticket, and thanks a lot for the very fast support!

Comment From: sbrannen

As a side note, all of the transaction management logging in the TestContext framework is logged from types in the org.springframework.test.context.transaction package.

So I typically recommend that users turn on DEBUG logging for org.springframework.test.context.transaction to see what's going on in integration tests.

If you do that, you'll find that you actually get a LOT more details coming from org.springframework.test.context.transaction.TransactionContext and org.springframework.test.context.transaction.TransactionalTestExecutionListener.

Comment From: michaelisvy

thanks Sam! Actually I tried what you've suggested but it doesn't seem to work in all cases. For instance, with the way you suggested, I can get logs with a unit test decorated with @Transactional. But if I remove the @Transactional from the unit test, I'm not getting transaction logs anymore. Anyway, the below way works perfectly, so I'm good with it.

logging.level.org.springframework.orm.jpa=DEBUG