Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Double delete due to batch flush #3363

Closed
tbee opened this issue Mar 18, 2024 · 27 comments · Fixed by #3367
Closed

Double delete due to batch flush #3363

tbee opened this issue Mar 18, 2024 · 27 comments · Fixed by #3367

Comments

@tbee
Copy link
Contributor

tbee commented Mar 18, 2024 •
edited
Loading

EBean 14.0.1-javax

We have the following entities (simplified):

class PresenceLog {
    @ManyToOne
    @JoinColumn(name = "clusterobjectid")
    private Cluster employeeCluster;

    @ManyToOne
    @JoinColumn(name = "costclusterobjectid")
    private Cluster costCluster;
}

class Cluster {
    // no @OneToMany to PresenceLog

    @PostRemove
    public void postRemove() {
        // a query on a PresenceLog using employeeCluster or costCluster
    }
}

When a cluster is DB.delete inside a JTA transaction, the correct sql delete statement is executed. After that the postRemove is triggered, which does the query. The query triggers a batchFlush, re-executes that delete, and verifies if the delete has a row count of 1. It of course has not, and thus throws a "data has changed" exception.

It passes though BatchControl.executeNow which sets the flushOnQuery to false, but it seems that is not checked afterwards, and it still re-executes the delete statement in the batch flush.

The stack trace at the moment the exception is thrown:

