This is an automated email from the ASF dual-hosted git repository.
kenhuuu pushed a commit to branch server-coordinator
in repository https://gitbox.apache.org/repos/asf/tinkerpop.git
The following commit(s) were added to refs/heads/server-coordinator by this
push:
new 9f92a8703a logging
9f92a8703a is described below
commit 9f92a8703a88dee52499b794832c4549018acc36
Author: Ken Hu <[email protected]>
AuthorDate: Thu Jun 11 11:45:01 2026 -0700
logging
---
.../server/handler/HttpGremlinEndpointHandler.java | 18 +++++++++++++
.../server/transaction/UnmanagedTransaction.java | 31 +++++++++++++++++++---
gremlin-server/src/test/resources/logback-test.xml | 4 +++
3 files changed, 49 insertions(+), 4 deletions(-)
diff --git
a/gremlin-server/src/main/java/org/apache/tinkerpop/gremlin/server/handler/HttpGremlinEndpointHandler.java
b/gremlin-server/src/main/java/org/apache/tinkerpop/gremlin/server/handler/HttpGremlinEndpointHandler.java
index 2248044a28..803b0dd4ba 100644
---
a/gremlin-server/src/main/java/org/apache/tinkerpop/gremlin/server/handler/HttpGremlinEndpointHandler.java
+++
b/gremlin-server/src/main/java/org/apache/tinkerpop/gremlin/server/handler/HttpGremlinEndpointHandler.java
@@ -297,6 +297,13 @@ public class HttpGremlinEndpointHandler extends
SimpleChannelInboundHandler<Requ
final Future<?> executionFuture = ((requestCtx.getTransactionId()
!= null) && !isBeginTransactionRequest) ?
transactionManager.get(requestCtx.getTransactionId()).get().submit(evalFuture) :
requestCtx.getGremlinExecutor().getExecutorService().submit(evalFuture);
+ // TODO(diagnostic): temporary INFO logging to chase a CI-only
hang. A transactional request that reaches
+ // here has been queued on the tx executor; if
close()/shutdownNow() then drains it, no response is ever
+ // written and the client hangs. Requests that should 404 instead
throw below and never log this.
+ if (requestCtx.getTransactionId() != null &&
!isBeginTransactionRequest) {
+ logger.info("TXDIAG endpoint submitted-to-tx tx={}
gremlin=[{}] thread={}",
+ requestCtx.getTransactionId(),
requestMessage.getGremlin(), Thread.currentThread().getName());
+ }
if (seto > 0) {
// Schedule a timeout in the thread pool for future execution.
The coordinator's monitor guarantees
// exactly one response: whichever of this timeout task or the
eval task terminates the response
@@ -309,6 +316,10 @@ public class HttpGremlinEndpointHandler extends
SimpleChannelInboundHandler<Requ
} catch (RejectedExecutionException ree) {
coordinator.writeError(GremlinError.rateLimiting());
} catch (NoSuchElementException | IllegalStateException nsee) {
+ // TODO(diagnostic): temporary INFO logging to chase a CI-only
hang. Reaching here is the GOOD path for a
+ // post-close request: it yields a 404 instead of hanging. Logs
which guard tripped.
+ logger.info("TXDIAG endpoint tx-not-found->404 tx={} via={}
thread={}",
+ requestCtx.getTransactionId(),
nsee.getClass().getSimpleName(), Thread.currentThread().getName());
coordinator.writeError(GremlinError.transactionNotFound(requestCtx.getTransactionId()));
}
}
@@ -513,8 +524,15 @@ public class HttpGremlinEndpointHandler extends
SimpleChannelInboundHandler<Requ
final HttpResponseCoordinator coordinator)
throws Exception {
final Graph graph =
graphManager.getTraversalSource(ctx.getRequestMessage().getField(Tokens.ARGS_G)).getGraph();
graphOp.accept(graph.tx());
+ // TODO(diagnostic): temporary INFO logging to chase a CI-only hang.
Remove once root-caused.
+ logger.info("TXDIAG handleGraphOp graphOp-done, closing tx={}
thread={}",
+ transactionId, Thread.currentThread().getName());
transactionManager.get(transactionId).ifPresent(tx -> tx.close(true));
+ logger.info("TXDIAG handleGraphOp closed, writing response tx={}
thread={} interrupted={}",
+ transactionId, Thread.currentThread().getName(),
Thread.currentThread().isInterrupted());
coordinator.writeData(List.of(Map.of(Tokens.ARGS_TRANSACTION_ID,
transactionId)), false, false);
+ logger.info("TXDIAG handleGraphOp response written tx={} thread={}",
+ transactionId, Thread.currentThread().getName());
}
private Bindings mergeBindingsFromRequest(final Context ctx, final
Bindings bindings) throws ProcessingException {
diff --git
a/gremlin-server/src/main/java/org/apache/tinkerpop/gremlin/server/transaction/UnmanagedTransaction.java
b/gremlin-server/src/main/java/org/apache/tinkerpop/gremlin/server/transaction/UnmanagedTransaction.java
index c3d3b8a274..8fad65998b 100644
---
a/gremlin-server/src/main/java/org/apache/tinkerpop/gremlin/server/transaction/UnmanagedTransaction.java
+++
b/gremlin-server/src/main/java/org/apache/tinkerpop/gremlin/server/transaction/UnmanagedTransaction.java
@@ -145,11 +145,20 @@ public class UnmanagedTransaction {
* @param force if {@code true}, skip the rollback attempt and shut down
immediately
*/
public synchronized void close(boolean force) {
+ // TODO(diagnostic): temporary INFO logging to chase a CI-only hang in
+ // shouldNotLeakDataWhenTraversalQueuedBehindCommit. Remove once
root-caused.
+ logger.info("TXDIAG close() enter tx={} force={} thread={}
accepting={}",
+ transactionId, force, Thread.currentThread().getName(),
accepting.get());
+
accepting.set(false);
// if the transaction has already been removed then there's no need to
do this process again. it's possible
// for this to be called at roughly the same time. this prevents
close() from being called more than once.
- if (manager.get(transactionId).isEmpty()) return;
+ if (manager.get(transactionId).isEmpty()) {
+ logger.info("TXDIAG close() short-circuit (already removed) tx={}
thread={}",
+ transactionId, Thread.currentThread().getName());
+ return;
+ }
if (!force) {
// when not "forced", an open transaction should be rolled back
@@ -169,7 +178,11 @@ public class UnmanagedTransaction {
// try to rollback open transactions. those jobs either timed-out or
completed successfully. either way, no
// additional jobs will be allowed, running jobs will be cancelled (if
possible) and any scheduled jobs will
// be cancelled
- executor.shutdownNow();
+ final java.util.List<Runnable> drained = executor.shutdownNow();
+ // TODO(diagnostic): if drained > 0, a queued request task was
discarded without ever running (and thus
+ // without writing a response) — that is the suspected source of the
client-side hang.
+ logger.info("TXDIAG close() shutdownNow tx={} thread={}
drainedQueuedTasks={}",
+ transactionId, Thread.currentThread().getName(),
drained.size());
manager.destroy(transactionId);
Optional.ofNullable(timeoutFuture.get()).ifPresent(f ->
f.cancel(true));
logger.debug("Transaction {} closed", transactionId);
@@ -185,9 +198,19 @@ public class UnmanagedTransaction {
* @throws IllegalStateException if the transaction is closed
*/
public Future<?> submit(final FutureTask<Void> task) {
- if (!accepting.get()) throw new IllegalStateException("Transaction " +
transactionId + " is closed");
+ // TODO(diagnostic): temporary INFO logging to chase a CI-only hang.
Remove once root-caused.
+ if (!accepting.get()) {
+ logger.info("TXDIAG submit() rejected (not accepting) tx={}
thread={}",
+ transactionId, Thread.currentThread().getName());
+ throw new IllegalStateException("Transaction " + transactionId + "
is closed");
+ }
touch();
- return executor.submit(task);
+ final Future<?> f = executor.submit(task);
+ logger.info("TXDIAG submit() accepted tx={} thread={}
queueLikelyDepth={}",
+ transactionId, Thread.currentThread().getName(),
+ (executor instanceof java.util.concurrent.ThreadPoolExecutor)
+ ? ((java.util.concurrent.ThreadPoolExecutor)
executor).getQueue().size() : -1);
+ return f;
}
}
diff --git a/gremlin-server/src/test/resources/logback-test.xml
b/gremlin-server/src/test/resources/logback-test.xml
index 647f9674e9..d23b0a5cd6 100644
--- a/gremlin-server/src/test/resources/logback-test.xml
+++ b/gremlin-server/src/test/resources/logback-test.xml
@@ -26,6 +26,10 @@ limitations under the License.
<!-- this logger is noisy and we don't assert anything and the error is
already tracked on the server so we can
trim the logs a bit with this. -->
<logger
name="org.apache.tinkerpop.gremlin.driver.handler.GremlinResponseHandler"
level="OFF"/>
+ <!-- TODO(diagnostic): temporary INFO loggers to surface TXDIAG lines
while chasing a CI-only transaction hang.
+ Remove together with the TXDIAG logging in UnmanagedTransaction and
HttpGremlinEndpointHandler. -->
+ <logger
name="org.apache.tinkerpop.gremlin.server.transaction.UnmanagedTransaction"
level="INFO"/>
+ <logger
name="org.apache.tinkerpop.gremlin.server.handler.HttpGremlinEndpointHandler"
level="INFO"/>
<root level="WARN">
<appender-ref ref="stdout"/>
</root>
