Partial fix of IGNITE-5473: Introduce troubleshooting logger
Project: http://git-wip-us.apache.org/repos/asf/ignite/repo Commit: http://git-wip-us.apache.org/repos/asf/ignite/commit/cf345b81 Tree: http://git-wip-us.apache.org/repos/asf/ignite/tree/cf345b81 Diff: http://git-wip-us.apache.org/repos/asf/ignite/diff/cf345b81 Branch: refs/heads/ignite-5578 Commit: cf345b81820fbbcb82e5fcb2283b43ea286a40b4 Parents: e46cf95 Author: Andrey V. Mashenkov <[email protected]> Authored: Tue Jul 18 15:50:03 2017 +0300 Committer: Andrey V. Mashenkov <[email protected]> Committed: Tue Jul 18 15:50:03 2017 +0300 ---------------------------------------------------------------------- .../apache/ignite/IgniteSystemProperties.java | 7 ++ ...idNearAtomicAbstractSingleUpdateRequest.java | 9 ++- ...GridNearAtomicSingleUpdateInvokeRequest.java | 6 ++ .../atomic/GridNearAtomicUpdateResponse.java | 2 +- .../processors/service/ServiceContextImpl.java | 2 + .../util/tostring/GridToStringBuilder.java | 2 +- .../communication/tcp/TcpCommunicationSpi.java | 66 ++++++++++-------- .../ignite/spi/discovery/tcp/ServerImpl.java | 72 ++++++++++++++------ .../spi/discovery/tcp/TcpDiscoverySpi.java | 16 +++-- 9 files changed, 123 insertions(+), 59 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java b/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java index 5da7bd6..264fb4b 100644 --- a/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java +++ b/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java @@ -146,6 +146,13 @@ public final class IgniteSystemProperties { public static final String IGNITE_QUIET = "IGNITE_QUIET"; /** + * Setting this option to {@code true} will enable troubleshooting logger. + * Troubleshooting logger makes logging more verbose without enabling debug mode + * to provide more detailed logs without performance penalty. + */ + public static final String IGNITE_TROUBLESHOOTING_LOGGER = "IGNITE_TROUBLESHOOTING_LOGGER"; + + /** * Setting to {@code true} enables writing sensitive information in {@code toString()} output. */ public static final String IGNITE_TO_STRING_INCLUDE_SENSITIVE = "IGNITE_TO_STRING_INCLUDE_SENSITIVE"; http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicAbstractSingleUpdateRequest.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicAbstractSingleUpdateRequest.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicAbstractSingleUpdateRequest.java index 7022561..45ccb0e 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicAbstractSingleUpdateRequest.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicAbstractSingleUpdateRequest.java @@ -21,10 +21,10 @@ import java.io.Externalizable; import java.util.UUID; import javax.cache.expiry.ExpiryPolicy; import org.apache.ignite.cache.CacheWriteSynchronizationMode; -import org.apache.ignite.internal.GridDirectTransient; import org.apache.ignite.internal.processors.affinity.AffinityTopologyVersion; import org.apache.ignite.internal.processors.cache.CacheEntryPredicate; import org.apache.ignite.internal.processors.cache.GridCacheOperation; +import org.apache.ignite.internal.util.typedef.internal.S; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; @@ -100,4 +100,11 @@ public abstract class GridNearAtomicAbstractSingleUpdateRequest extends GridNear @Nullable @Override public CacheEntryPredicate[] filter() { return NO_FILTER; } + + /** {@inheritDoc} */ + @Override public String toString() { + return S.toString(GridNearAtomicAbstractSingleUpdateRequest.class, this, + "nodeId", nodeId, "futId", futId, "topVer", topVer, + "parent", super.toString()); + } } http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicSingleUpdateInvokeRequest.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicSingleUpdateInvokeRequest.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicSingleUpdateInvokeRequest.java index b1fb530..865d6f8 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicSingleUpdateInvokeRequest.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicSingleUpdateInvokeRequest.java @@ -34,6 +34,7 @@ import org.apache.ignite.internal.processors.cache.GridCacheSharedContext; import org.apache.ignite.internal.processors.cache.KeyCacheObject; import org.apache.ignite.internal.processors.cache.version.GridCacheVersion; import org.apache.ignite.internal.util.typedef.internal.CU; +import org.apache.ignite.internal.util.typedef.internal.S; import org.apache.ignite.internal.util.typedef.internal.U; import org.apache.ignite.plugin.extensions.communication.MessageCollectionItemType; import org.apache.ignite.plugin.extensions.communication.MessageReader; @@ -282,4 +283,9 @@ public class GridNearAtomicSingleUpdateInvokeRequest extends GridNearAtomicSingl @Override public short directType() { return 126; } + + /** {@inheritDoc} */ + @Override public String toString() { + return S.toString(GridNearAtomicSingleUpdateRequest.class, this, super.toString()); + } } http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicUpdateResponse.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicUpdateResponse.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicUpdateResponse.java index 9492164..37fe824 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicUpdateResponse.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/atomic/GridNearAtomicUpdateResponse.java @@ -536,6 +536,6 @@ public class GridNearAtomicUpdateResponse extends GridCacheIdMessage implements /** {@inheritDoc} */ @Override public String toString() { - return S.toString(GridNearAtomicUpdateResponse.class, this, "parent"); + return S.toString(GridNearAtomicUpdateResponse.class, this, super.toString()); } } http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/internal/processors/service/ServiceContextImpl.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/service/ServiceContextImpl.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/service/ServiceContextImpl.java index 66061d5..490b598 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/service/ServiceContextImpl.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/service/ServiceContextImpl.java @@ -23,6 +23,7 @@ import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ConcurrentMap; import java.util.concurrent.ExecutorService; import org.apache.ignite.internal.util.tostring.GridToStringExclude; +import org.apache.ignite.internal.util.tostring.GridToStringInclude; import org.apache.ignite.internal.util.typedef.internal.S; import org.apache.ignite.services.Service; import org.apache.ignite.services.ServiceContext; @@ -48,6 +49,7 @@ public class ServiceContextImpl implements ServiceContext { private final String cacheName; /** Affinity key. */ + @GridToStringInclude private final Object affKey; /** Executor service. */ http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/internal/util/tostring/GridToStringBuilder.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/util/tostring/GridToStringBuilder.java b/modules/core/src/main/java/org/apache/ignite/internal/util/tostring/GridToStringBuilder.java index 0c49b51..8d578ac 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/util/tostring/GridToStringBuilder.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/util/tostring/GridToStringBuilder.java @@ -87,7 +87,7 @@ public class GridToStringBuilder { private static final ReadWriteLock rwLock = new ReentrantReadWriteLock(); /** Maximum number of collection (map) entries to print. */ - public static final int MAX_COL_SIZE = 100; + public static final int MAX_COL_SIZE = 200; /** {@link IgniteSystemProperties#IGNITE_TO_STRING_INCLUDE_SENSITIVE} */ public static final boolean INCLUDE_SENSITIVE = http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/spi/communication/tcp/TcpCommunicationSpi.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/spi/communication/tcp/TcpCommunicationSpi.java b/modules/core/src/main/java/org/apache/ignite/spi/communication/tcp/TcpCommunicationSpi.java index af12d3b..35d3032 100755 --- a/modules/core/src/main/java/org/apache/ignite/spi/communication/tcp/TcpCommunicationSpi.java +++ b/modules/core/src/main/java/org/apache/ignite/spi/communication/tcp/TcpCommunicationSpi.java @@ -346,6 +346,10 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati private boolean enableForcibleNodeKill = IgniteSystemProperties .getBoolean(IgniteSystemProperties.IGNITE_ENABLE_FORCIBLE_NODE_KILL); + /** */ + private boolean enableTroubleshootingLog = IgniteSystemProperties + .getBoolean(IgniteSystemProperties.IGNITE_TROUBLESHOOTING_LOGGER); + /** Server listener. */ private final GridNioServerListener<Message> srvLsnr = new GridNioServerListenerAdapter<Message>() { @@ -459,8 +463,8 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati final ClusterNode rmtNode = getSpiContext().node(sndId); if (rmtNode == null) { - if (log.isDebugEnabled()) - log.debug("Close incoming connection, unknown node: " + sndId); + U.warn(log, "Close incoming connection, unknown node [nodeId=" + sndId + + ", ses=" + ses + ']'); ses.close(); @@ -523,10 +527,10 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati if (oldClient != null) { if (oldClient instanceof GridTcpNioCommunicationClient) { - if (log.isDebugEnabled()) - log.debug("Received incoming connection when already connected " + - "to this node, rejecting [locNode=" + locNode.id() + - ", rmtNode=" + sndId + ']'); + if (log.isInfoEnabled()) + log.info("Received incoming connection when already connected " + + "to this node, rejecting [locNode=" + locNode.id() + + ", rmtNode=" + sndId + ']'); ses.send(new RecoveryLastReceivedMessage(ALREADY_CONNECTED)); @@ -555,10 +559,10 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati if (oldClient instanceof GridTcpNioCommunicationClient) { assert oldClient.connectionIndex() == connKey.connectionIndex() : oldClient; - if (log.isDebugEnabled()) - log.debug("Received incoming connection when already connected " + - "to this node, rejecting [locNode=" + locNode.id() + - ", rmtNode=" + sndId + ']'); + if (log.isInfoEnabled()) + log.info("Received incoming connection when already connected " + + "to this node, rejecting [locNode=" + locNode.id() + + ", rmtNode=" + sndId + ']'); ses.send(new RecoveryLastReceivedMessage(ALREADY_CONNECTED)); @@ -578,7 +582,7 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati if (log.isDebugEnabled()) log.debug("Received incoming connection from remote node " + - "[rmtNode=" + rmtNode.id() + ", reserved=" + reserved + + "[rmtNode=" + rmtNode.id() + ", reserved=" + reserved + ", recovery=" + recoveryDesc + ']'); if (reserved) { @@ -595,11 +599,11 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati } else { if (oldFut instanceof ConnectFuture && locNode.order() < rmtNode.order()) { - if (log.isDebugEnabled()) { - log.debug("Received incoming connection from remote node while " + - "connecting to this node, rejecting [locNode=" + locNode.id() + - ", locNodeOrder=" + locNode.order() + ", rmtNode=" + rmtNode.id() + - ", rmtNodeOrder=" + rmtNode.order() + ']'); + if (log.isInfoEnabled()) { + log.info("Received incoming connection from remote node while " + + "connecting to this node, rejecting [locNode=" + locNode.id() + + ", locNodeOrder=" + locNode.order() + ", rmtNode=" + rmtNode.id() + + ", rmtNodeOrder=" + rmtNode.order() + ']'); } ses.send(new RecoveryLastReceivedMessage(ALREADY_CONNECTED)); @@ -3131,11 +3135,11 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati ", addr=" + addr + ", err=" + e + ']'); if (attempt == reconCnt || connTimeout0 > maxConnTimeout) { - if (log.isDebugEnabled()) - log.debug("Handshake timedout (will stop attempts to perform the handshake) " + - "[timeout=" + connTimeout0 + ", maxConnTimeout=" + maxConnTimeout + - ", attempt=" + attempt + ", reconCnt=" + reconCnt + - ", err=" + e.getMessage() + ", addr=" + addr + ']'); + U.warn(log, "Handshake timedout (will stop attempts to perform the handshake) " + + "[node=" + node.id() + ", timeout=" + connTimeout0 + + ", maxConnTimeout=" + maxConnTimeout + + ", attempt=" + attempt + ", reconCnt=" + reconCnt + + ", err=" + e.getMessage() + ", addr=" + addr + ']'); if (errs == null) errs = new IgniteCheckedException("Failed to connect to node (is node still alive?). " + @@ -3172,6 +3176,11 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati boolean failureDetThrReached = timeoutHelper.checkFailureTimeoutReached(e); + if (enableTroubleshootingLog) + U.error(log, "Failed to establish connection to a remote node [node=" + node + + ", addr=" + addr + ", connectAttempts=" + connectAttempts + + ", failureDetThrReached=" + failureDetThrReached + ']', e); + if (failureDetThrReached) LT.warn(log, "Connect timed out (consider increasing 'failureDetectionTimeout' " + "configuration property) [addr=" + addr + ", failureDetectionTimeout=" + @@ -3216,15 +3225,14 @@ public class TcpCommunicationSpi extends IgniteSpiAdapter implements Communicati "operating system firewall is disabled on local and remote hosts) " + "[addrs=" + addrs + ']'); - if (enableForcibleNodeKill) { - if (getSpiContext().node(node.id()) != null && (CU.clientNode(node) || !CU.clientNode(getLocalNode())) && - X.hasCause(errs, ConnectException.class, HandshakeException.class, - SocketTimeoutException.class, HandshakeTimeoutException.class, - IgniteSpiOperationTimeoutException.class)) { + if (enableForcibleNodeKill) {if (getSpiContext().node(node.id()) != null && (CU.clientNode(node) || !CU.clientNode(getLocalNode())) && + X.hasCause(errs, ConnectException.class,HandshakeException.class, SocketTimeoutException.class, HandshakeTimeoutException.class, + IgniteSpiOperationTimeoutException.class)) {String msg = "TcpCommunicationSpi failed to establish connection to node, node will be dropped from " + + "cluster [" + "rmtNode=" + node + ']'; - U.error(log, "TcpCommunicationSpi failed to establish connection to node, node will be dropped from " + - "cluster [" + - "rmtNode=" + node + "]", errs); + if(enableTroubleshootingLog)U.error(log, msg, errs); + else + U.warn(log, msg); getSpiContext().failNode(node.id(), "TcpCommunicationSpi failed to establish connection to node [" + "rmtNode=" + node + http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/ServerImpl.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/ServerImpl.java b/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/ServerImpl.java index d75aae9..d621fb3 100644 --- a/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/ServerImpl.java +++ b/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/ServerImpl.java @@ -521,9 +521,6 @@ class ServerImpl extends TcpDiscoveryImpl { @Override public boolean pingNode(UUID nodeId) { assert nodeId != null; - if (log.isDebugEnabled()) - log.debug("Pinging node: " + nodeId + "]"); - if (nodeId == getLocalNodeId()) return true; @@ -535,8 +532,18 @@ class ServerImpl extends TcpDiscoveryImpl { if (!nodeAlive(nodeId)) return false; + long start = U.currentTimeMillis(); + + if (log.isInfoEnabled()) + log.info("Pinging node: " + nodeId); + boolean res = pingNode(node); + long end = System.currentTimeMillis(); + + if (log.isInfoEnabled()) + log.info("Finished node ping [nodeId=" + nodeId + ", res=" + res + ", time=" + (end - start) + "ms]"); + if (!res && !node.isClient() && nodeAlive(nodeId)) { LT.warn(log, "Failed to ping node (status check will be initiated): " + nodeId); @@ -1698,9 +1705,9 @@ class ServerImpl extends TcpDiscoveryImpl { assert log.isInfoEnabled(); - synchronized (mux) { - StringBuilder b = new StringBuilder(U.nl()); + StringBuilder b = new StringBuilder(U.nl()); + synchronized (mux) { b.append(">>>").append(U.nl()); b.append(">>>").append("Dumping discovery SPI debug info.").append(U.nl()); b.append(">>>").append(U.nl()); @@ -1747,9 +1754,9 @@ class ServerImpl extends TcpDiscoveryImpl { b.append(U.nl()); b.append("Stats: ").append(spi.stats).append(U.nl()); - - U.quietAndInfo(log, b.toString()); } + + U.quietAndInfo(log, b.toString()); } /** @@ -3137,12 +3144,8 @@ class ServerImpl extends TcpDiscoveryImpl { // If node existed on connection initialization we should check // whether it has not gone yet. - if (nextNodeExists) - U.warn(log, "Failed to send message to next node [msg=" + msg + ", next=" + next + - ", errMsg=" + (err != null ? err.getMessage() : "N/A") + ']'); - else if (log.isDebugEnabled()) - log.debug("Failed to send message to next node [msg=" + msg + ", next=" + next + - ", errMsg=" + (err != null ? err.getMessage() : "N/A") + ']'); + U.warn(log, "Failed to send message to next node [msg=" + msg + ", next=" + next + + ", errMsg=" + (err != null ? err.getMessage() : "N/A") + ']'); } } @@ -3324,6 +3327,8 @@ class ServerImpl extends TcpDiscoveryImpl { if (existingNode != null) { if (!node.socketAddresses().equals(existingNode.socketAddresses())) { if (!pingNode(existingNode)) { + U.warn(log, "Sending node failed message for existing node: " + node); + addMessage(new TcpDiscoveryNodeFailedMessage(locNodeId, existingNode.id(), existingNode.internalOrder())); @@ -5373,8 +5378,7 @@ class ServerImpl extends TcpDiscoveryImpl { if (msgs != null) { for (TcpDiscoveryNodeFailedMessage msg : msgs) { - if (log.isDebugEnabled()) - log.debug("Add node failed message for node from failed nodes list: " + msg); + U.warn(log, "Added node failed message for node from failed nodes list: " + msg); addMessage(msg); } @@ -5593,8 +5597,9 @@ class ServerImpl extends TcpDiscoveryImpl { long tstamp = U.currentTimeMillis(); - if (log.isDebugEnabled()) - log.debug("Accepted incoming connection from addr: " + sock.getInetAddress()); + if (log.isInfoEnabled()) + log.info("TCP discovery accepted incoming connection " + + "[rmtAddr=" + sock.getInetAddress() + ", rmtPort=" + sock.getPort() + ']'); SocketReader reader = new SocketReader(sock); @@ -5602,6 +5607,10 @@ class ServerImpl extends TcpDiscoveryImpl { readers.add(reader); } + if (log.isInfoEnabled()) + log.info("TCP discovery spawning a new thread for connection " + + "[rmtAddr=" + sock.getInetAddress() + ", rmtPort=" + sock.getPort() + ']'); + reader.start(); spi.stats.onServerSocketInitialized(U.currentTimeMillis() - tstamp); @@ -5664,6 +5673,12 @@ class ServerImpl extends TcpDiscoveryImpl { ClientMessageWorker clientMsgWrk = null; + SocketAddress rmtAddr = sock.getRemoteSocketAddress(); + + if (log.isInfoEnabled()) + log.info("Started serving remote node connection [rmtAddr=" + rmtAddr + + ", rmtPort=" + sock.getPort() + ']'); + boolean srvSock; try { @@ -5696,11 +5711,11 @@ class ServerImpl extends TcpDiscoveryImpl { else { if (log.isDebugEnabled()) log.debug("Failed to read magic header (too few bytes received) " + - "[rmtAddr=" + sock.getRemoteSocketAddress() + + "[rmtAddr=" + rmtAddr + ", locAddr=" + sock.getLocalSocketAddress() + ']'); LT.warn(log, "Failed to read magic header (too few bytes received) [rmtAddr=" + - sock.getRemoteSocketAddress() + ", locAddr=" + sock.getLocalSocketAddress() + ']'); + rmtAddr + ", locAddr=" + sock.getLocalSocketAddress() + ']'); return; } @@ -5712,7 +5727,7 @@ class ServerImpl extends TcpDiscoveryImpl { "this Ignite port?" + (!spi.isSslEnabled() ? " missed SSL configuration?" : "" ) + ") " + - "[rmtAddr=" + sock.getRemoteSocketAddress() + + "[rmtAddr=" + rmtAddr + ", locAddr=" + sock.getLocalSocketAddress() + ']'); LT.warn(log, "Unknown connection detected (is some other software connecting to " + @@ -5733,6 +5748,11 @@ class ServerImpl extends TcpDiscoveryImpl { if (!spi.isNodeStopping0()) { TcpDiscoveryPingRequest req = (TcpDiscoveryPingRequest)msg; + if (log.isInfoEnabled()) + log.info("Received ping request from the remote node " + + "[rmtNodeId=" + msg.creatorNodeId() + + ", rmtAddr=" + rmtAddr + ", rmtPort=" + sock.getPort() + "]"); + TcpDiscoveryPingResponse res = new TcpDiscoveryPingResponse(locNodeId); IgniteSpiOperationTimeoutHelper timeoutHelper = @@ -5746,6 +5766,12 @@ class ServerImpl extends TcpDiscoveryImpl { } spi.writeToSocket(sock, res, timeoutHelper.nextTimeoutChunk(spi.getSocketTimeout())); + + sock.shutdownOutput(); + + if (log.isInfoEnabled()) + log.info("Finished writing ping response " + "[rmtNodeId=" + msg.creatorNodeId() + + ", rmtAddr=" + rmtAddr + ", rmtPort=" + sock.getPort() + "]"); } else if (log.isDebugEnabled()) log.debug("Ignore ping request, node is stopping."); @@ -5872,7 +5898,7 @@ class ServerImpl extends TcpDiscoveryImpl { else if (e.hasCause(ClassNotFoundException.class)) LT.warn(log, "Failed to read message due to ClassNotFoundException " + "(make sure same versions of all classes are available on all nodes) " + - "[rmtAddr=" + sock.getRemoteSocketAddress() + + "[rmtAddr=" + rmtAddr + ", err=" + X.cause(e, ClassNotFoundException.class).getMessage() + ']'); // Always report marshalling problems. @@ -6162,6 +6188,10 @@ class ServerImpl extends TcpDiscoveryImpl { } U.closeQuiet(sock); + + if (log.isInfoEnabled()) + log.info("Finished serving remote node connection [rmtAddr=" + rmtAddr + + ", rmtPort=" + sock.getPort()); } } http://git-wip-us.apache.org/repos/asf/ignite/blob/cf345b81/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/TcpDiscoverySpi.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/TcpDiscoverySpi.java b/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/TcpDiscoverySpi.java index 371f308..c988d7e 100644 --- a/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/TcpDiscoverySpi.java +++ b/modules/core/src/main/java/org/apache/ignite/spi/discovery/tcp/TcpDiscoverySpi.java @@ -1585,7 +1585,8 @@ public class TcpDiscoverySpi extends IgniteSpiAdapter implements DiscoverySpi { catch (IOException | IgniteCheckedException e) { if (X.hasCause(e, SocketTimeoutException.class)) LT.warn(log, "Timed out waiting for message to be read (most probably, the reason is " + - "in long GC pauses on remote node) [curTimeout=" + timeout + ']'); + "long GC pauses on remote node) [curTimeout=" + timeout + + ", rmtAddr=" + sock.getRemoteSocketAddress() + ", rmtPort=" + sock.getPort() + ']'); throw e; } @@ -1626,8 +1627,9 @@ public class TcpDiscoverySpi extends IgniteSpiAdapter implements DiscoverySpi { catch (SocketTimeoutException e) { LT.warn(log, "Timed out waiting for message delivery receipt (most probably, the reason is " + "in long GC pauses on remote node; consider tuning GC and increasing 'ackTimeout' " + - "configuration property). Will retry to send message with increased timeout. " + - "Current timeout: " + timeout + '.'); + "configuration property). Will retry to send message with increased timeout " + + "[currentTimeout=" + timeout + ", rmtAddr=" + sock.getRemoteSocketAddress() + + ", rmtPort=" + sock.getPort() + ']'); stats.onAckTimeout(); @@ -2164,9 +2166,11 @@ public class TcpDiscoverySpi extends IgniteSpiAdapter implements DiscoverySpi { LT.warn(log, "Socket write has timed out (consider increasing " + (failureDetectionTimeoutEnabled() ? - "'IgniteConfiguration.failureDetectionTimeout' configuration property) [" + - "failureDetectionTimeout=" + failureDetectionTimeout() + ']' : - "'sockTimeout' configuration property) [sockTimeout=" + sockTimeout + ']')); + "'IgniteConfiguration.failureDetectionTimeout' configuration property) [" + + "failureDetectionTimeout=" + failureDetectionTimeout() : + "'sockTimeout' configuration property) [sockTimeout=" + sockTimeout) + + ", rmtAddr=" + sock.getRemoteSocketAddress() + ", rmtPort=" + sock.getPort() + + ", sockTimeout=" + sockTimeout + ']'); stats.onSocketTimeout(); }
