search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.82k stars 2.69k forks source link

Caught NoResultException silently causes Transaction to fail #23909

Open Aviss opened 2 years ago

Aviss commented 2 years ago

Describe the bug

A caught NoResultException within a transaction causes changes made during the transaction to not be persisted. Interestingly, no Exception is thrown, the transaction is not marked for rollback and even with hibernate logging set to TRACE there is no indication as to why this happens. The step running the insert query is simply missing.

Even weirder, inlining the function producing the NoResultException within the same class resolves the issue. I attached a reproducer project below but for completion: 

@Dependent
@Transactional(Transactional.TxType.REQUIRED)
public class ConfigurationRepository {

  @Inject protected EntityManager entityManager;
  [...]
  public String findValue(String key) {
    return entityManager.createQuery([...]).getSingleResult().getValue();
  }

  public Optional<String> findOptionalValue(String key) {
    try {
      String value = findValue(key);
      return Optional.of(value);
    } catch (NoResultException e) {
      return Optional.empty();
    }
  }
}

produces the behaviour, while

@Dependent
@Transactional(Transactional.TxType.REQUIRED)
public class ConfigurationRepository {

  @Inject protected EntityManager entityManager;
  [...]
  public Optional<String> findOptionalValue(String key) {
    try {
      String value = entityManager.createQuery([...]).getSingleResult().getValue();
      return Optional.of(value);
    } catch (NoResultException e) {
      return Optional.empty();
    }
  }
}

does not, when findOptionalValue is called from another method/class annotated @Transactional

If I need to take this bug up with hibernate instead, feel free to refer me with the necessary version information.

Expected behavior

Catching a NoResultException does not change the outcome of a transaction in any way. A transaction ending in a unexpected way should produce an exception or a warning.

Actual behavior

The Entity created during the Transaction is not persisted, no error is thrown, no warning is produced.

How to Reproduce?

Reproducer: quarkus-reproducible.zip

Steps to reproduce:

  1. Run mvnw clean install -DskipTests quarkus:dev
  2. Open localhost:8080/q/swagger-ui
  3. Execute POST /some-entity
  4. Verify that the Entity was not persisted with GET /some-entity

Or:

  1. Run mvnw clean install -DskipTests=true
  2. Execute SomeEndpointIT.testCreate()

Output of uname -a or ver

No response

Output of java -version

