"SQLException: Not using JDBC" when trying to obtain lock for entity created in same transaction

[markusdlugi]

When trying to obtain a pessimistic lock for an entity that was created within the same transaction that is used to obtain the lock, Hibernate Reactive fails with the following exception:

2022-04-07 11:39:09,398 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (vert.x-eventloop-thread-2) Request failed: org.hibernate.dialect.lock.PessimisticEntityLockException: could not obtain pessimistic lock
	at org.hibernate.dialect.lock.PessimisticWriteSelectLockingStrategy.lock(PessimisticWriteSelectLockingStrategy.java:102)
	at org.hibernate.persister.entity.AbstractEntityPersister.lock(AbstractEntityPersister.java:1996)
	at org.hibernate.event.internal.AbstractLockUpgradeEventListener.upgradeLock(AbstractLockUpgradeEventListener.java:82)
	at org.hibernate.loader.entity.CacheEntityLoaderHelper.loadFromSessionCache(CacheEntityLoaderHelper.java:111)
	at org.hibernate.reactive.event.impl.DefaultReactiveLoadEventListener.doLoad(DefaultReactiveLoadEventListener.java:597)
	at org.hibernate.reactive.event.impl.DefaultReactiveLoadEventListener.load(DefaultReactiveLoadEventListener.java:289)
	at org.hibernate.reactive.event.impl.DefaultReactiveLoadEventListener.lockAndLoad(DefaultReactiveLoadEventListener.java:550)
	at org.hibernate.reactive.event.impl.DefaultReactiveLoadEventListener.doOnLoad(DefaultReactiveLoadEventListener.java:213)
	at org.hibernate.reactive.event.impl.DefaultReactiveLoadEventListener.lambda$reactiveOnLoad$1(DefaultReactiveLoadEventListener.java:140)
	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1106)
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2235)
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:143)
	at org.hibernate.reactive.event.impl.DefaultReactiveLoadEventListener.reactiveOnLoad(DefaultReactiveLoadEventListener.java:139)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.lambda$fireEventOnEachListener$1(EventListenerGroupImpl.java:148)
	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1106)
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2235)
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:143)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:148)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.fireLoadNoChecks(ReactiveSessionImpl.java:1084)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.fireLoad(ReactiveSessionImpl.java:1077)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl$ReactiveIdentifierLoadAccessImpl.doLoad(ReactiveSessionImpl.java:1227)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl$ReactiveIdentifierLoadAccessImpl.lambda$load$5(ReactiveSessionImpl.java:1213)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl$ReactiveIdentifierLoadAccessImpl.perform(ReactiveSessionImpl.java:1180)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl$ReactiveIdentifierLoadAccessImpl.load(ReactiveSessionImpl.java:1213)
	at org.hibernate.reactive.session.impl.ReactiveSessionImpl.reactiveFind(ReactiveSessionImpl.java:1020)
	at org.hibernate.reactive.mutiny.impl.MutinySessionImpl.lambda$find$6(MutinySessionImpl.java:124)
	at io.smallrye.context.impl.wrappers.SlowContextualSupplier.get(SlowContextualSupplier.java:21)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage.subscribe(UniCreateFromCompletionStage.java:24)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.lambda$subscribe$0(UniRunSubscribeOn.java:27)
	at org.hibernate.reactive.context.impl.VertxContext.execute(VertxContext.java:78)
	at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.subscribe(UniRunSubscribeOn.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.performInnerSubscription(UniOnItemTransformToUni.java:81)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.onItem(UniOnItemTransformToUni.java:57)
	at io.smallrye.mutiny.operators.uni.UniOperatorProcessor.onItem(UniOperatorProcessor.java:46)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forwardResult(UniCreateFromCompletionStage.java:63)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251)
	at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:143)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forward(UniCreateFromCompletionStage.java:51)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage.subscribe(UniCreateFromCompletionStage.java:35)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.lambda$subscribe$0(UniRunSubscribeOn.java:27)
	at org.hibernate.reactive.context.impl.VertxContext.execute(VertxContext.java:78)
	at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.subscribe(UniRunSubscribeOn.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni.subscribe(UniOnItemTransformToUni.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.performInnerSubscription(UniOnItemTransformToUni.java:81)
	at io.smallrye.mutiny.operators.uni.UniOnItemTransformToUni$UniOnItemTransformToUniProcessor.onItem(UniOnItemTransformToUni.java:57)
	at io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forwardResult(UniCreateFromCompletionStage.java:63)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)
	at io.vertx.core.Future.lambda$toCompletionStage$2(Future.java:360)
	at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
	at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:60)
	at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:211)
	at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23)
	at io.vertx.core.impl.future.PromiseImpl.onSuccess(PromiseImpl.java:49)
	at io.vertx.core.impl.future.PromiseImpl.handle(PromiseImpl.java:41)
	at io.vertx.sqlclient.impl.TransactionImpl.lambda$wrap$0(TransactionImpl.java:72)
	at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
	at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54)
	at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:81)
	at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:173)
	at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:51)
	at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:211)
	at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23)
	at io.vertx.core.impl.future.PromiseImpl.onSuccess(PromiseImpl.java:49)
	at io.vertx.core.impl.future.PromiseImpl.handle(PromiseImpl.java:41)
	at io.vertx.core.impl.future.PromiseImpl.handle(PromiseImpl.java:23)
	at io.vertx.pgclient.impl.PgSocketConnection.lambda$doSchedule$2(PgSocketConnection.java:160)
	at io.vertx.sqlclient.impl.command.CommandResponse.fire(CommandResponse.java:46)
	at io.vertx.sqlclient.impl.SocketConnectionBase.handleMessage(SocketConnectionBase.java:287)
	at io.vertx.pgclient.impl.PgSocketConnection.handleMessage(PgSocketConnection.java:96)
	at io.vertx.sqlclient.impl.SocketConnectionBase.lambda$init$0(SocketConnectionBase.java:99)
	at io.vertx.core.impl.EventLoopContext.emit(EventLoopContext.java:50)
	at io.vertx.core.impl.ContextImpl.emit(ContextImpl.java:274)
	at io.vertx.core.impl.EventLoopContext.emit(EventLoopContext.java:22)
	at io.vertx.core.net.impl.NetSocketImpl.handleMessage(NetSocketImpl.java:394)
	at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:156)
	at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:153)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
	at io.vertx.pgclient.impl.codec.PgEncoder.lambda$write$0(PgEncoder.java:87)
	at io.vertx.pgclient.impl.codec.PgCommandCodec.handleReadyForQuery(PgCommandCodec.java:139)
	at io.vertx.pgclient.impl.codec.PgDecoder.decodeReadyForQuery(PgDecoder.java:237)
	at io.vertx.pgclient.impl.codec.PgDecoder.channelRead(PgDecoder.java:96)
	at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:111)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138)
	at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)
	at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.doPrepare(StatementPreparerImpl.java:90)
	at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
	at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareStatement(StatementPreparerImpl.java:75)
	at org.hibernate.dialect.lock.PessimisticWriteSelectLockingStrategy.lock(PessimisticWriteSelectLockingStrategy.java:62)
	... 112 more
