You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@tinkerpop.apache.org by sp...@apache.org on 2022/12/01 18:28:03 UTC
[tinkerpop] 01/05: TINKERPOP-2813 Improved logging around server-side close
This is an automated email from the ASF dual-hosted git repository.
spmallette pushed a commit to branch TINKERPOP-2813
in repository https://gitbox.apache.org/repos/asf/tinkerpop.git
commit 320ba48b9596ce685dee68d7215397991383742b
Author: Stephen Mallette <st...@amazon.com>
AuthorDate: Fri Oct 14 13:12:07 2022 -0400
TINKERPOP-2813 Improved logging around server-side close
Prior to this change it was impossible to know if the connection closed as a result of a client-side or server-side issue. The log messages now make that more clear. Also, improved the output of the info from Connection and ConnectionPool so that it logged a bit more nicely.
---
CHANGELOG.asciidoc | 1 +
.../tinkerpop/gremlin/driver/Connection.java | 27 ++++++++-
.../tinkerpop/gremlin/driver/ConnectionPool.java | 64 ++++++++++++++++++----
3 files changed, 79 insertions(+), 13 deletions(-)
diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc
index 30fec09ff2..7212285da6 100644
--- a/CHANGELOG.asciidoc
+++ b/CHANGELOG.asciidoc
@@ -41,6 +41,7 @@ image::https://raw.githubusercontent.com/apache/tinkerpop/master/docs/static/ima
* Bumped `jackson-databind` to 2.14.0 to fix security vulnerability.
* Bumped to Groovy 2.5.19.
* Bumped to Netty 4.1.85.
+* Improved logging for `gremlin-driver`.
==== Bugs
diff --git a/gremlin-driver/src/main/java/org/apache/tinkerpop/gremlin/driver/Connection.java b/gremlin-driver/src/main/java/org/apache/tinkerpop/gremlin/driver/Connection.java
index 00536e63ca..e2f5717714 100644
--- a/gremlin-driver/src/main/java/org/apache/tinkerpop/gremlin/driver/Connection.java
+++ b/gremlin-driver/src/main/java/org/apache/tinkerpop/gremlin/driver/Connection.java
@@ -123,8 +123,14 @@ final class Connection {
channel.closeFuture().addListener((ChannelFutureListener) future -> {
logger.debug("OnChannelClose callback called for channel {}", channel);
- // Replace the channel if it was not intentionally closed using CloseAsync method.
+ // if the closeFuture is not set, it means that closeAsync() wasn't called which means that the
+ // close did not come from the client side. it means the server closed the channel for some reason.
+ // it's important to distinguish that difference in debugging
if (thisConnection.closeFuture.get() == null) {
+ logger.error(String.format(
+ "Server closed the Connection on channel %s - scheduling removal from %s",
+ channel.id().asShortText(), thisConnection.pool.getPoolInfo(thisConnection)));
+
// delegate the task to worker thread and free up the event loop
thisConnection.cluster.executor().submit(() -> thisConnection.pool.definitelyDestroyConnection(thisConnection));
}
@@ -355,9 +361,24 @@ final class Connection {
}
}
+ /**
+ * Gets a message that describes the state of the connection.
+ */
public String getConnectionInfo() {
- return String.format("Connection{channel=%s, host=%s, isDead=%s, borrowed=%s, pending=%s}",
- channel, pool.host, isDead(), borrowed, pending.size());
+ return getConnectionInfo(true);
+ }
+
+ /**
+ * Gets a message that describes the state of the connection.
+ *
+ * @param showHost determines if the {@link Host} should be displayed in the message.
+ */
+ public String getConnectionInfo(final boolean showHost) {
+ return showHost ?
+ String.format("Connection{channel=%s, host=%s, isDead=%s, borrowed=%s, pending=%s}",
+ channel.id().asShortText(), pool.host, isDead(), borrowed, pending.size()) :
+ String.format("Connection{channel=%s, isDead=%s, borrowed=%s, pending=%s}",
+ channel.id().asShortText(), isDead(), borrowed, pending.size());
}
/**
diff --git a/gremlin-driver/src/main/java/org/apache/tinkerpop/gremlin/driver/ConnectionPool.java b/gremlin-driver/src/main/java/org/apache/tinkerpop/gremlin/driver/ConnectionPool.java
index ca42dbc791..f1d8f69eb7 100644
--- a/gremlin-driver/src/main/java/org/apache/tinkerpop/gremlin/driver/ConnectionPool.java
+++ b/gremlin-driver/src/main/java/org/apache/tinkerpop/gremlin/driver/ConnectionPool.java
@@ -371,9 +371,10 @@ final class ConnectionPool {
// only close the connection for good once it is done being borrowed or when it is dead
if (connection.isDead() || connection.borrowed.get() == 0) {
if (bin.remove(connection)) {
- connection.closeAsync();
- // TODO: Log the following message on completion of the future returned by closeAsync.
- logger.debug("{} destroyed", connection.getConnectionInfo());
+ final CompletableFuture<Void> closeFuture = connection.closeAsync();
+ closeFuture.whenComplete((v, t) -> {
+ logger.debug("Destroyed {}{}{}", connection.getConnectionInfo(), System.lineSeparator(), this.getPoolInfo());
+ });
}
}
}
@@ -416,13 +417,24 @@ final class ConnectionPool {
logger.debug("Continue to wait for connection on {} if {} > 0", host, remaining);
} while (remaining > 0);
- logger.error("Timed-out ({} {}) waiting for connection on {} - possibly unavailable", timeout, unit, host);
+ // if we get to this point, we waited up to maxWaitForConnection from the pool and did not get a Connection.
+ // this can either mean the pool is exhausted or the host is unavailable. for the former, this could mean
+ // the connection pool and/or server is not sized correctly for the workload as connections are not freeing up
+ // to keep up requests and for the latter it could mean anything from a network hiccup to the server simply
+ // being down. it is critical that the caller be able to discern between these two. the following error
+ // message written to the log should provide some insight into the state of the connection pool telling the
+ // user if the pool was running at maximum.
+ final String timeoutErrorMessage = String.format(
+ "Timed-out (%s %s) waiting for connection on %s%s%s",
+ timeout, unit, host, System.lineSeparator(), this.getPoolInfo());
+
+ logger.error(timeoutErrorMessage);
// if we timeout borrowing a connection that might mean the host is dead (or the timeout was super short).
// either way supply a function to reconnect
this.considerHostUnavailable();
- throw new TimeoutException("Timed-out waiting for connection on " + host + " - possibly unavailable");
+ throw new TimeoutException(timeoutErrorMessage);
}
public void considerHostUnavailable() {
@@ -521,14 +533,46 @@ final class ConnectionPool {
return connections.stream().map(Connection::getChannelId).collect(Collectors.toSet());
}
+ /**
+ * Gets a message that describes the state of the connection pool.
+ */
public String getPoolInfo() {
+ return getPoolInfo(null);
+ }
+
+ /**
+ * Gets a message that describes the state of the connection pool.
+ *
+ * @param connectionToCallout the connection from the pool to identify more clearly in the message
+ */
+ public String getPoolInfo(final Connection connectionToCallout) {
final StringBuilder sb = new StringBuilder("ConnectionPool (");
sb.append(host);
- sb.append(") - ");
- connections.forEach(c -> {
- sb.append(c);
- sb.append(",");
- });
+ sb.append(")");
+
+ if (connections.isEmpty()) {
+ sb.append("- no connections in pool");
+ } else {
+ final int connectionCount = connections.size();
+ sb.append(System.lineSeparator());
+ sb.append(String.format("Connection Pool Status (size=%s max=%s min=%s)", connectionCount, maxPoolSize, minPoolSize));
+ sb.append(System.lineSeparator());
+
+ for (int ix = 0; ix < connectionCount; ix++) {
+ final Connection c = connections.get(ix);
+
+ if (c == connectionToCallout)
+ sb.append("==> ");
+ else
+ sb.append("> ");
+
+ sb.append(c.getConnectionInfo(false));
+
+ if (ix < connectionCount - 1)
+ sb.append(System.lineSeparator());
+ }
+ }
+
return sb.toString().trim();
}