I have created a public Github repo replicating and illustrating the issue:
https://github.com/SparkersData/grails414-dataservice-int-test
The integration test aims to update an existing Book object by calling a transactional service, which in turn calls a GORM Data service to update the Book.
BookServiceIntSpec -> [ BookService -> BookDataService ]
The execution of the portion between square brackets should be guarded by a Transaction introduced by the @Transactional annotation of the BookService
I have created 3 different Spec methods that demonstrate the odd behavior.
The preamble of the integration tests is a follows:
import acme.domain.Book
import grails.gorm.transactions.Rollback
import grails.testing.mixin.integration.Integration
import spock.lang.Specification
import spock.lang.Subject
@Integration
@Rollback
@Subject(BookService)
class BookServiceIntSpec extends Specification {
BookService bookService
Book book
void setup() {
book = new Book(title: "The Hobbit")
book.save(flush: true, failOnError: true)
}
void cleanup() {
Book.where {}.deleteAll()
}
}
Production code in BookService:
Book updateWithGORM(Book toUpdate) {
toUpdate.save(flush: true, failOnError: true)
}
This is the Integration test:
def "It is able to update a Book without creating a new transaction, by using GORM in the service."() {
when:
book.title = updatedTitle
bookService.updateWithGORM(book)
then:
Book.findByTitle(updatedTitle) != null
where:
updatedTitle = "Bilbo The Hobbit"
}
Production code in BookService
Book updateWithDataService(Book toUpdate) {
bookDataService.save(toUpdate)
}
This is the Integration test:
def "It is NOT able to update a Book without creating a new transaction, if using a Data Service."() {
when:
book.title = updatedTitle
bookService.updateWithDataService(book)
then:
Book.findByTitle(updatedTitle) == null //<1>
where:
updatedTitle = "Bilbo The Hobbit"
}
<1> The updated book cannot be found after requesting an update
Book updateWithDataService(Book toUpdate) {
bookDataService.save(toUpdate)
}
This is the Integration test:
def "It is able to update a Book by creating a new transaction, if using a Data Service."() {
when:
book.title = updatedTitle
Book.withNewTransaction { //<1>
bookService.updateWithDataService(book)
}
then:
Book.findByTitle(updatedTitle) != null //<2>
where:
updatedTitle = "Bilbo The Hobbit"
}
<1> By usign withNewTransaction, the update succeeds
<2> The updated book CAN be found after requesting an update
Either this is a bug in the integration test runtime of Grails 4.1.4 or the documentation is not clear on how to use transactional services in integration tests. My guesses for the explanation of the behavior:
Has anyone else stumbled on this behavior or has an explanation of this? Wrapping every call with withNewTransaction seems like a nightmare.
By modifying the service method as follows:
Book updateWithDataService(Book toUpdate) {
def res = bookDataService.save(toUpdate)
sessionFactory.currentSession.flush()
res
}
The tests behave properly, without having to mess with creating new transactions, and potentially disturbing the Hibernate session.
I still don't understand why this is not the default behavior!
@mike-w Suggests that I may be hitting some kind of cache when using findByTitle in my test.
I think, however, that it is, on the contrary, when he uses findById() that we are hitting a cache in my test.
This is substantiated by the fact that, when I activate hibernate tracing in logback.groovy:
logger("org.hibernate.type.descriptor.sql.BasicBinder", TRACE, ['STDOUT'], false)
logger("org.hibernate.SQL", DEBUG, ['STDOUT'], false)
Then I can see the following, if I keep the session unflushed:
2024-04-21 01:15:36.620 DEBUG --- [ Test worker] org.hibernate.SQL : select this_.id as y0_ from book this_ where this_.title=? limit ?
2024-04-21 01:15:36.621 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [VARCHAR] - [The Hobbit]
2024-04-21 01:15:36.621 DEBUG --- [ Test worker] org.hibernate.SQL : insert into book (id, version, title) values (null, ?, ?)
2024-04-21 01:15:36.622 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [BIGINT] - [0]
2024-04-21 01:15:36.622 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [VARCHAR] - [The Hobbit]
2024-04-21 01:15:36.625 DEBUG --- [ Test worker] org.hibernate.SQL : select this_.id as y0_ from book this_ where this_.title=? limit ?
2024-04-21 01:15:36.626 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [VARCHAR] - [Bilbo The Hobbit]
2024-04-21 01:15:36.627 DEBUG --- [ Test worker] org.hibernate.SQL : select this_.id as id1_0_0_, this_.version as version2_0_0_, this_.title as title3_0_0_ from book this_ where this_.title=? limit ?
2024-04-21 01:15:36.627 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [VARCHAR] - [Bilbo The Hobbit]
2024-04-21 01:15:36.638 DEBUG --- [ Test worker] org.hibernate.SQL : delete from book
i.e. no update statement whatsoever.
If, however, i add sessionFactory.currentSession.flush() then I can see the following:
2024-04-21 01:21:29.612 DEBUG --- [ Test worker] org.hibernate.SQL : select this_.id as y0_ from book this_ where this_.title=? limit ?
2024-04-21 01:21:29.613 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [VARCHAR] - [The Hobbit]
2024-04-21 01:21:29.614 DEBUG --- [ Test worker] org.hibernate.SQL : insert into book (id, version, title) values (null, ?, ?)
2024-04-21 01:21:29.614 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [BIGINT] - [0]
2024-04-21 01:21:29.614 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [VARCHAR] - [The Hobbit]
2024-04-21 01:21:29.618 DEBUG --- [ Test worker] org.hibernate.SQL : select this_.id as y0_ from book this_ where this_.title=? limit ?
2024-04-21 01:21:29.618 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [VARCHAR] - [Bilbo The Hobbit]
2024-04-21 01:21:29.621 DEBUG --- [ Test worker] org.hibernate.SQL : update book set version=?, title=? where id=? and version=?
2024-04-21 01:21:29.621 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [BIGINT] - [1]
2024-04-21 01:21:29.621 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [VARCHAR] - [Bilbo The Hobbit]
2024-04-21 01:21:29.622 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [BIGINT] - [2]
2024-04-21 01:21:29.622 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [4] as [BIGINT] - [0]
2024-04-21 01:21:29.625 DEBUG --- [ Test worker] org.hibernate.SQL : select this_.id as id1_0_0_, this_.version as version2_0_0_, this_.title as title3_0_0_ from book this_ where this_.title=? limit ?
2024-04-21 01:21:29.625 TRACE --- [ Test worker] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [VARCHAR] - [Bilbo The Hobbit]
2024-04-21 01:21:29.627 DEBUG --- [ Test worker] org.hibernate.SQL : delete from book
So I don't believe that in the first case the book has been updated at all, but in Mike's solution, we are hitting the cache when trying to get the Book by id (i.e. the updated book instance in the hibernate session of the integration test).
All right, I don't know what I was thinking.
Sometimes leaving a problem a couple of days alone is all you need.
Now it seems totally obvious to me that my expectation of the Session being flushed after the transactional service method exits was mistaken.
It is an integration test, marked with @Rollback. This means that the test will run in a transaction that will be rolled back after the test concludes.
The @Transactional service will not create a new transaction, it will join the existing transaction. The transaction by no means is concluded after the transactional service method returns. The transaction is still running inside my integration test.
If I want to measure transactional effects I need to use withNewTransaction and make sure that the service joins a different transaction from my test.
If I want to see the side effects of my service method, I need to flush the session. I can do that by injecting the SessionFactory in the integration test, and calling sessionFactory.currentSession.flush().
So no bug at all. Unless you want to count me being confused.