quarkusio / quarkus

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

Intermittent NullPointerException when use hibernate with context propagation #11295

Open ThomasSousa96 opened 4 years ago

ThomasSousa96 commented 4 years ago

Describe the bug Using hibernate and context propagation with ManagedExecutor occur an intermittent NullPointerException. I runs this code and sometimes it runs with success but other time it fail.

Expected behavior No throw NullPointerException

Actual behavior

java.util.concurrent.CompletionException: java.lang.NullPointerException
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
    at java.util.concurrent.CompletableFuture.biRelay(CompletableFuture.java:1300)
    at java.util.concurrent.CompletableFuture$BiRelay.tryFire(CompletableFuture.java:1284)
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488)
    at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975)
    at io.smallrye.context.CompletableFutureWrapper.lambda$new$0(CompletableFutureWrapper.java:34)
    at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:774)
    at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:750)
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488)
    at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1646)
    at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
    at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2046)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1578)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at java.lang.Thread.run(Thread.java:748)
    at org.jboss.threads.JBossThread.run(JBossThread.java:479)
Caused by: java.lang.NullPointerException
    at io.quarkus.hibernate.orm.runtime.customized.QuarkusConnectionProvider.closeConnection(QuarkusConnectionProvider.java:28)
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.releaseConnection(NonContextualJdbcConnectionAccess.java:49)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.releaseConnection(LogicalConnectionManagedImpl.java:201)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.afterStatement(LogicalConnectionManagedImpl.java:147)
    at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterStatementExecution(JdbcCoordinatorImpl.java:265)
    at org.hibernate.loader.Loader.doQuery(Loader.java:975)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:352)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:322)
    at org.hibernate.loader.Loader.loadEntity(Loader.java:2429)
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:74)
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:63)
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:47)
    at org.hibernate.loader.entity.PaddedBatchingEntityLoaderBuilder$PaddedBatchingEntityLoader.load(PaddedBatchingEntityLoaderBuilder.java:105)
    at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:4415)
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4405)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:569)
    at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:537)
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:208)
    at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:332)
    at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:108)
    at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:74)
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:113)
    at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1184)
    at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1173)
    at org.hibernate.internal.SessionImpl.access$2100(SessionImpl.java:194)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.doLoad(SessionImpl.java:2784)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.lambda$load$1(SessionImpl.java:2765)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.perform(SessionImpl.java:2721)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2765)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3320)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3282)
    at io.quarkus.hibernate.orm.runtime.entitymanager.TransactionScopedEntityManager.find(TransactionScopedEntityManager.java:142)
    at io.quarkus.hibernate.orm.runtime.entitymanager.ForwardingEntityManager.find(ForwardingEntityManager.java:42)
    ...(local class)...
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:252)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:34)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:53)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:26)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:339)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    ...(local class)...
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:252)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:34)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:53)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:26)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:339)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    ...(local class)...
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:252)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:34)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:53)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:26)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:339)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    ...(local class)...
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:252)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:34)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:53)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:26)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:339)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    ...(local class)...
    at io.smallrye.context.SmallRyeThreadContext$ContextualRunnable.run(SmallRyeThreadContext.java:56)
    at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1640)
    ... 8 more

To Reproduce Steps to reproduce the behavior:

  1. A common bean
@Transactional
@RequestScoped
public class Bar {

    @Inject
    EntityManager entityManager;

    public void doSomething() {
         //execute some query or find by id
    }

}
  1. A bean that delegate the work to some Bar beans
@Transactional
@RequestScoped
public class Foo {

    @Any
    @Inject
    Instance<Bar> bars;

    @Inject
    ManagedExecutor managedExecutor;

    public void bar() {
         //...
        CompletableFuture.allOf(bars.stream()
                .map(b -> managedExecutor.runAsync(() -> b.doSomething()))
                .toArray(CompletableFuture[]::new))
                .join();
         //...
    }

}
  1. A test class
@QuarkusTest
@TestMethodOrder(OrderAnnotation.class)
public class FooTest {

    @Inject
    Foo foo;

    @Test
    @Order(0)
    public void testFoo() {
        foo.bar();
    }
}

Configuration

# Add your application.properties here, if applicable.

Screenshots (If applicable, add screenshots to help explain your problem.)

Environment (please complete the following information):

Additional context (Add any other context about the problem here.)

quarkusbot commented 4 years ago

/cc @gsmet, @Sanne

Sanne commented 4 years ago

Hi, thanks for reporting! We probably need to improve the error detection, but I wouldn't say this to be a valid usage: you can't use an EntityManager in a different thread than the one which created it as it's a managed component, which in turn manages several resources (such as the connection in this case).

