Javers: Incorrect new last modified date stored in commit for UPDATEs

[OmarHawk]

Hi,

we have Javers configured in our application and use basically defaults for kind of everything related to this Blueprint. We noticed, that the LastModifiedDate, that is being set by Spring Data via the @LastModifiedDate is not reflected within the data stored within Javers tables for the new value of an existing Entity, so we get so see the following observations:

In Javers, it shows the values that the users has submitted from the Frontend form (which is the old/previous value actually, without seconds/milliseconds). This is kind of confusing....

I do assume, that Javers takes the response value from the Spring Data repository for the entity to store
values in its tables.
This happens before actually calculating the actual new value and especially for the actual update of the data, as visible in the following log excerpt, where the INSERT into the javers tables happens before the update within the entity table. Maybe it has something to do with how the @Transactional and the @LastModifiedDate in combination works for Updates.
I do assume, the actual calculation and commit of that value happens at the end of the @Transactional session and not when the JPA Repository returns a value... which may be the root cause here...

Strangely, for initial INSERTs, it does work, i.e. for the very first commit in the Javers tables, the values are appropriate and also the INSERT into the Entity happens before the INSERT into the Javers table according to the logs.

2024-03-04T17:16:42.986+01:00 DEBUG 20652 --- [  XNIO-1 task-3] o.javers.core.graph.ObjectGraphBuilder   : live graph assembled, object nodes: 1, entities: 1, valueObjects: 0
2024-03-04T17:16:42.988+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : SQL session 'get head id' finished. 1 statement(s) executed in 
1 millis.
2024-03-04T17:16:42.989+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : * SELECT max CommitId              executed 1 time(s) in 1 millis, SQL: SELECT MAX(commit_id) FROM jv_commit WHERE 1 = 1
2024-03-04T17:16:42.993+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : SQL session 'get latest snapshots' finished. 2 statement(s) executed in 1 millis.
2024-03-04T17:16:42.994+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : * SELECT snapshots                 executed 1 time(s) in 1 millis, SQL:   SELECT state, type, version, changed_properties, managed_type, commit_pk, 
author, commit_date, commit_date_instant, commit_id, g.local_id, g.fragment, g.owner_id_fk, o.local_id owner_local_id, o.fragment owner_fragment, o.type_name owner_type_name FROM jv_snapshot INNER JOIN jv_commit ON commit_pk = commit_fk INNER JOIN jv_global_id g ON g.global_id_pk = global_id_fk LEFT OUTER JOIN jv_global_id o ON o.global_id_pk = g.owner_id_fk WHERE 1 = 1 AND snapshot_pk = ? ORDER BY snapshot_pk DESC LIMIT 
? OFFSET ?
2024-03-04T17:16:42.995+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : * SELECT select max snapshot's PK  executed 1 time(s) in 0 millis, SQL: SELECT MAX(snapshot_pk) FROM jv_snapshot WHERE 1 = 1 AND global_id_fk = ?   
2024-03-04T17:16:43.000+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : SQL session 'persist commit' finished. 3 statement(s) executed 
in 1 millis.
2024-03-04T17:16:43.001+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : * INSERT Commit                    executed 1 time(s) in 1 millis, SQL: INSERT INTO jv_commit ( author, commit_date, commit_date_instant, commit_id 
) VALUES  ( ?,?,?,? )
2024-03-04T17:16:43.001+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : * INSERT Snapshot                  executed 1 time(s) in 0 millis, SQL: INSERT INTO jv_snapshot ( type, global_id_fk, commit_fk, version, state, changed_properties, managed_type ) VALUES  ( ?,?,?,?,?,?,? )
2024-03-04T17:16:43.002+01:00 TRACE 20652 --- [  XNIO-1 task-3] org.javers.SQL       
                    : * last autoincrementDefinition id  executed 1 time(s) in 0 millis, SQL: select last_insert_id()