checkRowCount:812, PersistRequestBean (io.ebeaninternal.server.core)
executeAndCheckRowCounts:167, BatchedPstmt (io.ebeaninternal.server.persist)
executeBatch:114, BatchedPstmt (io.ebeaninternal.server.persist)
executeAll:139, BatchedPstmtHolder (io.ebeaninternal.server.persist)
flush:115, BatchedPstmtHolder (io.ebeaninternal.server.persist)
flushPstmtHolder:216, BatchControl (io.ebeaninternal.server.persist)
executeNow:238, BatchControl (io.ebeaninternal.server.persist)
executeNow:93, BatchedBeanHolder (io.ebeaninternal.server.persist)
executeAll:328, BatchControl (io.ebeaninternal.server.persist)
flushInternal:305, BatchControl (io.ebeaninternal.server.persist)
flushBuffer:278, BatchControl (io.ebeaninternal.server.persist)
flushOnCommit:246, BatchControl (io.ebeaninternal.server.persist)
batchFlush:550, JdbcTransaction (io.ebeaninternal.server.transaction)
internalBatchFlush:665, JdbcTransaction (io.ebeaninternal.server.transaction)
flush:654, JdbcTransaction (io.ebeaninternal.server.transaction)
flushJdbcBatchOnQuery:63, DefaultOrmQueryEngine (io.ebeaninternal.server.query)
findMany:118, DefaultOrmQueryEngine (io.ebeaninternal.server.query)
findList:403, OrmQueryRequest (io.ebeaninternal.server.core)
findList:1430, DefaultServer (io.ebeaninternal.server.core)
findList:1409, DefaultServer (io.ebeaninternal.server.core)
findList:1517, DefaultOrmQuery (io.ebeaninternal.server.querydefn)
forClusterRemovedOnly:636, PresenceLogFinder (com.nedap.healthcare.administration.registration.presencelog)
process:29, ClusterChangedEventListener (com.nedap.healthcare.administration.registration.presencelog)
invoke0:-1, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:62, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:566, Method (java.lang.reflect)
invokeHandler:23, ReflectiveHandlerInvocation (net.engio.mbassy.dispatch)
invoke:49, ReflectiveHandlerInvocation (net.engio.mbassy.dispatch)
dispatch:30, MessageDispatcher (net.engio.mbassy.dispatch)
publish:49, Subscription (net.engio.mbassy.subscription)
execute:43, MessagePublication (net.engio.mbassy.bus)
publish:37, MBassador (net.engio.mbassy.bus)
fire:43, EventBus (com.nedap.healthcare.administration.eventbus)
postRemove:577, Cluster (com.nedap.healthcare.administration.crm.cluster)
invoke0:-1, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:62, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:566, Method (java.lang.reflect)
invoke:203, BeanLifecycleAdapterFactory$PersistAdapter (io.ebeaninternal.server.deploy)
invoke:211, BeanLifecycleAdapterFactory$PersistAdapter (io.ebeaninternal.server.deploy)
postDelete:241, BeanLifecycleAdapterFactory$PersistAdapter (io.ebeaninternal.server.deploy)
postDelete:103, ChainedBeanPersistController (io.ebeaninternal.server.deploy)
controllerPost:933, PersistRequestBean (io.ebeaninternal.server.core)
postExecute:874, PersistRequestBean (io.ebeaninternal.server.core)
checkRowCount:100, DmlHandler (io.ebeaninternal.server.persist.dml)
execute:51, DeleteHandler (io.ebeaninternal.server.persist.dml)
executeNoBatch:88, DmlHandler (io.ebeaninternal.server.persist.dml)
execute:69, DmlBeanPersister (io.ebeaninternal.server.persist.dml)
delete:38, DmlBeanPersister (io.ebeaninternal.server.persist.dml)
executeDelete:1238, PersistRequestBean (io.ebeaninternal.server.core)
executeNow:746, PersistRequestBean (io.ebeaninternal.server.core)
executeOrQueue:171, BatchControl (io.ebeaninternal.server.persist)
executeOrQueue:765, PersistRequestBean (io.ebeaninternal.server.core)
delete:925, DefaultPersister (io.ebeaninternal.server.persist)
deleteRequest:565, DefaultPersister (io.ebeaninternal.server.persist)
deleteRequest:547, DefaultPersister (io.ebeaninternal.server.persist)
delete:539, DefaultPersister (io.ebeaninternal.server.persist)
delete:1844, DefaultServer (io.ebeaninternal.server.core)
delete:1835, DefaultServer (io.ebeaninternal.server.core)
delete:481, DB (io.ebean)
lambda$delete$1:252, TestUtil (com.nedap.healthcare.administratie.util)
get:-1, 1438035345 (com.nedap.healthcare.administratie.util.TestUtil$$Lambda$2344)
runInTransaction:42, TransactionServiceImpl (com.nedap.aeos.ejbutil)
invoke:-1, GeneratedMethodAccessor187 (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:566, Method (java.lang.reflect)
processInvocation:52, ManagedReferenceMethodInterceptor (org.jboss.as.ee.component)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:43, ExecutionTimeInterceptor (org.jboss.as.ejb3.component.invocationmetrics)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:47, SBInvocationInterceptor (org.jboss.as.jpa.interceptor)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:45, ConcurrentContextInterceptor (org.jboss.as.ee.concurrent)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:40, InitialInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:53, ChainedInterceptor (org.jboss.invocation)
processInvocation:52, ComponentDispatcherInterceptor (org.jboss.as.ee.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:51, PooledInstanceInterceptor (org.jboss.as.ejb3.component.pool)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:56, AdditionalSetupInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
invokeInNoTx:232, CMTTxInterceptor (org.jboss.as.ejb3.tx)
supports:446, CMTTxInterceptor (org.jboss.as.ejb3.tx)
processInvocation:164, CMTTxInterceptor (org.jboss.as.ejb3.tx)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:41, CurrentInvocationContextInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:47, WaitTimeInterceptor (org.jboss.as.ejb3.component.invocationmetrics)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:73, IdentityOutflowInterceptor (org.jboss.as.ejb3.security)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:44, SecurityDomainInterceptor (org.jboss.as.ejb3.security)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:22, StartupAwaitInterceptor (org.jboss.as.ejb3.deployment.processors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:64, ShutDownInterceptorFactory$1 (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:67, LoggingInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:50, NamespaceContextInterceptor (org.jboss.as.ee.component)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:60, ContextClassLoaderInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
run:438, InterceptorContext (org.jboss.invocation)
doChecked:633, WildFlySecurityManager (org.wildfly.security.manager)
processInvocation:57, AccessCheckingInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:53, ChainedInterceptor (org.jboss.invocation)
invoke:198, ViewService$View (org.jboss.as.ee.component)
processInvocation:191, ViewDescription$1 (org.jboss.as.ee.component)
invoke:81, ProxyInvocationHandler (org.jboss.as.ee.component)
runInTransaction:-1, TransactionService$$$view586 (com.nedap.aeos.ejbutil)
delete:252, TestUtil (com.nedap.healthcare.administratie.util)
tearDown:34, ClusterRule (com.nedap.healthcare.administration.rules)
evaluate:47, EnvironmentSetupRule$1 (com.nedap.healthcare.administration)
evaluate:42, EnvironmentSetupRule$1 (com.nedap.healthcare.administration)
evaluate:42, EnvironmentSetupRule$1 (com.nedap.healthcare.administration)
evaluate:239, ExpectedException$ExpectedExceptionStatement (org.junit.rules)
evaluate:20, RunRules (org.junit.rules)
runLeaf:325, ParentRunner (org.junit.runners)
runChild:78, BlockJUnit4ClassRunner (org.junit.runners)
runChild:57, BlockJUnit4ClassRunner (org.junit.runners)
run:290, ParentRunner$3 (org.junit.runners)
schedule:71, ParentRunner$1 (org.junit.runners)
runChildren:288, ParentRunner (org.junit.runners)
access$000:58, ParentRunner (org.junit.runners)
evaluate:268, ParentRunner$2 (org.junit.runners)
run:363, ParentRunner (org.junit.runners)
run:28, NedapJunit4Runner (com.nedap.healthcare.administratie.util)
run:137, JUnitCore (org.junit.runner)
run:115, JUnitCore (org.junit.runner)
run:134, TestRunner$2 (net.sf.junite2.runner)
run:149, TestRunner (net.sf.junite2.runner)
runTests:257, JUnitEEServlet (net.sf.junite2.servlet)
doGet:225, JUnitEEServlet (net.sf.junite2.servlet)
service:503, HttpServlet (javax.servlet.http)
service:590, HttpServlet (javax.servlet.http)
handleRequest:74, ServletHandler (io.undertow.servlet.handlers)
handleRequest:62, ServletSecurityRoleHandler (io.undertow.servlet.handlers.security)
handleRequest:68, ServletChain$1 (io.undertow.servlet.handlers)
handleRequest:36, ServletDispatchingHandler (io.undertow.servlet.handlers)
lambda$handleRequest$1:68, ElytronRunAsHandler (org.wildfly.elytron.web.undertow.server)
call:-1, 57990013 (org.wildfly.elytron.web.undertow.server.ElytronRunAsHandler$$Lambda$2339)
apply:-1, 221947350 (org.wildfly.security.auth.server.Scoped$$Lambda$2340)
apply:-1, 382694305 (org.wildfly.security.auth.server.Scoped$$Lambda$2341)
runAsFunctionEx:103, FlexibleIdentityAssociation (org.wildfly.security.auth.server)
runAsFunctionEx:161, Scoped (org.wildfly.security.auth.server)
runAs:73, Scoped (org.wildfly.security.auth.server)
handleRequest:67, ElytronRunAsHandler (org.wildfly.elytron.web.undertow.server)
handleRequest:68, RedirectDirHandler (io.undertow.servlet.handlers)
handleRequest:117, SSLInformationAssociationHandler (io.undertow.servlet.handlers.security)
handleRequest:57, ServletAuthenticationCallHandler (io.undertow.servlet.handlers.security)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleRequest:46, AbstractConfidentialityHandler (io.undertow.security.handlers)
handleRequest:64, ServletConfidentialityConstraintHandler (io.undertow.servlet.handlers.security)
handleRequest:43, AbstractSecurityContextAssociationHandler (io.undertow.security.handlers)
handleRequest:38, CleanUpHandler (org.wildfly.elytron.web.undertow.server.servlet)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleRequest:61, JACCContextIdHandler (org.wildfly.extension.undertow.security.jacc)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleRequest:68, GlobalRequestControllerHandler (org.wildfly.extension.undertow.deployment)
handleRequest:52, SendErrorPageHandler (io.undertow.servlet.handlers)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleFirstRequest:275, ServletInitialHandler (io.undertow.servlet.handlers)
access$100:79, ServletInitialHandler (io.undertow.servlet.handlers)
call:134, ServletInitialHandler$2 (io.undertow.servlet.handlers)
call:131, ServletInitialHandler$2 (io.undertow.servlet.handlers)
call:48, ServletRequestContextThreadSetupAction$1 (io.undertow.servlet.core)
call:43, ContextClassLoaderSetupAction$1 (io.undertow.servlet.core)
lambda$create$0:1544, UndertowDeploymentInfoService$UndertowThreadSetupAction (org.wildfly.extension.undertow.deployment)
call:-1, 769732336 (org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1321)
lambda$create$0:1544, UndertowDeploymentInfoService$UndertowThreadSetupAction (org.wildfly.extension.undertow.deployment)
call:-1, 769732336 (org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1321)
lambda$create$0:1544, UndertowDeploymentInfoService$UndertowThreadSetupAction (org.wildfly.extension.undertow.deployment)
call:-1, 769732336 (org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1321)
lambda$create$0:1544, UndertowDeploymentInfoService$UndertowThreadSetupAction (org.wildfly.extension.undertow.deployment)
call:-1, 769732336 (org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1321)
dispatchRequest:255, ServletInitialHandler (io.undertow.servlet.handlers)
access$000:79, ServletInitialHandler (io.undertow.servlet.handlers)
handleRequest:100, ServletInitialHandler$1 (io.undertow.servlet.handlers)
executeRootHandler:387, Connectors (io.undertow.server)
run:852, HttpServerExchange$1 (io.undertow.server)
run:35, ContextClassLoaderSavingRunnable (org.jboss.threads)
safeRun:1990, EnhancedQueueExecutor (org.jboss.threads)
doRunTask:1486, EnhancedQueueExecutor$ThreadBody (org.jboss.threads)
run:1348, EnhancedQueueExecutor$ThreadBody (org.jboss.threads)
run:1282, XnioWorker$WorkerThreadFactory$1$1 (org.xnio)
run:829, Thread (java.lang)

The logging and actual exception:

...
13:57:23,182 DEBUG (default task-1) [io.ebean.SQL] txn[] delete from manager_cluster where clusterobjectid = ?
13:57:23,184 DEBUG (default task-1) [io.ebean.SQL] txn[]  -- bind(3)
13:57:23,184 DEBUG (default task-1) [io.ebean.SQL] txn[] delete from cluster_address where clusterObjectId = ?
13:57:23,184 DEBUG (default task-1) [io.ebean.SQL] txn[]  -- bind(3)
13:57:23,185 DEBUG (default task-1) [io.ebean.SQL] txn[]  -- executeBatch() size:1 sql:delete from manager_cluster where clusterobjectid = ?
13:57:23,185 DEBUG (default task-1) [io.ebean.SQL] txn[]  -- executeBatch() size:1 sql:delete from cluster_address where clusterObjectId = ?
13:57:23,186 DEBUG (default task-1) [io.ebean.SQL] txn[] select t0.objectId, t0.createdAt, t0.updatedAt, t0.version, t0.clusterobjectid, t0.unitobjectid from treatmentlocation t0 where t0.clusterobjectid = ?; --bind(3) --micros(253)
13:57:23,199 DEBUG (default task-1) [io.ebean.SQL] txn[] select count(*) from ( select c.objectid FROM careorder c LEFT JOIN primary_care_order pco ON c.objectid = pco.careorder_objectid  LEFT JOIN treatmentlocation tl1 ON tl1.objectid = pco.treatment_location_objectid  LEFT JOIN bggz_care_order bco ON c.objectid = bco.careOrderObjectId  LEFT JOIN treatmentlocation tl2 ON tl2.objectid = bco.treatment_location_objectid  WHERE tl1.clusterobjectid = ? OR tl2.clusterobjectid = ? ) as c; --bind(3, 3) --micros(2.816)
13:57:23,204 DEBUG (default task-1) [io.ebean.SQL] txn[] select t0.objectId, t0.createdAt, t0.updatedAt, t0.beginDate, t0.endDate, t0.version, t0.careOrderObjectId, t0.treatmentLocationObjectId from careorder_zpm_treatmentlocation t0 left join treatmentlocation t1 on t1.objectId = t0.treatmentLocationObjectId where t1.clusterobjectid = ? limit 1; --bind(3) --micros(2.261)
13:57:23,205 DEBUG (default task-1) [io.ebean.SQL] txn[] delete from carriercluster where objectId=? and version=?; -- bind(3,3)
13:57:23,210 DEBUG (default task-1) [io.ebean.SQL] txn[] delete from treatmentlocation where objectId=? and version=?
13:57:23,210 DEBUG (default task-1) [io.ebean.SQL] txn[]  -- bind(1,1)
13:57:23,210 DEBUG (default task-1) [io.ebean.SQL] txn[]  -- executeBatch() size:1 sql:delete from treatmentlocation where objectId=? and version=?
Caused by: javax.persistence.OptimisticLockException: Data has changed. updated row count 0
        at deployment.ioserver.ear//io.ebeaninternal.server.core.PersistRequestBean.checkRowCount(PersistRequestBean.java:812)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedPstmt.executeAndCheckRowCounts(BatchedPstmt.java:167)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedPstmt.executeBatch(BatchedPstmt.java:114)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedPstmtHolder.executeAll(BatchedPstmtHolder.java:139)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedPstmtHolder.flush(BatchedPstmtHolder.java:115)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.flushPstmtHolder(BatchControl.java:216)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.executeNow(BatchControl.java:238)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedBeanHolder.executeNow(BatchedBeanHolder.java:93)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.executeAll(BatchControl.java:328)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.flushInternal(BatchControl.java:305)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.flushBuffer(BatchControl.java:278)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.flushOnCommit(BatchControl.java:246)
        at deployment.ioserver.ear//io.ebeaninternal.server.transaction.JdbcTransaction.batchFlush(JdbcTransaction.java:550)
        at deployment.ioserver.ear//io.ebeaninternal.server.transaction.JdbcTransaction.internalBatchFlush(JdbcTransaction.java:665)
        at deployment.ioserver.ear//io.ebeaninternal.server.transaction.JdbcTransaction.flush(JdbcTransaction.java:654)
        at deployment.ioserver.ear//io.ebeaninternal.server.query.DefaultOrmQueryEngine.flushJdbcBatchOnQuery(DefaultOrmQueryEngine.java:63)
        at deployment.ioserver.ear//io.ebeaninternal.server.query.DefaultOrmQueryEngine.findMany(DefaultOrmQueryEngine.java:118)
        at deployment.ioserver.ear//io.ebeaninternal.server.core.OrmQueryRequest.findList(OrmQueryRequest.java:403)
        at deployment.ioserver.ear//io.ebeaninternal.server.core.DefaultServer.findList(DefaultServer.java:1430)
        at deployment.ioserver.ear//io.ebeaninternal.server.core.DefaultServer.findList(DefaultServer.java:1409)
        at deployment.ioserver.ear//io.ebeaninternal.server.querydefn.DefaultOrmQuery.findList(DefaultOrmQuery.java:1517)
        at deployment.ioserver.ear.registration.jar//com.nedap.healthcare.administration.registration.presencelog.PresenceLogFinder.forClusterRemovedOnly(PresenceLogFinder.java:636)
        at deployment.ioserver.ear.registration.jar//com.nedap.healthcare.administration.registration.presencelog.ClusterChangedEventListener.process(ClusterChangedEventListener.java:29)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at deployment.ioserver.ear//net.engio.mbassy.dispatch.ReflectiveHandlerInvocation.invokeHandler(ReflectiveHandlerInvocation.java:23)
        at deployment.ioserver.ear//net.engio.mbassy.dispatch.ReflectiveHandlerInvocation.invoke(ReflectiveHandlerInvocation.java:49)
        at deployment.ioserver.ear//net.engio.mbassy.dispatch.MessageDispatcher.dispatch(MessageDispatcher.java:30)
        at deployment.ioserver.ear//net.engio.mbassy.subscription.Subscription.publish(Subscription.java:49)
        at deployment.ioserver.ear//net.engio.mbassy.bus.MessagePublication.execute(MessagePublication.java:43)
        at deployment.ioserver.ear//net.engio.mbassy.bus.MBassador.publish(MBassador.java:37)
        ... 150 more

Disabling batching makes the issue go away.
@rbygrave
Copy link
Member

Are you able to create a test case that reproduces the issue based on https://github.com/ebean-orm-examples/example-minimal ?

@rbygrave
Copy link
Member

On a transaction there is control over isFlushOnQuery(). For example, in BatchControl there is code that disables that for the execution of batch prepared statements (because they might have post processing registered).
https://github.com/ebean-orm/ebean/blob/master/ebean-core/src/main/java/io/ebeaninternal/server/persist/BatchControl.java#L227-L228

This issue seems very similar to this and makes me think that at: PersistRequestBean.controllerPost() line 933 it could be that it should similarly automatically disable "flushOnQuery" before firing any post processors there - in this case the Post Delete processing.

That is, this case looks like there is Post Delete processing registered, that processing executes a query, that execution of the query is then causing the batch to flush because flushOnQuery is enabled.

@rbygrave
Copy link
Member

Perhaps a fast way to test and confirm that would be to use transaction.setFlushOnQuery(false) BEFORE the actual delete.

@rbygrave
Copy link
Member

I have been unable to simulate / reproduce this issue. How difficult is it to create a reproducing test case?

@rbygrave
Copy link
Member

It is tempting to add what I think the fix for this (stop the flushOnQuery in the "BeanPersistAdapters Post Processors" - Post Delete, Post Update etc) even though we haven't got a failing test case that I can confirm against as such.

@tbee
Copy link
Contributor Author

tbee commented Mar 20, 2024

Today I'm on a different project today, I can come back to this tomorrow (CET)

@tbee
Copy link
Contributor Author

tbee commented Mar 21, 2024

We could of course create a snapshot version and test your assumption. Is probably easier than trying to create a test.

rbygrave added a commit that referenced this issue Mar 21, 2024
@rbygrave
For #3363 disable flushOnQuery before BeanPersistAdapter post-processors
6bf1c6a
@rbygrave rbygrave linked a pull request Mar 21, 2024 that will close this issue
For #3363 disable flushOnQuery before BeanPersistAdapter post-processors #3367
Merged
rbygrave added a commit that referenced this issue Mar 21, 2024
@rbygrave
For #3363 disable flushOnQuery before BeanPersistAdapter post-process…
582fec7 
…ors (#3367)
@tbee
Copy link
Contributor Author

tbee commented Mar 21, 2024

Okay. I just came in to take a peek. What branch is the 14.x.x release built from?

@rbygrave
Copy link
Member

rbygrave commented Mar 21, 2024 •
edited
Loading

I've released 14.0.2 (to maven central) with the change that disables flushOnQuery for the post processing of BeanPersisAdapters. See if you can try that version and see if the issue still reproduces.

Edit: So you can use that version from central rather than build from source if you like.

What branch is the 14.x.x release built from?

14.x is master branch, but note that for the -javax build we need to run the ./jakarta-to-javax.sh script (to do appropriate search n replace for the javax.persistence changes.

@rbygrave rbygrave reopened this Mar 21, 2024
@tbee
Copy link
Contributor Author

tbee commented Mar 21, 2024

Tested it. The tests that failed under 14.0.1 still do under 14.0.2, but with different errors. And thoses tests are green when batching is disabled. Need to dive deeper to figure out why.

@rbygrave
Copy link
Member

Post up the new stack trace when you can, that will help - cheers, Rob.

@tbee
Copy link
Contributor Author

tbee commented Mar 21, 2024 •
edited
Loading

Okay, so the original problem is gone, but it seems it is doing the same a bit further down the road; same delete statement being executed twice, second one with no rows modified.

Ah, flushBatchOnGetter (preGetterTrigger:342, PersistRequestBean (io.ebeaninternal.server.core))

checkRowCount:812, PersistRequestBean (io.ebeaninternal.server.core)
executeAndCheckRowCounts:167, BatchedPstmt (io.ebeaninternal.server.persist)
executeBatch:114, BatchedPstmt (io.ebeaninternal.server.persist)
executeAll:139, BatchedPstmtHolder (io.ebeaninternal.server.persist)
flush:115, BatchedPstmtHolder (io.ebeaninternal.server.persist)
flushPstmtHolder:216, BatchControl (io.ebeaninternal.server.persist)
executeNow:238, BatchControl (io.ebeaninternal.server.persist)
executeNow:93, BatchedBeanHolder (io.ebeaninternal.server.persist)
executeAll:328, BatchControl (io.ebeaninternal.server.persist)
flushInternal:305, BatchControl (io.ebeaninternal.server.persist)
flushBuffer:278, BatchControl (io.ebeaninternal.server.persist)
flushOnCommit:246, BatchControl (io.ebeaninternal.server.persist)
batchFlush:550, JdbcTransaction (io.ebeaninternal.server.transaction)
internalBatchFlush:665, JdbcTransaction (io.ebeaninternal.server.transaction)
flush:654, JdbcTransaction (io.ebeaninternal.server.transaction)
preGetterTrigger:342, PersistRequestBean (io.ebeaninternal.server.core)
preGetterCallback:820, InterceptReadWrite (io.ebean.bean)
preGetId:826, InterceptReadWrite (io.ebean.bean)
_ebean_get_id:5, Base (com.nedap.healthcare.administration.ebean)
getObjectId:70, Base (com.nedap.healthcare.administration.ebean)
getData:98, AuditTrail (com.nedap.healthcare.administration.audit)
getData:13, AuditTrail (com.nedap.healthcare.administration.audit)
toTO:16, TransferableHelper (com.nedap.aeos.util.transferable)
create:36, AuditServiceImpl (com.nedap.healthcare.administration.audit)
create:43, AuditServiceImpl (com.nedap.healthcare.administration.audit)
invoke:-1, GeneratedMethodAccessor194 (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:566, Method (java.lang.reflect)
processInvocation:52, ManagedReferenceMethodInterceptor (org.jboss.as.ee.component)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:43, ExecutionTimeInterceptor (org.jboss.as.ejb3.component.invocationmetrics)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:47, SBInvocationInterceptor (org.jboss.as.jpa.interceptor)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:45, ConcurrentContextInterceptor (org.jboss.as.ee.concurrent)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:40, InitialInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:53, ChainedInterceptor (org.jboss.invocation)
processInvocation:52, ComponentDispatcherInterceptor (org.jboss.as.ee.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:51, PooledInstanceInterceptor (org.jboss.as.ejb3.component.pool)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:56, AdditionalSetupInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
invokeInCallerTx:201, CMTTxInterceptor (org.jboss.as.ejb3.tx)
supports:448, CMTTxInterceptor (org.jboss.as.ejb3.tx)
processInvocation:164, CMTTxInterceptor (org.jboss.as.ejb3.tx)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:41, CurrentInvocationContextInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:47, WaitTimeInterceptor (org.jboss.as.ejb3.component.invocationmetrics)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:73, IdentityOutflowInterceptor (org.jboss.as.ejb3.security)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:44, SecurityDomainInterceptor (org.jboss.as.ejb3.security)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:22, StartupAwaitInterceptor (org.jboss.as.ejb3.deployment.processors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:64, ShutDownInterceptorFactory$1 (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:67, LoggingInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:50, NamespaceContextInterceptor (org.jboss.as.ee.component)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:60, ContextClassLoaderInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
run:438, InterceptorContext (org.jboss.invocation)
doChecked:633, WildFlySecurityManager (org.wildfly.security.manager)
processInvocation:57, AccessCheckingInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:53, ChainedInterceptor (org.jboss.invocation)
invoke:198, ViewService$View (org.jboss.as.ee.component)
processInvocation:191, ViewDescription$1 (org.jboss.as.ee.component)
invoke:81, ProxyInvocationHandler (org.jboss.as.ee.component)
create:-1, AuditService$$$view255 (com.nedap.healthcare.administration.audit)
saveAuditTrail:79, AuditUtil (com.nedap.healthcare.administration.audit)
process:22, AuditEventListener (com.nedap.healthcare.administration.audit)
invoke:-1, GeneratedMethodAccessor193 (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:566, Method (java.lang.reflect)
invokeHandler:23, ReflectiveHandlerInvocation (net.engio.mbassy.dispatch)
invoke:49, ReflectiveHandlerInvocation (net.engio.mbassy.dispatch)
dispatch:30, MessageDispatcher (net.engio.mbassy.dispatch)
publish:49, Subscription (net.engio.mbassy.subscription)
execute:43, MessagePublication (net.engio.mbassy.bus)
publish:37, MBassador (net.engio.mbassy.bus)
fire:43, EventBus (com.nedap.healthcare.administration.eventbus)
publish:96, AbstractAuditEvent (com.nedap.healthcare.administration.audit)
afterDelete:31, AuditEventController (com.nedap.healthcare.administration.audit.ebean)
postDelete:41, BeanPersistAdapter (com.nedap.healthcare.administration.ebean)
postDelete:103, ChainedBeanPersistController (io.ebeaninternal.server.deploy)
controllerPost:936, PersistRequestBean (io.ebeaninternal.server.core)
postExecute:874, PersistRequestBean (io.ebeaninternal.server.core)
checkRowCount:100, DmlHandler (io.ebeaninternal.server.persist.dml)
execute:51, DeleteHandler (io.ebeaninternal.server.persist.dml)
executeNoBatch:88, DmlHandler (io.ebeaninternal.server.persist.dml)
execute:69, DmlBeanPersister (io.ebeaninternal.server.persist.dml)
delete:38, DmlBeanPersister (io.ebeaninternal.server.persist.dml)
executeDelete:1244, PersistRequestBean (io.ebeaninternal.server.core)
executeNow:746, PersistRequestBean (io.ebeaninternal.server.core)
executeOrQueue:171, BatchControl (io.ebeaninternal.server.persist)
executeOrQueue:765, PersistRequestBean (io.ebeaninternal.server.core)
delete:925, DefaultPersister (io.ebeaninternal.server.persist)
deleteRequest:565, DefaultPersister (io.ebeaninternal.server.persist)
deleteRequest:547, DefaultPersister (io.ebeaninternal.server.persist)
delete:539, DefaultPersister (io.ebeaninternal.server.persist)
delete:1844, DefaultServer (io.ebeaninternal.server.core)
delete:1835, DefaultServer (io.ebeaninternal.server.core)
delete:481, DB (io.ebean)
lambda$delete$1:252, TestUtil (com.nedap.healthcare.administratie.util)
get:-1, 1956183096 (com.nedap.healthcare.administratie.util.TestUtil$$Lambda$2373)
runInTransaction:42, TransactionServiceImpl (com.nedap.aeos.ejbutil)
invoke:-1, GeneratedMethodAccessor183 (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:566, Method (java.lang.reflect)
processInvocation:52, ManagedReferenceMethodInterceptor (org.jboss.as.ee.component)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:43, ExecutionTimeInterceptor (org.jboss.as.ejb3.component.invocationmetrics)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:47, SBInvocationInterceptor (org.jboss.as.jpa.interceptor)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:45, ConcurrentContextInterceptor (org.jboss.as.ee.concurrent)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:40, InitialInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:53, ChainedInterceptor (org.jboss.invocation)
processInvocation:52, ComponentDispatcherInterceptor (org.jboss.as.ee.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:51, PooledInstanceInterceptor (org.jboss.as.ejb3.component.pool)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:56, AdditionalSetupInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
invokeInNoTx:232, CMTTxInterceptor (org.jboss.as.ejb3.tx)
supports:446, CMTTxInterceptor (org.jboss.as.ejb3.tx)
processInvocation:164, CMTTxInterceptor (org.jboss.as.ejb3.tx)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:41, CurrentInvocationContextInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:47, WaitTimeInterceptor (org.jboss.as.ejb3.component.invocationmetrics)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:73, IdentityOutflowInterceptor (org.jboss.as.ejb3.security)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:44, SecurityDomainInterceptor (org.jboss.as.ejb3.security)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:22, StartupAwaitInterceptor (org.jboss.as.ejb3.deployment.processors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:64, ShutDownInterceptorFactory$1 (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:67, LoggingInterceptor (org.jboss.as.ejb3.component.interceptors)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:50, NamespaceContextInterceptor (org.jboss.as.ee.component)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:60, ContextClassLoaderInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
run:438, InterceptorContext (org.jboss.invocation)
doChecked:633, WildFlySecurityManager (org.wildfly.security.manager)
processInvocation:57, AccessCheckingInterceptor (org.jboss.invocation)
proceed:422, InterceptorContext (org.jboss.invocation)
processInvocation:53, ChainedInterceptor (org.jboss.invocation)
invoke:198, ViewService$View (org.jboss.as.ee.component)
processInvocation:191, ViewDescription$1 (org.jboss.as.ee.component)
invoke:81, ProxyInvocationHandler (org.jboss.as.ee.component)
runInTransaction:-1, TransactionService$$$view586 (com.nedap.aeos.ejbutil)
delete:252, TestUtil (com.nedap.healthcare.administratie.util)
tearDown:34, ClusterRule (com.nedap.healthcare.administration.rules)
evaluate:47, EnvironmentSetupRule$1 (com.nedap.healthcare.administration)
evaluate:42, EnvironmentSetupRule$1 (com.nedap.healthcare.administration)
evaluate:42, EnvironmentSetupRule$1 (com.nedap.healthcare.administration)
evaluate:239, ExpectedException$ExpectedExceptionStatement (org.junit.rules)
evaluate:20, RunRules (org.junit.rules)
runLeaf:325, ParentRunner (org.junit.runners)
runChild:78, BlockJUnit4ClassRunner (org.junit.runners)
runChild:57, BlockJUnit4ClassRunner (org.junit.runners)
run:290, ParentRunner$3 (org.junit.runners)
schedule:71, ParentRunner$1 (org.junit.runners)
runChildren:288, ParentRunner (org.junit.runners)
access$000:58, ParentRunner (org.junit.runners)
evaluate:268, ParentRunner$2 (org.junit.runners)
run:363, ParentRunner (org.junit.runners)
run:28, NedapJunit4Runner (com.nedap.healthcare.administratie.util)
run:137, JUnitCore (org.junit.runner)
run:115, JUnitCore (org.junit.runner)
run:134, TestRunner$2 (net.sf.junite2.runner)
run:149, TestRunner (net.sf.junite2.runner)
runTests:257, JUnitEEServlet (net.sf.junite2.servlet)
doGet:225, JUnitEEServlet (net.sf.junite2.servlet)
service:503, HttpServlet (javax.servlet.http)
service:590, HttpServlet (javax.servlet.http)
handleRequest:74, ServletHandler (io.undertow.servlet.handlers)
handleRequest:62, ServletSecurityRoleHandler (io.undertow.servlet.handlers.security)
handleRequest:68, ServletChain$1 (io.undertow.servlet.handlers)
handleRequest:36, ServletDispatchingHandler (io.undertow.servlet.handlers)
lambda$handleRequest$1:68, ElytronRunAsHandler (org.wildfly.elytron.web.undertow.server)
call:-1, 1538320059 (org.wildfly.elytron.web.undertow.server.ElytronRunAsHandler$$Lambda$2360)
apply:-1, 824572207 (org.wildfly.security.auth.server.Scoped$$Lambda$2361)
apply:-1, 1199661423 (org.wildfly.security.auth.server.Scoped$$Lambda$2362)
runAsFunctionEx:103, FlexibleIdentityAssociation (org.wildfly.security.auth.server)
runAsFunctionEx:161, Scoped (org.wildfly.security.auth.server)
runAs:73, Scoped (org.wildfly.security.auth.server)
handleRequest:67, ElytronRunAsHandler (org.wildfly.elytron.web.undertow.server)
handleRequest:68, RedirectDirHandler (io.undertow.servlet.handlers)
handleRequest:117, SSLInformationAssociationHandler (io.undertow.servlet.handlers.security)
handleRequest:57, ServletAuthenticationCallHandler (io.undertow.servlet.handlers.security)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleRequest:46, AbstractConfidentialityHandler (io.undertow.security.handlers)
handleRequest:64, ServletConfidentialityConstraintHandler (io.undertow.servlet.handlers.security)
handleRequest:43, AbstractSecurityContextAssociationHandler (io.undertow.security.handlers)
handleRequest:38, CleanUpHandler (org.wildfly.elytron.web.undertow.server.servlet)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleRequest:61, JACCContextIdHandler (org.wildfly.extension.undertow.security.jacc)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleRequest:68, GlobalRequestControllerHandler (org.wildfly.extension.undertow.deployment)
handleRequest:52, SendErrorPageHandler (io.undertow.servlet.handlers)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleFirstRequest:275, ServletInitialHandler (io.undertow.servlet.handlers)
access$100:79, ServletInitialHandler (io.undertow.servlet.handlers)
call:134, ServletInitialHandler$2 (io.undertow.servlet.handlers)
call:131, ServletInitialHandler$2 (io.undertow.servlet.handlers)
call:48, ServletRequestContextThreadSetupAction$1 (io.undertow.servlet.core)
call:43, ContextClassLoaderSetupAction$1 (io.undertow.servlet.core)
lambda$create$0:1544, UndertowDeploymentInfoService$UndertowThreadSetupAction (org.wildfly.extension.undertow.deployment)
call:-1, 2098646692 (org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1337)
lambda$create$0:1544, UndertowDeploymentInfoService$UndertowThreadSetupAction (org.wildfly.extension.undertow.deployment)
call:-1, 2098646692 (org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1337)
lambda$create$0:1544, UndertowDeploymentInfoService$UndertowThreadSetupAction (org.wildfly.extension.undertow.deployment)
call:-1, 2098646692 (org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1337)
lambda$create$0:1544, UndertowDeploymentInfoService$UndertowThreadSetupAction (org.wildfly.extension.undertow.deployment)
call:-1, 2098646692 (org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1337)
dispatchRequest:255, ServletInitialHandler (io.undertow.servlet.handlers)
access$000:79, ServletInitialHandler (io.undertow.servlet.handlers)
handleRequest:100, ServletInitialHandler$1 (io.undertow.servlet.handlers)
executeRootHandler:387, Connectors (io.undertow.server)
run:852, HttpServerExchange$1 (io.undertow.server)
run:35, ContextClassLoaderSavingRunnable (org.jboss.threads)
safeRun:1990, EnhancedQueueExecutor (org.jboss.threads)
doRunTask:1486, EnhancedQueueExecutor$ThreadBody (org.jboss.threads)
run:1377, EnhancedQueueExecutor$ThreadBody (org.jboss.threads)
run:1282, XnioWorker$WorkerThreadFactory$1$1 (org.xnio)
run:829, Thread (java.lang)

Resulting exception:

Caused by: javax.persistence.OptimisticLockException: Data has changed. updated row count 0
        at deployment.ioserver.ear//io.ebeaninternal.server.core.PersistRequestBean.checkRowCount(PersistRequestBean.java:812)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedPstmt.executeAndCheckRowCounts(BatchedPstmt.java:167)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedPstmt.executeBatch(BatchedPstmt.java:114)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedPstmtHolder.executeAll(BatchedPstmtHolder.java:139)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedPstmtHolder.flush(BatchedPstmtHolder.java:115)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.flushPstmtHolder(BatchControl.java:216)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.executeNow(BatchControl.java:238)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchedBeanHolder.executeNow(BatchedBeanHolder.java:93)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.executeAll(BatchControl.java:328)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.flushInternal(BatchControl.java:305)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.flushBuffer(BatchControl.java:278)
        at deployment.ioserver.ear//io.ebeaninternal.server.persist.BatchControl.flushOnCommit(BatchControl.java:246)
        at deployment.ioserver.ear//io.ebeaninternal.server.transaction.JdbcTransaction.batchFlush(JdbcTransaction.java:550)
        at deployment.ioserver.ear//io.ebeaninternal.server.transaction.JdbcTransaction.internalBatchFlush(JdbcTransaction.java:665)
        at deployment.ioserver.ear//io.ebeaninternal.server.transaction.JdbcTransaction.flush(JdbcTransaction.java:654)
        at deployment.ioserver.ear//io.ebeaninternal.server.core.PersistRequestBean.preGetterTrigger(PersistRequestBean.java:342)
        at deployment.ioserver.ear//io.ebean.bean.InterceptReadWrite.preGetterCallback(InterceptReadWrite.java:820)
        at deployment.ioserver.ear//io.ebean.bean.InterceptReadWrite.preGetId(InterceptReadWrite.java:826)
        at deployment.ioserver.ear.ebean.jar//com.nedap.healthcare.administration.ebean.Base._ebean_get_id(Base.java:5)
        at deployment.ioserver.ear.ebean.jar//com.nedap.healthcare.administration.ebean.Base.getObjectId(Base.java:70)
        at deployment.ioserver.ear.audit.jar//com.nedap.healthcare.administration.audit.AuditTrail.getData(AuditTrail.java:98)
        at deployment.ioserver.ear.audit.jar//com.nedap.healthcare.administration.audit.AuditTrail.getData(AuditTrail.java:13)
        at deployment.ioserver.ear.util.jar//com.nedap.aeos.util.transferable.TransferableHelper.toTO(TransferableHelper.java:16)
        at deployment.ioserver.ear.audit.jar//com.nedap.healthcare.administration.audit.AuditServiceImpl.create(AuditServiceImpl.java:36)
        at deployment.ioserver.ear.audit.jar//com.nedap.healthcare.administration.audit.AuditServiceImpl.create(AuditServiceImpl.java:43)
        at jdk.internal.reflect.GeneratedMethodAccessor194.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.jboss.as.ee@26.1.3.Final//org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3@26.1.3.Final//org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.jpa@26.1.3.Final//org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ee@26.1.3.Final//org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
        at org.jboss.as.ee@26.1.3.Final//org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3@26.1.3.Final//org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3@26.1.3.Final//org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:56)
        at org.jboss.invocation@1.7.0.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3@26.1.3.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:201)
        ... 186 more

@tbee
Copy link
Contributor Author

tbee commented Mar 22, 2024

I was wondering; you are trying to fix this by not flushing the batch in certain scenarios, but isn't the actual problem that the batch contains statements that are already executed? Wouldn't the appropriate solution be to fix the batch itself?

@rbygrave
Copy link
Member

We need the failing test case that reproduces the issue.

actual problem that the batch contains statements that are already executed?

Maybe, I think once we see the failing test we'll get more of an idea.

@tbee
Copy link
Contributor Author

tbee commented Mar 26, 2024

I'll give it a try.

@tbee
Copy link
Contributor Author

tbee commented Mar 26, 2024 •
edited
Loading

Okay. So I've created a setup with two entities, one referring the other with two ManyToOnes. Then dropped the generated FKs (to match the setup in our datamodel), and created a bunch of entities. Then deleted one side. In its PostRemove queried the other side and replaced the deleted reference with one to an "unknown customer". That basically is what happens in our code, but the test works flawlessly.

In our environment we're running with a JtaTransaction manager, that may be of influence, but cannot be reproduced in the minimal example.

However, the stacktrace is pretty clear; it performs a batch flush on a pre-getter which executes a batched statement that was already executed, causing the row count check to fail. In my opinion the root of the problem is the fact that a statement that was already executed is still present in a batch.

Should a statement that was/is being executed not immediately be marked as such, so that a second flush (via whatever execution path) does not re-execute it?

@tbee tbee mentioned this issue Apr 8, 2024
Closed
@rbygrave
Copy link
Member

rbygrave commented Apr 8, 2024 •
edited
Loading

but cannot be reproduced in the minimal example.

Right, apologies because I read this and thought that you would continue to try and create a failing test case. Is that the case or have you stopping trying to reproduce it?

it performs a batch flush on a pre-getter which executes a batched statement that was already executed, causing the row count check to fail

Yes, but I think we are really trying to understand how that occurs. There is no "mark statement as executed" because this isn't supposed to happen at all.

What options have we got at the moment? Are we blocked on trying to reproduce this? Have you tried running the test with a JTATransactionManager / in a JEE container? Have you tried using a debugger with the JEE container to try and see how the statement is executed twice or what code path gets the statement executed the first time? (with a view of finding out why it isn't being reproduced)

@tbee
Copy link
Contributor Author

tbee commented Apr 9, 2024 •
edited
Loading

I was not pursuing reproducing the scenario ATM, because in my opinion there is a fundamental flaw, which is also the basis for 3185, being not marking statements in the batch as having executed. But what I can do is reproduce where the first delete is executed. That will give some insight in how this second execute can still occur. Because, if I remember correctly, that was outside of the batch.

@rbygrave
Copy link
Member

rbygrave commented Apr 9, 2024

Ok, once you publish that somewhere then I can have a look.

Just to clarify, we do not have a reproducing test case that runs in JBoss either then?

@tbee
Copy link
Contributor Author

tbee commented Apr 9, 2024

Let's start with both stacktraces and take it from there.

@tbee
Copy link
Contributor Author

tbee commented Apr 11, 2024

FYI: I'm trying to figure out when the first delete happens. It must be EBean related, because with batch mode off everything works fine. But so far I have not been able to find it, even with a breakpoint inside the JDBC driver and database logging enabled. I only see the batched delete, but the record is already gone by then. There is no cascading at the database level, from what I can tell. To be continued...

@rbygrave
Copy link
Member

Ok, given the updated stack trace it would good to see the code at the following:

lambda$delete$1:252, TestUtil (com.nedap.healthcare.administratie.util)
get:-1, 1438035345 (com.nedap.healthcare.administratie.util.TestUtil$$Lambda$2344)
runInTransaction:42, TransactionServiceImpl (com.nedap.aeos.ejbutil)

fire:43, EventBus (com.nedap.healthcare.administration.eventbus)
postRemove:577, Cluster (com.nedap.healthcare.administration.crm.cluster)

forClusterRemovedOnly:636, PresenceLogFinder (com.nedap.healthcare.administration.registration.presencelog)
process:29, ClusterChangedEventListener (com.nedap.healthcare.administration.registration.presencelog)

Are you able to provide that code?

@tbee
Copy link
Contributor Author

tbee commented Apr 12, 2024 •
edited
Loading

[insert explitive here] I figured it out; the database does delete the record. That is IMHO a no go when using an ORM, so I was totally not looking for that. We probably not only need to disable batching, but also any caches.

@tbee tbee closed this as completed Apr 12, 2024
@rbygrave
Copy link
Member

Well done!!

the database does delete the record

So I'm thinking that there is a DB trigger or a Foreign Key on delete cascade deleting a row that ebean was also looking to delete.

We probably not only need to disable batching

There should be no need to disable batching, that should be orthogonal to working with DB triggered deletes.

@tbee
Copy link
Contributor Author

tbee commented Apr 12, 2024

So I'm thinking that there is a DB trigger or a Foreign Key on delete cascade deleting a row that ebean was also looking to delete.

Yup.

There should be no need to disable batching, that should be orthogonal to working with DB triggered deletes.

What happens is that the delete of record A is batched, postDelete is executed, it finds record B (which will be deleted alongside of A) and batches the delete of B. Then the batch is flushed. With batching off, A is deleted immediately, so B is not found and thus not attempted to be deleted.

@rbygrave
Copy link
Member

A is batched, postDelete is executed

postDelete will not occur until after A is executed.

postDelete is executed, it finds record B

At that point the A delete has been executed.

@tbee
Copy link
Contributor Author

tbee commented Apr 12, 2024

Checked; the find indeed happens in de preRemove (not the postDelete) of A which will then -I assume- batch the delete B. Because somehow that statement ends up in the batch to be executed in the postDelete -> flushBatch.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

For #3363 disable flushOnQuery before BeanPersistAdapter post-processors ebean-orm/ebean
2 participants
@rbygrave @tbee