from checking the ORM code, it looks like that to trigger this specific NPE we'd need a concurrent invocation on org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl#releaseConnection - but I don't know what is triggering this. Since what I see is a race condition, that would explain why you see this intermittently.

Any suggestion @mkouba , @FroMage or @stuartwdouglas ? Could we do better, or at least detect and block using such a pattern?

Sanne commented 4 years ago

I've pushed this change to Hibernate ORM:

Wondering if Quarkus would be able to preven this in a better way.

famod commented 4 years ago

@Sanne I am actually a bit surprised that this usage scenario is not supported? I mean, the EM is not (directly) injected into the bean that is using the executor. TBH, given all the "laziness" that is usually happening during CDI injection, I also would have expected that this scenario should just work... What would be the "right" way to do it?

Sanne commented 4 years ago

I mean, the EM is not (directly) injected into the bean that is using the executor.

The problem I see in the code above is that the EntityManager is being created in one thread (the one requesting the injection) and then that one single EntityManager is passed to N threads to be used. The EntityManager is not threadsafe.

What would be the "right" way to do it?

I'm not familiar with context propagation (so perhaps there's a better way to do this) but the way I'd do this myself is to pass the EntityManagerFactory to other threads, and then explicitly open/close a new EntityManager within each "task" scope.

In particular when writing code which does explicit threading I'd tend to favour being all-in explicit with scope boundaries of the EntityManager lifecycle, its fllush and load cycles, and transaction boundaries. Alternatively, if simpicity is more important, refrain from explicit threading.

famod commented 4 years ago

Ok, I can see it now: All Bar instances are resolved outside of runAsync() and therefore each @RequestScoped Bar instance is associated to the "original" request/thread, but not to the respective ManagedExecutor thread(s).

So either each Bar instance would have to do the executor handling on its own or the lookup of each Bar instance has to be deferred to runAsync(). But let's see what the experts you've linked are saying...

Sanne commented 4 years ago

Exactly, @famod ; this is a violation of the ORM contracts. We could close the issue, but I'm not sure if "context propagation" is in some way suggesting that this should be doable.

And ideally I'd hope we could detect such cases and provide a better error message - I've included a small improvement in ORM but I don't think it's effective enough, as it will only trigger in rare conditions (and probably too late to prevent trouble).

FroMage commented 4 years ago

No, CP exists for the use-cases of propagating contexts that work on multiple threads provided that:

You can exclude contexts by creating your own ManagedExecutor and specifying that you want all contexts cleared if you intend to manage your own ORM context in parallel threads.

Sanne commented 4 years ago

No,

Could you clarify what you're saying "No" to @FroMage ? You don't agree we should close this issue?

FroMage commented 4 years ago

I was replying to your question "I'm not sure if "context propagation" is in some way suggesting that this should be doable."

No, it should not be doable, so yes you can close this, though it'd be nice to be able to detect this.

Sanne commented 4 years ago

Can you think of a way to detect and prevent such a mistake? This seems very important to me, but I'm not familiar at all with the context propagation design.

FroMage commented 4 years ago

I can't think of any way to detect and prevent this, precisely because it's alright to access a transaction from multiple threads, as long as it's not "at the same time", so with proper user synchronisation. So, if you start an endpoint as transactional you have the TX in your thread, from which you can totally spawn another thread which captures it and as long as the operations are not done in parallel, it will work, and we want it to work. If we were to try to detect that a transaction is used by two threads we'd break this valid usage, so the TX granularity is too coarse.

Given that it's the ORM operations that are problematic, we could try to detect that an operation is ongoing, either by synchronizing them or keeping track of ongoing calls, but that's some work, and it will be costly even for people who don't try this fancy kind of death trap.

We could look at which thread is currently invoking the ORM operation, like we do for preventing it on the IO thread, but it would only tell us that we're in a worker thread, and the ManagedExecutor delegates to the worker thread, so we still can't distinguish that this is a potentially parallel thread.

So, sorry, I have several ideas of what would not work, but no idea as to what could work.

Sanne commented 4 years ago

ok, thanks @FroMage - I appreciate the thoughts. To clarify, I don't think it's problematic for an Hibernate Session to be "passed on" to a different thread, but there is a problem with exclusivity, or lack of safe state handoff. In particular the bug reported here is only possible if there's parallel operations happening, or if the full memory state hasn't been fully published to the new thread.

From that I'd conclude:

For the record point 1 bothers me, as I'd expect most code to fall into this cathegory - especially end user's code.

cc/ @gavinking

yrodiere commented 1 year ago

the problem isn't limited to ORM but extends to any non-threadsafe component one would use in such pattern

I changed the labels of this issue to reflect this.