Skip to content

Commit bc79f54

Browse files
tsegismonttsegismont
committed
Trace SqlClientConnection creation
Then we can log some useful information when the connection is used on the wrong context: WARN org.hibernate.reactive.pool.impl.SqlClientConnection:355 [vert.x-eventloop-thread-0] Expected to use connection org.hibernate.reactive.pool.impl.SqlClientConnection@38721e55 on context io.vertx.core.impl.ContextImpl@277d1bea but was io.vertx.core.impl.ContextImpl@1c27414a java.lang.Exception at org.hibernate.reactive.pool.impl.SqlClientPool.getConnectionFromPool(SqlClientPool.java:127) at org.hibernate.reactive.pool.impl.SqlClientPool.getConnection(SqlClientPool.java:108) at org.hibernate.reactive.pool.impl.SqlClientPool$ProxyConnection.connection(SqlClientPool.java:262) at org.hibernate.reactive.pool.impl.SqlClientPool$ProxyConnection.selectIdentifier(SqlClientPool.java:372) at org.hibernate.reactive.id.impl.ReactiveSequenceIdentifierGenerator.nextHiValue(ReactiveSequenceIdentifierGenerator.java:74) at org.hibernate.reactive.id.impl.BlockingIdentifierGenerator$GenerateIdAction.execute(BlockingIdentifierGenerator.java:143) at org.hibernate.reactive.id.impl.BlockingIdentifierGenerator$GenerateIdAction.execute(BlockingIdentifierGenerator.java:123) at io.vertx.core.internal.pool.CombinerExecutor.submit(CombinerExecutor.java:67) at org.hibernate.reactive.id.impl.BlockingIdentifierGenerator.generate(BlockingIdentifierGenerator.java:98) at org.hibernate.reactive.id.impl.ReactiveGeneratorWrapper.generate(ReactiveGeneratorWrapper.java:51) at org.hibernate.reactive.event.impl.AbstractReactiveSaveEventListener.generateId(AbstractReactiveSaveEventListener.java:183) at org.hibernate.reactive.event.impl.AbstractReactiveSaveEventListener.reactiveSaveWithGeneratedId(AbstractReactiveSaveEventListener.java:147) at org.hibernate.reactive.event.impl.DefaultReactivePersistEventListener.entityIsTransient(DefaultReactivePersistEventListener.java:189) at org.hibernate.reactive.event.impl.DefaultReactivePersistEventListener.persist(DefaultReactivePersistEventListener.java:109) at org.hibernate.reactive.event.impl.DefaultReactivePersistEventListener.reactiveOnPersist(DefaultReactivePersistEventListener.java:92) at org.hibernate.reactive.event.impl.DefaultReactivePersistEventListener.reactiveOnPersist(DefaultReactivePersistEventListener.java:64) at org.hibernate.event.service.internal.EventListenerGroupImpl.lambda$fireEventOnEachListener$0(EventListenerGroupImpl.java:164) at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:144) at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:164) at org.hibernate.reactive.session.impl.ReactiveSessionImpl.firePersist(ReactiveSessionImpl.java:887) at org.hibernate.reactive.session.impl.ReactiveSessionImpl.reactivePersist(ReactiveSessionImpl.java:866) at org.hibernate.reactive.stage.impl.StageSessionImpl.persist(StageSessionImpl.java:175) at org.hibernate.reactive.MultithreadedInsertionWithLazyConnectionTest$InsertEntitiesVerticle.storeEntity(MultithreadedInsertionWithLazyConnectionTest.java:201) at org.hibernate.reactive.MultithreadedInsertionWithLazyConnectionTest$InsertEntitiesVerticle.lambda$storeMultipleEntities$2(MultithreadedInsertionWithLazyConnectionTest.java:191) at org.hibernate.reactive.util.impl.CompletionStages.lambda$loop$8(CompletionStages.java:483) at org.hibernate.reactive.util.impl.CompletionStages$ArrayLoop.next(CompletionStages.java:557) at org.hibernate.reactive.util.async.impl.AsyncTrampoline.lambda$asyncWhile$1(AsyncTrampoline.java:215) at org.hibernate.reactive.util.async.impl.AsyncTrampoline$TrampolineInternal.unroll(AsyncTrampoline.java:121) at org.hibernate.reactive.util.async.impl.AsyncTrampoline$TrampolineInternal.trampoline(AsyncTrampoline.java:102) at org.hibernate.reactive.util.async.impl.AsyncTrampoline.asyncWhile(AsyncTrampoline.java:197) at org.hibernate.reactive.util.async.impl.AsyncTrampoline.asyncWhile(AsyncTrampoline.java:215) at org.hibernate.reactive.util.impl.CompletionStages.loop(CompletionStages.java:484) at org.hibernate.reactive.util.impl.CompletionStages.loop(CompletionStages.java:455) at org.hibernate.reactive.MultithreadedInsertionWithLazyConnectionTest$InsertEntitiesVerticle.storeMultipleEntities(MultithreadedInsertionWithLazyConnectionTest.java:191) at org.hibernate.reactive.MultithreadedInsertionWithLazyConnectionTest$InsertEntitiesVerticle.start(MultithreadedInsertionWithLazyConnectionTest.java:166) at io.vertx.core.AbstractVerticle.deploy(AbstractVerticle.java:106) at io.vertx.core.impl.deployment.DefaultDeployment.lambda$deploy$1(DefaultDeployment.java:183) at io.vertx.core.internal.ContextInternal.dispatch(ContextInternal.java:249) at io.vertx.core.internal.ContextInternal.dispatch(ContextInternal.java:231) at io.vertx.core.internal.ContextInternal.lambda$runOnContext$0(ContextInternal.java:50) at io.netty.util.concurrent.AbstractEventExecutor.runTask$$$capture(AbstractEventExecutor.java:148) at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:141) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:535) at io.netty.channel.SingleThreadIoEventLoop.run(SingleThreadIoEventLoop.java:201) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:1193) 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:840) Signed-off-by: Thomas Segismont <tsegismo@ibm.com>
1 parent 08b4386 commit bc79f54

