Using beforeUpdate events breaks instance.getPersistentValue("someProperty")

[SCAI_Andre]

Hi,

Using Grails 3.2.9

I found a rather confusing and irritating issue which is easily reproducable.

When I have add a beforeUpdate event to a domain class and I store a new instance of that domain class, the beforeUpdate event gets fired, the instance gets stored into the db and everything seems just fine.

But when I then try to access the persistent value of a domain object instance in the later course of the application I receive the properties of the incorrect field.

After hours of debugging I found out about the details on that.

HibernateGormInstanceApi.getPersistentValue relies on the sequence of the property values of the domain object in the loadedState in EntityEntry object to be the same as propertyNames in the persister of EntityEntry object.

See the code from HibernateGormInstanceApi.groovy

Object getPersistentValue(D instance, String fieldName) {
        SessionImplementor session = (SessionImplementor)sessionFactory.currentSession
        def entry = findEntityEntry(instance, session, false)
        if (!entry || !entry.loadedState) {
            return null
        }
       
        // searching through list of property names for index of field to get persistent value for
        int fieldIndex = entry.persister.propertyNames.findIndexOf { fieldName == it }
       
        // Grails is now assuming that order of values in loaded state is the
        // same and returning the value from loadedState and index determined above.
        // Hibernate assumes the same convention in other places!
        return fieldIndex == -1 ? null : entry.loadedState[fieldIndex]                
    }

This is usually OK and works in default cases, but does NOT work anymore once a single beforeUpdate event on that domain class has been fired.

What happens is that during saving an object and firing and beforeUpdate event of the domain class, Grails and Hibernate at some point reach the method AbstractEntityPersister.resolveAttributeIndexes.

And this nasty little thing does something really funny in Line 2005 (of hibernate-core:5.1.3.Final):
Arrays.sort( attributeNames );

Before that method has been called the sequence of propertyNames in persister.propertyNames is usually like this:
 * version
 * ... all other properties sorted alphabetically

After that method has been called the order is again alphabetically, including the version property!

But the sequence of values in the loadedState is still the same, with the value for the version property residing at the top (index 0) of loadedState.

So the two lists are not consistent anymore with each other!

The possible consequences are not totally clear to me, but apart from getPersistentValue returning wrong values, I also see a problem in AbstractEntityPersister.hydrate.

Starting from 2772 it iterates over getPropertyNames() and getPropertyTypes() and writes the information into the loadedState from the resultset. This seems to work fine, but it relies on getPropertyNames() having the same order of the values. This only comes into play when determining propertyIsDeferred but still this might be very likely cause errors.

Steps to reproduce

Quite easy:

grails create-app mytestapp
cd mytestapp
grails create-domain-class Book

Modify Book.groovy like this:

class Book {

    static constraints = {
    }

    String bookName
    def beforeUpdate() {
        println "beforeUpdate"
    }
}

grails generate-all Book

Modify BookController.update like this with just to additional lines from the generated default:

    @Transactional
    def update(Book book) {
        // Added line: Log the persistentValue
        println "version: ${book.getPersistentValue("version")}"
       
        if (book == null) {
            transactionStatus.setRollbackOnly()
            notFound()
            return
        }

        if (book.hasErrors()) {
            transactionStatus.setRollbackOnly()
            respond book.errors, view:'edit'
            return
        }

        book.save flush:true

        // Added line: Log the persistentValue
        println "version: ${book.getPersistentValue("version")}"

        request.withFormat {
            form multipartForm {
                flash.message = message(code: 'default.updated.message', args: [message(code: 'book.label', default: 'Book'), book.id])
                redirect book
            }
            '*'{ respond book, [status: OK] }
        }
    }

We are just adding two lines to print (yes, I know about log.debug) the persistent value of the version attribute to the console.

•     Start the application
•     Add a book named "abc"
•     Edit the book, renaming it to "abcd"
•     Save the value

This is what you see on the console:

version: 0
beforeUpdate trigger
version: abcd

Not so cool. All this is caused due to the reordering of propertyNames in AbstractEntityPersister.resolveAttributeIndexes, which only happens when you have a beforeUpdate trigger. Otherwise this does not get called once the application has been launched.

This seems not only to be a Grails bug but a Hibernate bug. The sources of newer versions of Hibernate look the same as far as I can tell, but I cannot test it, since Grails does not work with newer releases of Hibernate, giving exceptions already when launching the application.

What to do?

I cannot say when this has been introduced, but since the consistency of loadedState with propertyNames in the EnitityEntry seems to so fundamental to Grails and Hibernate while using beforeUpdate triggers in domain classes being not uncommon we have a risk that many applications are broken without easily recognizing.

What do you think?

Thanks,
André

[SCAI_Andre]

To make it simpler to reproduce I uploaded the test project to github:

git clone https://github.com/scai-gmbh/grails-showpersistentvaluebug.git
cd grails-showpersistentvaluebug
./gradlew bootRun

• goto http://localhost:8080/book/create
• Create a book named "abc" and click the "Create" button or whatever it is called in you i18n
  
• Edit the books name in http://localhost:8080/book/edit/1
• Change the books name to "abcd" and click the "Update" button
• See console showing this

version: 0
beforeUpdate
version: abcd <<<<< this should be a number (the hibernate version), but it is book.name now! It remains like that now as long as the application is running!

[SCAI_Andre]

I received info from Graeme on slack that this issue was just fixed here
https://github.com/grails/gorm-hibernate5/commit/8c1645ace02ea83e40d5220cea20918548727389

And this is the issue I was too stupid to find
https://github.com/grails/grails-core/issues/10609

I still think there is an issue in Hibernate left (see https://github.com/hibernate/hibernate-orm/blob/5.1/hibernate-core/src/main/java/org/hibernate/persister/entity/AbstractEntityPersister.java#L2830 ) but that code is far above my head and I cannot produce a test case for my assumption.

Thanks to Graeme for pointing me to the right issue!