Caused by: java.sql.SQLException: Not using JDBC
	at org.hibernate.reactive.provider.service.NoJdbcConnectionProvider.getConnection(NoJdbcConnectionProvider.java:25)
	at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108)
	... 118 more

Of course, locking an entity while it only exists in the local transaction isn't really necessary. But it would still be nice if Hibernate Reactive supported this use case. For example, we sometimes want to update an entity and don't want to distinguish whether the entity was just created earlier in the transaction or whether it already existed. So in the current situation we would have to distinguish which use case is executed and either access the entity with lock or without lock. If not for this bug, we could just reuse the update code for multiple use cases and have the exact same behavior.

Reproducer: https://github.com/markusdlugi/hibernate-locking

Steps to reproduce:

1. Start the attached MyEntityResourceTest.
2. Observe that creating an entity and then updating it with lock leads to the aforementioned exception, while updating it without lock works.

Tested with Quarkus 2.7.5.Final and Hibernate Reactive 1.1.3.Final.

[DavideD]

I think there is a bug somewhere. We should at least throw a better error message.
That said, I think I have a workaround for the time being.
It should work if you change the methods in MyEntityResource to

	@POST
	@Path("/withlock/{name}")
	public Uni<MyEntity> createEntityWithLock(final String name) {
		final MyEntity myEntity = new MyEntity( name );
		return sessionFactory
				.withTransaction( session -> session
						.persist( myEntity )
						.call( session::flush )
						.call( () -> session.lock( myEntity, LockMode.PESSIMISTIC_WRITE ) )
						.chain( () -> this.updateEntity( name ) )
				);
	}

	@POST
	@Path("/withoutlock/{name}")
	public Uni<MyEntity> createEntityWithoutLock(final String name) {
		return sessionFactory
				.withTransaction( session -> session
						.persist( new MyEntity( name ) )
						.onItem().ignore()
						.andSwitchTo( () -> this.updateEntity( name ) )
				);
	}

	private Uni<MyEntity> updateEntity(final String name) {
		return sessionFactory
				.withTransaction( session -> session.find( MyEntity.class, name ) )
				.map( entity -> entity.setLastUpdated( Instant.now() ) );
	}

[blafond]

Pushed a HR reproducer to my repo.

testLockBeforeUpdate() does a session.lock() before the udpate and the update works.

testLockDuringUpdate does the lock during update via the session.find(.....LockMode.PESSIMISTIC_WRITE) and it fails with

ERROR SqlExceptionHelper [vert.x-eventloop-thread-0] Not using JDBC

could not obtain pessimistic lock
org.hibernate.dialect.lock.PessimisticEntityLockException: could not obtain pessimistic lock
	at app//org.hibernate.dialect.lock.PessimisticWriteSelectLockingStrategy.lock(PessimisticWriteSelectLockingStrategy.java:102)
	at app//org.hibernate.persister.entity.AbstractEntityPersister.lock(AbstractEntityPersister.java:1996)
	at app//org.hibernate.event.internal.AbstractLockUpgradeEventListener.upgradeLock(AbstractLockUpgradeEventListener.java:82)
	at app//org.hibernate.loader.entity.CacheEntityLoaderHelper.loadFromSessionCache(CacheEntityLoaderHelper.java:111)
	at app//org.hibernate.reactive.event.impl.DefaultReactiveLoadEventListener.doLoad(DefaultReactiveLoadEventListener.java:597

[blafond]

@DavideD The Not using JDBC error is coming from the NoJdbcConnectionProvider.getConnection() call and I haven't figured out why it would call that service.

There's section in DefaultReactiveLoadEventListener.reactiveOnLoad() that has a TODO around lock mode.

[blafond]

@DavideD Changed the lock mode to OPTIMISTIC for both tests and they both succeed

[gavinking]

There's section in DefaultReactiveLoadEventListener.reactiveOnLoad() that has a TODO around lock mode.

@blafond what looks strange here is that this code block seems to be for forced pessimistic locks, but the test code doesn't
appear to be requesting this lock level.

But maybe i'm wrong and this is normal, I would have to run and step through the code.

[gavinking]

Folks, what's the status of this one?

[DavideD]

I don't think anybody is working on this at the moment

[gavinking]

Well, the problem looks straightforward: the nonreactive function CacheEntityLoaderHelper.loadFromSessionCache() calls
EntityPersister.lock() which is obviously incorrect.