File tree

2 files changed

+58
-7
lines changed

2 files changed

+58
-7
lines changed

‎hibernate-reactive-core/src/main/java/org/hibernate/reactive/pool/impl/SqlClientConnection.java‎

Lines changed: 20 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@
2424
import org.hibernate.reactive.pool.ReactiveConnection;
2525
import org.hibernate.reactive.util.impl.CompletionStages;
2626

27+
import io.vertx.core.internal.ContextInternal;
2728
import io.vertx.core.json.JsonArray;
2829
import io.vertx.core.json.JsonObject;
2930
import io.vertx.sqlclient.DatabaseException;
@@ -59,9 +60,20 @@ public class SqlClientConnection implements ReactiveConnection {
5960

6061
private final Pool pool;
6162
private final SqlConnection connection;
63+
private final ContextInternal creationContext;
64+
private final Exception creationTrace;
6265
private Transaction transaction;
6366

64-
SqlClientConnection(SqlConnection connection, Pool pool, SqlStatementLogger sqlStatementLogger, SqlExceptionHelper sqlExceptionHelper) {
67+
SqlClientConnection(
68+
SqlConnection connection,
69+
Pool pool,
70+
SqlStatementLogger sqlStatementLogger,
71+
SqlExceptionHelper sqlExceptionHelper,
72+
ContextInternal creationContext,
73+
Exception creationTrace) {
74+
this.creationContext = creationContext;
75+
this.creationTrace = creationTrace;
76+
LOG.warn( "Creating Hibernate SqlClientConnection " + this + " on context " + creationContext );
6577
this.pool = pool;
6678
this.sqlStatementLogger = sqlStatementLogger;
6779
this.connection = connection;
@@ -338,6 +350,13 @@ public CompletionStage<RowSet<Row>> preparedQueryOutsideTransaction(String sql)
338350
}
339351

340352
private void feedback(String sql) {
353+
ContextInternal currentContext = ContextInternal.current();
354+
if ( !currentContext.equals( creationContext ) ) {
355+
LOG.warn(
356+
"Expected to use connection " + this + " on context " + creationContext + " but was " + currentContext,
357+
creationTrace
358+
);
359+
}
341360
Objects.requireNonNull( sql, "SQL query cannot be null" );
342361
// DDL already gets formatted by the client, so don't reformat it
343362
FormatStyle formatStyle = sqlStatementLogger.isFormat() && !sql.contains( System.lineSeparator() )

‎hibernate-reactive-core/src/main/java/org/hibernate/reactive/pool/impl/SqlClientPool.java‎

Lines changed: 38 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222
import org.hibernate.reactive.pool.ReactiveConnectionPool;
2323

2424
import io.vertx.core.Future;
25+
import io.vertx.core.internal.ContextInternal;
2526
import io.vertx.sqlclient.DatabaseException;
2627
import io.vertx.sqlclient.Pool;
2728
import io.vertx.sqlclient.Row;
@@ -123,12 +124,29 @@ public CompletionStage<ReactiveConnection> getConnection(String tenantId, SqlExc
123124
}
124125

125126
private CompletionStage<ReactiveConnection> getConnectionFromPool(Pool pool) {
126-
return completionStage( pool.getConnection().map( this::newConnection ), ReactiveConnection::close );
127+
Exception creationTrace = new Exception();
128+
ContextInternal creationContext = ContextInternal.current();
129+
return completionStage(
130+
pool.getConnection()
131+
.map( connection -> newConnection(
132+
connection,
133+
creationContext,
134+
creationTrace
135+
) ), ReactiveConnection::close
136+
);
127137
}
128138

129139
private CompletionStage<ReactiveConnection> getConnectionFromPool(Pool pool, SqlExceptionHelper sqlExceptionHelper) {
140+
Exception creationTrace = new Exception();
141+
ContextInternal creationContext = ContextInternal.current();
130142
return completionStage(
131-
pool.getConnection().map( sqlConnection -> newConnection( sqlConnection, sqlExceptionHelper ) ),
143+
pool.getConnection()
144+
.map( sqlConnection -> newConnection(
145+
sqlConnection,
146+
sqlExceptionHelper,
147+
creationContext,
148+
creationTrace
149+
) ),
132150
ReactiveConnection::close
133151
);
134152
}
@@ -205,12 +223,26 @@ private <T> CompletionStage<T> completionStage(Future<T> future, Consumer<T> onC
205223
return completableFuture;
206224
}
207225

208-
private SqlClientConnection newConnection(SqlConnection connection) {
209-
return newConnection( connection, getSqlExceptionHelper() );
226+
private SqlClientConnection newConnection(
227+
SqlConnection connection,
228+
ContextInternal creationContext,
229+
Exception creationTrace) {
230+
return newConnection( connection, getSqlExceptionHelper(), creationContext, creationTrace );
210231
}
211232

212-
private SqlClientConnection newConnection(SqlConnection connection, SqlExceptionHelper sqlExceptionHelper) {
213-
return new SqlClientConnection( connection, getPool(), getSqlStatementLogger(), sqlExceptionHelper );
233+
private SqlClientConnection newConnection(
234+
SqlConnection connection,
235+
SqlExceptionHelper sqlExceptionHelper,
236+
ContextInternal creationContext,
237+
Exception creationTrace) {
238+
return new SqlClientConnection(
239+
connection,
240+
getPool(),
241+
getSqlStatementLogger(),
242+
sqlExceptionHelper,
243+
creationContext,
244+
creationTrace
245+
);
214246
}
215247

216248
private static class ProxyConnection implements ReactiveConnection {

0 commit comments

Comments
 (0)