Concurrent modification should not be logged as ERROR?

Question

We have an application running on a Wildfly 17. I have a scenario, which occurs occasionally, in which two background threads are accessing the same entity:

Thread A deletes the entity (for good reason)
Thread B is working on slightly older data and attempts to update the entity

When thread B is the later of the two, it fails due to the concurrent modification. This works correctly. It is retried automatically and finds that nothing needs to be done anymore (because the entity has been deleted). That is the intended behavior, when these two threads collide. All is fine!

However I find that this is logged as ERROR by CMTTxInterceptor:

2020-03-31 16:51:35,463 +0200 ERROR: as.ejb3.invocation - WFLYEJB0034: EJB Invocation failed on component ... for method ... throws ...: 
  javax.ejb.EJBTransactionRolledbackException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:203) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final]
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:364) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final]
    at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:144) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final]
    at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
...
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_171]
    at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)
Caused by: javax.persistence.OptimisticLockException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.wrapStaleStateException(AbstractEntityManagerImpl.java:1729) [hibernate-entitymanager.jar:5.0.12.Final]
... at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:185) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final]
    ... 262 more
Caused by: org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
    at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:67) [hibernate-core.jar:5.0.12.Final]
    at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:54) [hibernate-core.jar:5.0.12.Final]
    at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:46) [hibernate-core.jar:5.0.12.Final]
    at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:3261) [hibernate-core.jar:5.0.12.Final]
...

It seems to me, that this log is incorrect, mostly because this is not an ERROR. Concurrent modification is something normal, that is to be expected - and that our application logic handles. This log will distract my colleagues at the hotline.

Do you agree that the logging is incorrect, or am I missing something?

I think I will disable logging for "as.ejb3.invocation".

score 0 · Answer 1 · answered May 29 '20 at 19:17

0

In your case this exception was thrown because Hibernate detected that the entity previously fetched from database was changed (deleted) during the current transaction. So, there is nothing to update.

In this specific case I think you can ignore or swallow the exception. In other cases, it may be good to know about this exception, so I recommend swallow the exception but don’t disable as a whole on log level.

answered May 29 '20 at 19:17

Petr Freiberg

567
4
14

I'm afraid this does not help. The question was whether the logging is incorrect: No error occurred in this scenario, so I believe, it should not be logged as ERROR. – Darkwyng Jun 08 '20 at 05:02
In my opinion, it is not wrong that the log level is ERROR. – Petr Freiberg Jun 10 '20 at 08:07

Concurrent modification should not be logged as ERROR?

1 Answers1