openjdk version "11.0.2" 2019-01-15 OpenJDK Runtime Environment 18.9 (build 11.0.2+9) OpenJDK 64-Bit Server VM 18.9 (build 11.0.2+9, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.6.2-Final

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.8.1 (05c21c65bdfed0f71a2f2ada8b84da59348c4c5d) Maven home: C:\Users___.m2\wrapper\dists\apache-maven-3.8.1-bin\2l5mhf2pq2clrde7f7qp1rdt5m\apache-maven-3.8.1 Java version: 11.0.2, vendor: Oracle Corporation, runtime: D:\Build\Java\jdk-11.0.2 Default locale: de_DE, platform encoding: Cp1252 OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Additional information

Here are the relevant Serverlogs for calling the function as outlined above: 

TRACE [org.hib.int.SessionFactoryImpl$SessionBuilderImpl] (executor-thread-0) Opening Hibernate Session.  tenant=null
DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) `hibernate.connection.provider_disables_autocommit` was enabled.  This setting should only be enabled when you are certain that the Connections given to Hibernate by the ConnectionProvider have auto-commit disabled.  Enabling this setting when the Connections do not have auto-commit disabled will lead to Hibernate executing SQL operations outside of any JDBC/SQL transaction.
DEBUG [org.hib.res.tra.bac.jta.int.JtaTransactionCoordinatorImpl] (executor-thread-0) Hibernate RegisteredSynchronization successfully registered with JTA platform
TRACE [org.hib.int.SessionImpl] (executor-thread-0) Opened Session [9dd5d0f8-d5f6-492c-8260-d8db9a20da92] at timestamp: 1645542566040
TRACE [org.hib.eng.que.spi.QueryPlanCache] (executor-thread-0) Located HQL query plan in cache (SELECT e from ConfigurationParameter e where e.key = :key)
TRACE [org.hib.eng.que.spi.HQLQueryPlan] (executor-thread-0) Find: SELECT e from ConfigurationParameter e where e.key = :key
TRACE [org.hib.eng.spi.QueryParameters] (executor-thread-0) Named parameters: {key=some.key.label}
DEBUG [org.hib.SQL] (executor-thread-0) select configurat0_.id as id1_0_, configurat0_.key as key2_0_, configurat0_.value as value3_0_ from ConfigurationParameter configurat0_ where configurat0_.key=?
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Registering statement [wrapped[ prep13: select configurat0_.id as id1_0_, configurat0_.key as key2_0_, configurat0_.value as value3_0_ from ConfigurationParameter configurat0_ where configurat0_.key=? ]]
TRACE [org.hib.eng.jdb.int.JdbcCoordinatorImpl] (executor-thread-0) Registering last query statement [wrapped[ prep13: select configurat0_.id as id1_0_, configurat0_.key as key2_0_, configurat0_.value as value3_0_ from ConfigurationParameter configurat0_ where configurat0_.key=? ]]
TRACE [org.hib.typ.des.sql.BasicBinder] (executor-thread-0) binding parameter [1] as [VARCHAR] - [some.key.label]
TRACE [org.hib.loa.Loader] (executor-thread-0) Bound [2] parameters total
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Registering result set [io.agroal.pool.wrapper.ResultSetWrapper@1e1214d4]
TRACE [org.hib.loa.Loader] (executor-thread-0) Processing result set
TRACE [org.hib.loa.Loader] (executor-thread-0) Done processing result set (0 rows)
TRACE [org.hib.loa.Loader] (executor-thread-0) Total objects hydrated: 0
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Releasing statement [wrapped[ prep13: select configurat0_.id as id1_0_, configurat0_.key as key2_0_, configurat0_.value as value3_0_ from ConfigurationParameter configurat0_ where configurat0_.key=? {1: 'some.key.label'} ]]
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Closing result set [io.agroal.pool.wrapper.ResultSetWrapper@1e1214d4]
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Closing prepared statement [wrapped[ prep13: select configurat0_.id as id1_0_, configurat0_.key as key2_0_, configurat0_.value as value3_0_ from ConfigurationParameter configurat0_ where configurat0_.key=? {1: 'some.key.label'} ]]
TRACE [org.hib.eng.jdb.int.JdbcCoordinatorImpl] (executor-thread-0) Starting after statement execution processing [BEFORE_TRANSACTION_COMPLETION]
TRACE [org.hib.eng.int.StatefulPersistenceContext] (executor-thread-0) Initializing non-lazy collections
TRACE [org.hib.eve.int.EntityState] (executor-thread-0) Transient instance of: reproducable.persistence.SomeEntity
TRACE [org.hib.eve.int.DefaultPersistEventListener] (executor-thread-0) Saving transient instance
DEBUG [org.hib.SQL] (executor-thread-0) call next value for some_entity_id_seq
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Registering statement [wrapped[ prep14: call next value for some_entity_id_seq ]]
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Registering result set [io.agroal.pool.wrapper.ResultSetWrapper@3763aeb]
DEBUG [org.hib.id.enh.SequenceStructure] (executor-thread-0) Sequence value obtained: 2
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Releasing result set [io.agroal.pool.wrapper.ResultSetWrapper@3763aeb]
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Closing result set [io.agroal.pool.wrapper.ResultSetWrapper@3763aeb]
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Releasing statement [wrapped[ prep14: call next value for some_entity_id_seq ]]
DEBUG [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) HHH000387: ResultSet's statement was not registered
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Closing prepared statement [wrapped[ prep14: call next value for some_entity_id_seq ]]
TRACE [org.hib.eng.jdb.int.JdbcCoordinatorImpl] (executor-thread-0) Starting after statement execution processing [BEFORE_TRANSACTION_COMPLETION]
DEBUG [org.hib.eve.int.AbstractSaveEventListener] (executor-thread-0) Generated identifier: 2, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator
TRACE [org.hib.eve.int.AbstractSaveEventListener] (executor-thread-0) Saving [reproducable.persistence.SomeEntity#2]
TRACE [org.hib.eng.spi.ActionQueue] (executor-thread-0) Adding an EntityInsertAction for [reproducable.persistence.SomeEntity] object
TRACE [org.hib.eng.spi.ActionQueue] (executor-thread-0) Adding insert with no non-nullable, transient entities: [EntityInsertAction[reproducable.persistence.SomeEntity#2]]
TRACE [org.hib.eng.spi.ActionQueue] (executor-thread-0) Adding resolved non-early insert action.
TRACE [org.hib.res.tra.bac.jta.int.syn.RegisteredSynchronization] (executor-thread-0) Registered JTA Synchronization : afterCompletion(4)
TRACE [org.hib.res.tra.bac.jta.int.syn.SynchronizationCallbackCoordinatorTrackingImpl] (executor-thread-0) Synchronization coordinator: afterCompletion(status=4)
TRACE [org.hib.res.tra.bac.jta.int.syn.SynchronizationCallbackCoordinatorNonTrackingImpl] (executor-thread-0) Synchronization coordinator: doAfterCompletion(successful=false, delayed=false)
TRACE [org.hib.res.tra.int.SynchronizationRegistryStandardImpl] (executor-thread-0) SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(5)
TRACE [org.hib.res.jdb.int.AbstractLogicalConnectionImplementor] (executor-thread-0) LogicalConnection#afterTransaction
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Releasing JDBC resources
DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) Initiating JDBC connection release from afterTransaction
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Releasing JDBC resources
TRACE [org.hib.int.SessionImpl] (executor-thread-0) SessionImpl#afterTransactionCompletion(successful=false, delayed=false)
DEBUG [org.hib.eng.tra.int.TransactionImpl] (executor-thread-0) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
TRACE [org.hib.int.SessionImpl] (executor-thread-0) Automatically closing session
TRACE [org.hib.int.SessionImpl] (executor-thread-0) Closing session [9dd5d0f8-d5f6-492c-8260-d8db9a20da92]
TRACE [org.hib.eng.jdb.int.JdbcCoordinatorImpl] (executor-thread-0) Closing JDBC container [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl@dcc2ae5]
TRACE [org.hib.res.jdb.int.ResourceRegistryStandardImpl] (executor-thread-0) Releasing JDBC resources
TRACE [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) Closing logical connection
TRACE [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) Logical connection closed
atastrumf commented 2 years ago

Came across the same issue on my side, while figuring out why entities are not persisted when there was no logical error with my code... @Aviss I'm extremly grateful that you wrote this bug report, as it's quite hard to figure out what's wrong when you expect the container to behave correctly!

quarkus-bot[bot] commented 2 years ago

/cc @Sanne, @gsmet

yrodiere commented 1 year ago

I remember seeing another issue about this behavior (which, I agree, is very strange). IIRC the conclusion was that, as per the spec, a transaction must be rolled back as soon as any method annotated with @Transactional throws an exception. Here your method findOptionalValue is annotated with @Transactional (at the class level), so as soon as it throws an exception, the ongoing transaction is rolled back.

Of course I agree it would make more sense for the transaction to be rolled back when the method whose transaction interceptor started the transaction throws an exception, ignoring all "internal" caught exceptions. But if the spec says otherwise, who am I to contradict it...

I'll try to find the other issue and the part of the spec that mandates this nonsensical behavior.

yrodiere commented 1 year ago

I couldn't find the other issue I was talking about, but I had a look at the spec. While it's not extra clear, there are places where it seems to imply that the @Transactional interceptor should only roll back transactions it created itself, such as here (emphasis mine):

For example if a transaction is begun as a result of a call to a bean annotated with Transactional(TxType.REQUIRES) and this bean in turn calls a second bean annotated with Transactional(TxType.NEVER), the transaction begun by the first bean will be marked for rollback

So... I would say the current behavior of the @Transactional interceptor in Quarkus, where it seems to roll back transactions it did not even start, seems incorrect.

I.e. I would argue that here, handleException should not lead to a rollback:

https://github.com/quarkusio/quarkus/blob/c3b9b36cf8c0ff151d44f26d2ef1748e0d4f051f/extensions/narayana-jta/runtime/src/main/java/io/quarkus/narayana/jta/runtime/interceptor/TransactionalInterceptorBase.java#L300-L308

@gsmet @stuartwdouglas @Sanne do you agree? Can I start working on a fix (and tests)?

stuartwdouglas commented 1 year ago

I know this is not the same spec, but the original @TransactionAttribute from the EJB spec would roll back the callers transaction: https://jakarta.ee/specifications/enterprise-beans/4.0/jakarta-enterprise-beans-spec-core-4.0.html#a3008 table 7 row 1.

I would argue that the Jakarta Transaction spec also expects the same behavior, in 3.7 it talks about how the Transaction interceptor handles exceptions and when it rolls back, but this is not qualified in any way, i.e. the behavior should be the same no matter the transaction attribute or who started the transaction.

Note that this largely mirrors the behavior of the EJB spec that this was based on, so I don't think this is an oversight.

The passage @yrodiere quoted is not really relevant, the call never enters the business method of the NEVER bean, it is just saying that if you do cause the TX interceptor of an inner bean to throw an exception then the TX will be rolled back as normal.

Note that I am not arguing that this behavior is user friendly, I remember hating this semantic as an end user over a decade ago, but it is what the spec expects.

stuartwdouglas commented 1 year ago

Actually the big difference here compared to the EJB spec is that we are doing self-interception, while EJBs did not.

This makes things even more confusing. If you make findValue private it would also fix the issue.

@mkouba just FYI self-interception + the transaction interceptor can produce some very unexpected results.

yrodiere commented 1 year ago

The passage @yrodiere quoted is not really relevant, the call never enters the business method of the NEVER bean, it is just saying that if you do cause the TX interceptor of an inner bean to throw an exception then the TX will be rolled back as normal.

I'm aware of that, but as you said the spec does not say which transactions should be rolled back and which should not, while this passage seems to go out of its way to mention the transaction being rolled back is the one that was started by the same interceptor. That's really the only hint I could find in the Transaction spec, as thin as it is.

Note that I am not arguing that this behavior is user friendly, I remember hating this semantic as an end user over a decade ago

I suspect a lot of people will share that feeling. I can't think of a scenario where I would want that behavior. It basically forces you to fiddle with @Transactional.rollbackOn/@Transactional.dontRollbackOn everytime your clients can possibly catch a runtime exception, effectively forcing you to work as if using checked exceptions. Dreadful.

Taking into account self-interception, which worsens the issue... maybe deviating from the spec might make sense here? Or rather, deviating from what the spec doesn't say explicitly :)

mkouba commented 1 year ago

@mkouba just FYI self-interception + the transaction interceptor can produce some very unexpected results.

ACK.

Note that self-interception/self-invocation is something completely undefined in CDI.

atastrumf commented 1 year ago

Hi, not sure if this is relevant for discussion about what specs say, but javax.persistence.PersistenceException clearly states which subclasses should not cause rollback. https://docs.oracle.com/javaee/7/api/javax/persistence/PersistenceException.html In case an interceptor is handling the thrown exceptions, I think it's also it's obligation to follow the linked documentation. I just don't see how CDI/EJB specs could/should change the documentated behaviour, unless they explicity state so.

yrodiere commented 1 year ago

@atastrumf I think that specific bit of specification describes whether the JPA implementor (here, Hibernate ORM) triggers a rollback when it throws an exception. Code catching that exception later (like the transaction interceptor) is not bound by that spec. So I don't think this is relevant.

That said, I still think the current behavior is impractical at best and should change. I don't seem to be in the majority, though, so... :shrug: