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.

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

Intermittent NullPointerException when use hibernate with context propagation #11295

Closed
ThomasSousa96 opened this issue Aug 9, 2020 · 15 comments
Labels
area/context-propagation area/reactive kind/bug Something isn't working triage/out-of-date This issue/PR is no longer valid or relevant

Comments

@ThomasSousa96
Copy link

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):

  • Output of uname -a or ver: Linux 5.4.0-42-generic Add proper logging #46-Ubuntu SMP Fri Jul 10 00:24:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
  • Output of java -version: Java 8
  • GraalVM version (if different from Java):
  • Quarkus version or git rev: 1.6.1
  • Build tool (ie. output of mvnw --version or gradlew --version): 3.6.3

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

@ThomasSousa96 ThomasSousa96 added the kind/bug Something isn't working label Aug 9, 2020
@quarkusbot
Copy link

/cc @gsmet, @Sanne

@quarkusbot quarkusbot added area/hibernate-orm Hibernate ORM area/persistence OBSOLETE, DO NOT USE labels Aug 9, 2020
@Sanne
Copy link
Member

Sanne commented Aug 10, 2020

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
Copy link
Member

Sanne commented Aug 10, 2020

I've pushed this change to Hibernate ORM:

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

@famod
Copy link
Member

famod commented Aug 10, 2020

@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
Copy link
Member

Sanne commented Aug 10, 2020

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
Copy link
Member

famod commented Aug 10, 2020

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
Copy link
Member

Sanne commented Aug 10, 2020

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
Copy link
Member

FroMage commented Aug 13, 2020

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

  • Either the context is accessed concurrently but not in parallel (reactive use-case)
  • Or the context is thread-safe and can be accessed in parallel (runAsync for example)

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
Copy link
Member

Sanne commented Oct 4, 2020

No,

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

@FroMage
Copy link
Member

FroMage commented Oct 19, 2020

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
Copy link
Member

Sanne commented Oct 20, 2020

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
Copy link
Member

FroMage commented Oct 28, 2020

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
Copy link
Member

Sanne commented Oct 28, 2020

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:

  • the problem isn't limited to ORM but extends to any non-threadsafe component one would use in such pattern
  • if there's a lack of barriers between these asynch operations, that's something we might be able to fix

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 yrodiere added area/context-propagation and removed area/persistence OBSOLETE, DO NOT USE area/hibernate-orm Hibernate ORM labels Feb 21, 2023
@yrodiere
Copy link
Member

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.

@cescoffier
Copy link
Member

I was unable to reproduce it anymore.
I used the following reproducer: test-quarkus-11295.zip

Closing this issue - please re-open if it's still relevant (with an updated reproducer)

@cescoffier cescoffier closed this as not planned Won't fix, can't repro, duplicate, stale Jan 6, 2025
@cescoffier cescoffier added the triage/out-of-date This issue/PR is no longer valid or relevant label Jan 6, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/context-propagation area/reactive kind/bug Something isn't working triage/out-of-date This issue/PR is no longer valid or relevant
Projects
None yet
Development

No branches or pull requests

7 participants