2024-03-04T17:16:43.003+01:00  INFO 20652 --- [  XNIO-1 task-3] org.javers.core.Javers                   : Commit(id:15.00, snapshots:1, author:jwedding, changes - ValueChange:1), done in 17 ms (diff:10 ms, persist:7 ms)
2024-03-04T17:16:43.005+01:00 DEBUG 20652 --- [dataview-task-2] org.hibernate.SQL    
                    : select sj1_0.id,sj1_0.active,sj1_0.created_by,sj1_0.created_date,sj1_0.delsourceitem,sj1_0.friday,sj1_0.hour,sj1_0.info,sj1_0.inprogress,sj1_0.jobname,sj1_0.jobpattern,sj1_0.jobtype,sj1_0.last_modified_by,sj1_0.last_modified_date,sj1_0.lastrun_at,sj1_0.minute,sj1_0.monday,sj1_0.rightid_id,r1_0.id,r1_0.created_by,r1_0.created_date,r1_0.description,r1_0.last_modified_by,r1_0.last_modified_date,r1_0.name,sj1_0.runonce,sj1_0.saturday,s1_0.id,s1_0.active,s1_0.cloudstate,s1_0.connectionid_id,s1_0.created_by,s1_0.created_date,s1_0.information,s1_0.last_modified_by,s1_0.last_modified_date,s1_0.resend,s1_0.usecasename,s1_0.validfrom,sj1_0.sunday,sj1_0.thursday,t1_0.id,t1_0.active,t1_0.cloudstate,t1_0.connectionid_id,t1_0.created_by,t1_0.created_date,t1_0.information,t1_0.last_modified_by,t1_0.last_modified_date,t1_0.resend,t1_0.usecasename,t1_0.validfrom,sj1_0.tuesday,sj1_0.wednesday from stream_jobs sj1_0 left join stream_rights r1_0 on r1_0.id=sj1_0.rightid_id left join stream_usecaseid s1_0 on s1_0.id=sj1_0.sid_id left join stream_usecaseid t1_0 on t1_0.id=sj1_0.tid_id where sj1_0.id=?
2024-03-04T17:16:43.006+01:00 DEBUG 20652 --- [  XNIO-1 task-3] org.hibernate.SQL    
                    : update stream_jobs set active=?,delsourceitem=?,friday=?,hour=?,info=?,inprogress=?,jobname=?,jobpattern=?,jobtype=?,last_modified_by=?,last_modified_date=?,lastrun_at=?,minute=?,monday=?,rightid_id=?,runonce=?,saturday=?,sid_id=?,sunday=?,thursday=?,tid_id=?,tuesday=?,wednesday=? where id=?   

We do have MySQL8, JHipster 8.1.0 (Spring Boot 3.2.0).

I'm still investigating deeper and hope to figure out the root cause (possibily nothing directly related to the Blueprint), but maybe, someone else made similar observations and needs a starting point for investigations.

[OmarHawk]

I figured out the mechanism mentioned above does work properly, if I'd change the generated service.update method (the default one from JHipster) to use

repository.saveAndFlush(entity)

instead of

repository.save(entity)

So now, I do wonder, why repository.save(entity) for some reasons delays an UPDATE into the database (but not an INSERT) therefore leading to strange side effects in this Blueprint... and whether this may be something that I should open as ticket in generator-jhipster itself...

Seemingly having to do something with Hibernate.

[OmarHawk]

Could be related to spring-projects/spring-data-jpa#1735 - where it is explained it is an expected behaviour when using a completely new instance while wanting to actually update one that is already in the database. We also have updateable=false on these audit fields

[OmarHawk]

Ok, so the Default JpaRepository is checking, if an entity is new and if so, it immediately persists it. If it is not new (like in the update case) it just runs a merge on the entityManager, and only once the @Transactional method is through, it will persist. I'd create a ticket in generator-jhipster itself to discuss about it...

[mshima]

It will probably require to implement Persistable interface.
@RequiresPersistableImplementation

[mshima]

It will probably require to implement Persistable interface. @RequiresPersistableImplementation

Seems to work.

[mshima]

I see now. We probably should change to saveAndFlush at update operation.

[OmarHawk]

I did this in my own application via a custom blueprint and noticed, the JaversSpringDataAuditableRepositoryAspect as being default does not define an Advice for the saveAndFlush method, so these save operations were not recorded. Therefore, we had to configure the JaversSpringDataJpaAuditableRepositoryAspect instead by configuring it as a part of an @Configuration class:

package de.mt.dv.config.audit;

import org.javers.core.Javers;
import org.javers.spring.auditable.AuthorProvider;
import org.javers.spring.auditable.CommitPropertiesProvider;
import org.javers.spring.auditable.aspect.springdatajpa.JaversSpringDataJpaAuditableRepositoryAspect;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.EnableAspectJAutoProxy;

@Configuration
@EnableAspectJAutoProxy
public class JaverSpecialConfiguration {

    @Bean
    public JaversSpringDataJpaAuditableRepositoryAspect javersSpringDataAuditableAspect(
        Javers javers,
        AuthorProvider authorProvider,
        CommitPropertiesProvider commitPropertiesProvider
    ) {
        return new JaversSpringDataJpaAuditableRepositoryAspect(javers, authorProvider, commitPropertiesProvider);
    }
}

Additionally, it is required, to turn off the default Aspect in e.g. application.yaml file:

javers:
  springDataAuditableRepositoryAspectEnabled: false