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 aae18500bc4fcef6ef3cf4584886c64828318e43 Author: Stephen Mallette <[email protected]> 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(); }
