From aeeba422ca6cc732aef57409bd3f691cc4043702 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 14:00:38 +0200 Subject: [PATCH 01/17] IGNITE-19007 Java client: Improve logging --- .../apache/ignite/internal/client/TcpClientChannel.java | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index 1036863386b..89feebd9383 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -207,7 +207,7 @@ public void onMessage(ByteBuf buf) { /** {@inheritDoc} */ @Override public void onDisconnected(@Nullable Exception e) { - log.debug("Disconnected from server: " + cfg.getAddress()); + log.debug("Disconnected from server [remoteAddress=" + cfg.getAddress() + ']'); close(e); } @@ -484,6 +484,10 @@ private CompletableFuture handshakeRes(ClientMessageUnpacker unpacker, Pro srvVer, ProtocolBitmaskFeature.allFeaturesAsEnumSet(), serverIdleTimeout, clusterNode, clusterId); return CompletableFuture.completedFuture(null); + } catch (Exception e) { + log.warn("Failed to handle handshake response [remoteAddress=" + cfg.getAddress() + "]: " + e.getMessage(), e); + + return CompletableFuture.failedFuture(e); } } @@ -563,7 +567,7 @@ private class HeartbeatTask extends TimerTask { .orTimeout(heartbeatTimeout, TimeUnit.MILLISECONDS) .exceptionally(e -> { if (e instanceof TimeoutException) { - log.warn("Heartbeat timeout, closing the channel"); + log.warn("Heartbeat timeout, closing the channel [remoteAddress=" + cfg.getAddress() + ']'); close((TimeoutException) e); } From 02883bdb698f25f2e39f70c550368a7288935465 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 14:03:19 +0200 Subject: [PATCH 02/17] Log failed heartbeats --- .../org/apache/ignite/internal/client/TcpClientChannel.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index 89feebd9383..a4258a2de25 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -576,8 +576,8 @@ private class HeartbeatTask extends TimerTask { }); } } - } catch (Throwable ignored) { - // Ignore failed heartbeats. + } catch (Throwable e) { + log.warn("Failed to send heartbeat [remoteAddress=" + cfg.getAddress() + "]: " + e.getMessage(), e); } } } From 82bbcb374d516e51d89e571a62afa011f20f9441 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 14:48:02 +0200 Subject: [PATCH 03/17] Log failed requests --- .../org/apache/ignite/internal/client/TcpClientChannel.java | 3 +++ 1 file changed, 3 insertions(+) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index a4258a2de25..395bde6f64e 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -268,6 +268,9 @@ private ClientRequestFuture send(int opCode, PayloadWriter payloadWriter) { return fut; } catch (Throwable t) { + log.warn("Failed to send request [id=" + id + ", op=" + opCode + ", remoteAddress=" + cfg.getAddress() + "]: " + + t.getMessage(), t); + // Close buffer manually on fail. Successful write closes the buffer automatically. payloadCh.close(); pendingReqs.remove(id); From 5d095e78422e2b4f36bdd89a11fd02950acad6a7 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 14:49:54 +0200 Subject: [PATCH 04/17] Log partition assignment change --- .../org/apache/ignite/internal/client/TcpClientChannel.java | 2 ++ 1 file changed, 2 insertions(+) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index 395bde6f64e..452d3141456 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -334,6 +334,8 @@ private void processNextMessage(ByteBuf buf) throws IgniteException { int flags = unpacker.unpackInt(); if (ResponseFlags.getPartitionAssignmentChangedFlag(flags)) { + log.info("Partition assignment change notification received [remoteAddress=" + cfg.getAddress() + "]"); + for (Consumer listener : assignmentChangeListeners) { listener.accept(this); } From b4dd3feea2e392818b6a4ae25d6010ca82d9af7a Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 14:50:13 +0200 Subject: [PATCH 05/17] wip TODOs --- .../org/apache/ignite/internal/client/TcpClientChannel.java | 3 +++ 1 file changed, 3 insertions(+) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index 452d3141456..23204d25e6b 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -320,6 +320,7 @@ private void processNextMessage(ByteBuf buf) throws IgniteException { var type = unpacker.unpackInt(); if (type != ServerMessageType.RESPONSE) { + // TODO: Log? throw new IgniteClientConnectionException(PROTOCOL_ERR, "Unexpected message type: " + type); } @@ -328,6 +329,8 @@ private void processNextMessage(ByteBuf buf) throws IgniteException { ClientRequestFuture pendingReq = pendingReqs.remove(resId); if (pendingReq == null) { + // TODO: Log? + // TODO: Check all other throwables. throw new IgniteClientConnectionException(PROTOCOL_ERR, String.format("Unexpected response ID [%s]", resId)); } From ab4ffbdc8b7f3c3d64f7cff229f96d8275145cbc Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 18:35:30 +0200 Subject: [PATCH 06/17] Log all errors --- .../apache/ignite/internal/client/TcpClientChannel.java | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index 23204d25e6b..1764e092ba7 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -300,6 +300,8 @@ private CompletableFuture receiveAsync(ClientRequestFuture pendingReq, Pa try (var in = new PayloadInputChannel(this, payload)) { return payloadReader.apply(in); } catch (Exception e) { + log.error("Failed to deserialize server response [remoteAddress=" + cfg.getAddress() + "]: " + e.getMessage(), e); + throw new IgniteClientConnectionException(PROTOCOL_ERR, "Failed to deserialize server response: " + e.getMessage(), e); } }, asyncContinuationExecutor); @@ -320,7 +322,8 @@ private void processNextMessage(ByteBuf buf) throws IgniteException { var type = unpacker.unpackInt(); if (type != ServerMessageType.RESPONSE) { - // TODO: Log? + log.error("Unexpected message type [remoteAddress=" + cfg.getAddress() + "]: " + type); + throw new IgniteClientConnectionException(PROTOCOL_ERR, "Unexpected message type: " + type); } @@ -329,8 +332,8 @@ private void processNextMessage(ByteBuf buf) throws IgniteException { ClientRequestFuture pendingReq = pendingReqs.remove(resId); if (pendingReq == null) { - // TODO: Log? - // TODO: Check all other throwables. + log.error("Unexpected response ID [remoteAddress=" + cfg.getAddress() + "]: " + resId); + throw new IgniteClientConnectionException(PROTOCOL_ERR, String.format("Unexpected response ID [%s]", resId)); } From a6f2babd4e86a31a9e9d405fdf8260b8791a9bf2 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 18:37:46 +0200 Subject: [PATCH 07/17] add log level checks --- .../apache/ignite/internal/client/TcpClientChannel.java | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index 1764e092ba7..62c06a23252 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -207,7 +207,10 @@ public void onMessage(ByteBuf buf) { /** {@inheritDoc} */ @Override public void onDisconnected(@Nullable Exception e) { - log.debug("Disconnected from server [remoteAddress=" + cfg.getAddress() + ']'); + if (log.isDebugEnabled()) { + log.debug("Disconnected from server [remoteAddress=" + cfg.getAddress() + ']'); + } + close(e); } @@ -340,7 +343,9 @@ private void processNextMessage(ByteBuf buf) throws IgniteException { int flags = unpacker.unpackInt(); if (ResponseFlags.getPartitionAssignmentChangedFlag(flags)) { - log.info("Partition assignment change notification received [remoteAddress=" + cfg.getAddress() + "]"); + if (log.isInfoEnabled()) { + log.info("Partition assignment change notification received [remoteAddress=" + cfg.getAddress() + "]"); + } for (Consumer listener : assignmentChangeListeners) { listener.accept(this); From 26575b20cda127a1804116bde100a13e77c0b512 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 18:42:00 +0200 Subject: [PATCH 08/17] Log connect/disconnec --- .../org/apache/ignite/internal/client/TcpClientChannel.java | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index 62c06a23252..a2c7e7e4817 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -137,6 +137,10 @@ private CompletableFuture initAsync(ClientConnectionMultiplexer c return connMgr .openAsync(cfg.getAddress(), this, this) .thenCompose(s -> { + if (log.isDebugEnabled()) { + log.debug("Connection established [remoteAddress=" + s.remoteAddress() + ']'); + } + sock = s; return handshakeAsync(DEFAULT_VERSION); @@ -208,7 +212,7 @@ public void onMessage(ByteBuf buf) { @Override public void onDisconnected(@Nullable Exception e) { if (log.isDebugEnabled()) { - log.debug("Disconnected from server [remoteAddress=" + cfg.getAddress() + ']'); + log.debug("Connection closed [remoteAddress=" + cfg.getAddress() + ']'); } close(e); From 013867bc759a6a9b248f0ea106ac6df11d53f187 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 19:06:16 +0200 Subject: [PATCH 09/17] Log schema updates in ClientTable --- .../ignite/internal/client/table/ClientTable.java | 15 ++++++++++++++- 1 file changed, 14 insertions(+), 1 deletion(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/table/ClientTable.java b/modules/client/src/main/java/org/apache/ignite/internal/client/table/ClientTable.java index d4a36701b98..03fd8bd55b9 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/table/ClientTable.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/table/ClientTable.java @@ -30,12 +30,15 @@ import java.util.function.BiConsumer; import java.util.function.BiFunction; import java.util.function.Function; +import org.apache.ignite.client.IgniteClientConfiguration; import org.apache.ignite.internal.client.ClientChannel; +import org.apache.ignite.internal.client.ClientUtils; import org.apache.ignite.internal.client.PayloadOutputChannel; import org.apache.ignite.internal.client.ReliableChannel; import org.apache.ignite.internal.client.proto.ClientMessageUnpacker; import org.apache.ignite.internal.client.proto.ClientOp; import org.apache.ignite.internal.client.tx.ClientTransaction; +import org.apache.ignite.internal.logger.IgniteLogger; import org.apache.ignite.internal.tostring.IgniteToStringBuilder; import org.apache.ignite.lang.IgniteBiTuple; import org.apache.ignite.lang.IgniteException; @@ -60,6 +63,8 @@ public class ClientTable implements Table { private final ConcurrentHashMap schemas = new ConcurrentHashMap<>(); + private final IgniteLogger log; + private volatile int latestSchemaVer = -1; private final Object latestSchemaLock = new Object(); @@ -74,8 +79,9 @@ public class ClientTable implements Table { * @param ch Channel. * @param id Table id. * @param name Table name. + * @param cfg Config. */ - public ClientTable(ReliableChannel ch, UUID id, String name) { + public ClientTable(ReliableChannel ch, UUID id, String name, IgniteClientConfiguration cfg) { assert ch != null; assert id != null; assert name != null && !name.isEmpty(); @@ -83,6 +89,7 @@ public ClientTable(ReliableChannel ch, UUID id, String name) { this.ch = ch; this.id = id; this.name = name; + this.log = ClientUtils.logger(cfg, ClientTable.class); } /** @@ -160,6 +167,8 @@ private CompletableFuture loadSchema(@Nullable Integer ver) { int schemaCnt = r.in().unpackMapHeader(); if (schemaCnt == 0) { + log.warn("Schema not found [tableId=" + id + ", schemaVersion=" + ver + "]"); + throw new IgniteException(UNEXPECTED_ERR, "Schema not found: " + ver); } @@ -167,6 +176,10 @@ private CompletableFuture loadSchema(@Nullable Integer ver) { for (var i = 0; i < schemaCnt; i++) { last = readSchema(r.in()); + + if (log.isDebugEnabled()) { + log.debug("Schema loaded [tableId=" + id + ", schemaVersion=" + last.version() + "]"); + } } return last; From a7475465dc3f8a90ccccd6159b87f614ac327340 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 19:08:02 +0200 Subject: [PATCH 10/17] Log schema updates in ClientTable --- .../org/apache/ignite/internal/client/ReliableChannel.java | 4 ++++ .../apache/ignite/internal/client/table/ClientTable.java | 6 ++---- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java index 09fb936c889..80b3ceacede 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java @@ -166,6 +166,10 @@ public List connections() { return res; } + public IgniteClientConfiguration configuration() { + return clientCfg; + } + /** * Sends request and handles response asynchronously. * diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/table/ClientTable.java b/modules/client/src/main/java/org/apache/ignite/internal/client/table/ClientTable.java index 03fd8bd55b9..91c1a18bad1 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/table/ClientTable.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/table/ClientTable.java @@ -30,7 +30,6 @@ import java.util.function.BiConsumer; import java.util.function.BiFunction; import java.util.function.Function; -import org.apache.ignite.client.IgniteClientConfiguration; import org.apache.ignite.internal.client.ClientChannel; import org.apache.ignite.internal.client.ClientUtils; import org.apache.ignite.internal.client.PayloadOutputChannel; @@ -79,9 +78,8 @@ public class ClientTable implements Table { * @param ch Channel. * @param id Table id. * @param name Table name. - * @param cfg Config. */ - public ClientTable(ReliableChannel ch, UUID id, String name, IgniteClientConfiguration cfg) { + public ClientTable(ReliableChannel ch, UUID id, String name) { assert ch != null; assert id != null; assert name != null && !name.isEmpty(); @@ -89,7 +87,7 @@ public ClientTable(ReliableChannel ch, UUID id, String name, IgniteClientConfigu this.ch = ch; this.id = id; this.name = name; - this.log = ClientUtils.logger(cfg, ClientTable.class); + this.log = ClientUtils.logger(ch.configuration(), ClientTable.class); } /** From 3c796f679b535b88ec484980a3b387c1c37de2b6 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 19:16:39 +0200 Subject: [PATCH 11/17] log retries --- .../ignite/internal/client/ReliableChannel.java | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java index 80b3ceacede..458066f114e 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java @@ -564,7 +564,19 @@ private CompletableFuture getCurChannelAsync() { private boolean shouldRetry(int opCode, ClientFutureUtils.RetryContext ctx) { ClientOperationType opType = ClientUtils.opCodeToClientOperationType(opCode); - return shouldRetry(opType, ctx); + boolean res = shouldRetry(opType, ctx); + + if (log.isDebugEnabled()) { + if (res) { + log.debug("Retrying operation [opCode=" + opCode + ", attempt=" + ctx.attempt + ", lastError=" + + ctx.lastError() + ']'); + } else { + log.debug("Not retrying operation [opCode=" + opCode + ", attempt=" + ctx.attempt + ", lastError=" + + ctx.lastError() + ']'); + } + } + + return res; } /** Determines whether specified operation should be retried. */ From e36dc0bdd3436cf678f6529c46572084fdf12223 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Tue, 14 Mar 2023 19:21:08 +0200 Subject: [PATCH 12/17] Log all requests with trace level --- .../org/apache/ignite/internal/client/TcpClientChannel.java | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index a2c7e7e4817..24a13a0676c 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -226,6 +226,10 @@ public CompletableFuture serviceAsync( PayloadReader payloadReader ) { try { + if (log.isTraceEnabled()) { + log.trace("Sending request [opCode=" + opCode + ", remoteAddress=" + cfg.getAddress() + ']'); + } + ClientRequestFuture fut = send(opCode, payloadWriter); return receiveAsync(fut, payloadReader); From 95c2c06b987864f1e08807b74b559fa2997501b9 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Wed, 15 Mar 2023 12:25:26 +0200 Subject: [PATCH 13/17] Fix tests --- .../src/test/java/org/apache/ignite/client/HeartbeatTest.java | 4 ++-- .../test/java/org/apache/ignite/client/RetryPolicyTest.java | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/modules/client/src/test/java/org/apache/ignite/client/HeartbeatTest.java b/modules/client/src/test/java/org/apache/ignite/client/HeartbeatTest.java index c505deaf306..aeeb47112ee 100644 --- a/modules/client/src/test/java/org/apache/ignite/client/HeartbeatTest.java +++ b/modules/client/src/test/java/org/apache/ignite/client/HeartbeatTest.java @@ -46,8 +46,8 @@ public void testHeartbeatLongerThanIdleTimeoutCausesDisconnect() throws Exceptio try (var ignored = builder.build()) { assertTrue( IgniteTestUtils.waitForCondition( - () -> loggerFactory.logger.entries().stream().anyMatch(x -> x.contains("Disconnected from server")), - 1000)); + () -> loggerFactory.logger.entries().stream().anyMatch(x -> x.contains("Connection closed")), + 10000)); } } } diff --git a/modules/client/src/test/java/org/apache/ignite/client/RetryPolicyTest.java b/modules/client/src/test/java/org/apache/ignite/client/RetryPolicyTest.java index b154503415c..e757d933fb9 100644 --- a/modules/client/src/test/java/org/apache/ignite/client/RetryPolicyTest.java +++ b/modules/client/src/test/java/org/apache/ignite/client/RetryPolicyTest.java @@ -187,7 +187,7 @@ public void testRetryReadPolicyRetriesReadOperations() throws Exception { recView.get(null, Tuple.create().set("id", 1L)); recView.get(null, Tuple.create().set("id", 1L)); - loggerFactory.assertLogContains("Disconnected from server"); + loggerFactory.assertLogContains("Connection closed"); loggerFactory.assertLogContains("Going to retry operation because of error [op=TUPLE_GET"); } } From e1b09eb2b9dcc8f2145bd628e40f8ced7f03e280 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Wed, 15 Mar 2023 12:27:30 +0200 Subject: [PATCH 14/17] Fix checkstyle --- .../org/apache/ignite/internal/client/TcpClientChannel.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java index 24a13a0676c..86387df6747 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/TcpClientChannel.java @@ -279,8 +279,8 @@ private ClientRequestFuture send(int opCode, PayloadWriter payloadWriter) { return fut; } catch (Throwable t) { - log.warn("Failed to send request [id=" + id + ", op=" + opCode + ", remoteAddress=" + cfg.getAddress() + "]: " + - t.getMessage(), t); + log.warn("Failed to send request [id=" + id + ", op=" + opCode + ", remoteAddress=" + cfg.getAddress() + "]: " + + t.getMessage(), t); // Close buffer manually on fail. Successful write closes the buffer automatically. payloadCh.close(); From 3d89d670e3df8a6fe83cff013f38131b85d3fad2 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Wed, 15 Mar 2023 12:39:01 +0200 Subject: [PATCH 15/17] Add testBasicLogging --- .../ignite/client/ClientLoggingTest.java | 26 +++++++++++++++++++ 1 file changed, 26 insertions(+) diff --git a/modules/client/src/test/java/org/apache/ignite/client/ClientLoggingTest.java b/modules/client/src/test/java/org/apache/ignite/client/ClientLoggingTest.java index 71e557b8364..7a417c79e28 100644 --- a/modules/client/src/test/java/org/apache/ignite/client/ClientLoggingTest.java +++ b/modules/client/src/test/java/org/apache/ignite/client/ClientLoggingTest.java @@ -22,11 +22,15 @@ import static org.hamcrest.Matchers.not; import static org.hamcrest.Matchers.startsWith; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertTrue; +import java.util.List; import org.apache.ignite.client.fakes.FakeIgnite; import org.apache.ignite.client.fakes.FakeIgniteTables; +import org.apache.ignite.internal.testframework.IgniteTestUtils; import org.apache.ignite.internal.util.IgniteUtils; import org.apache.ignite.lang.LoggerFactory; +import org.apache.ignite.table.Tuple; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.Test; @@ -78,6 +82,28 @@ public void loggersSetToDifferentClientsNotInterfereWithEachOther() throws Excep loggerFactory2.logger.entries().forEach(msg -> assertThat(msg, startsWith("client2:"))); } + @Test + public void testBasicLogging() throws Exception { + FakeIgnite ignite = new FakeIgnite(); + ((FakeIgniteTables) ignite.tables()).createTable("t"); + + server = startServer(10950, ignite); + server2 = startServer(10955, ignite); + + var loggerFactory = new TestLoggerFactory("c"); + + try (var client = createClient(loggerFactory)) { + client.tables().tables(); + client.tables().table("t"); + + assertTrue(IgniteTestUtils.waitForCondition(() -> loggerFactory.logger.entries().size() > 10, 5_000)); + + loggerFactory.assertLogContains("Connection established"); + loggerFactory.assertLogContains("c:Sending request [opCode=3, remoteAddress=127.0.0.1:1095"); + loggerFactory.assertLogContains("c:Failed to establish connection to 127.0.0.1:1095"); + } + } + private static TestServer startServer(int port, FakeIgnite ignite) { return AbstractClientTest.startServer( port, From d7cdcba4966bb661a6fa164ebfe8bdce512cbfc7 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Wed, 15 Mar 2023 12:39:24 +0200 Subject: [PATCH 16/17] Fix checkstyle --- .../test/java/org/apache/ignite/client/ClientLoggingTest.java | 2 -- 1 file changed, 2 deletions(-) diff --git a/modules/client/src/test/java/org/apache/ignite/client/ClientLoggingTest.java b/modules/client/src/test/java/org/apache/ignite/client/ClientLoggingTest.java index 7a417c79e28..41635df9b85 100644 --- a/modules/client/src/test/java/org/apache/ignite/client/ClientLoggingTest.java +++ b/modules/client/src/test/java/org/apache/ignite/client/ClientLoggingTest.java @@ -24,13 +24,11 @@ import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertTrue; -import java.util.List; import org.apache.ignite.client.fakes.FakeIgnite; import org.apache.ignite.client.fakes.FakeIgniteTables; import org.apache.ignite.internal.testframework.IgniteTestUtils; import org.apache.ignite.internal.util.IgniteUtils; import org.apache.ignite.lang.LoggerFactory; -import org.apache.ignite.table.Tuple; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.Test; From 33bec4c5f27266eb5e35677afe130518429d97b3 Mon Sep 17 00:00:00 2001 From: Pavel Tupitsyn Date: Wed, 15 Mar 2023 12:46:03 +0200 Subject: [PATCH 17/17] Fix duplicate retry logging --- .../ignite/internal/client/ReliableChannel.java | 17 +++++------------ .../apache/ignite/client/RetryPolicyTest.java | 2 +- 2 files changed, 6 insertions(+), 13 deletions(-) diff --git a/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java b/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java index 458066f114e..5fbe5b3bf45 100644 --- a/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java +++ b/modules/client/src/main/java/org/apache/ignite/internal/client/ReliableChannel.java @@ -568,11 +568,11 @@ private boolean shouldRetry(int opCode, ClientFutureUtils.RetryContext ctx) { if (log.isDebugEnabled()) { if (res) { - log.debug("Retrying operation [opCode=" + opCode + ", attempt=" + ctx.attempt + ", lastError=" - + ctx.lastError() + ']'); + log.debug("Retrying operation [opCode=" + opCode + ", opType=" + opType + ", attempt=" + ctx.attempt + + ", lastError=" + ctx.lastError() + ']'); } else { - log.debug("Not retrying operation [opCode=" + opCode + ", attempt=" + ctx.attempt + ", lastError=" - + ctx.lastError() + ']'); + log.debug("Not retrying operation [opCode=" + opCode + ", opType=" + opType + ", attempt=" + ctx.attempt + + ", lastError=" + ctx.lastError() + ']'); } } @@ -612,14 +612,7 @@ private boolean shouldRetry(@Nullable ClientOperationType opType, ClientFutureUt RetryPolicyContext retryPolicyContext = new RetryPolicyContextImpl(clientCfg, opType, ctx.attempt, exception); // Exception in shouldRetry will be handled by ClientFutureUtils.doWithRetryAsync - boolean shouldRetry = plc.shouldRetry(retryPolicyContext); - - if (shouldRetry) { - log.debug("Going to retry operation because of error [op={}, currentAttempt={}, errMsg={}]", - exception, opType, ctx.attempt, exception.getMessage()); - } - - return shouldRetry; + return plc.shouldRetry(retryPolicyContext); } /** diff --git a/modules/client/src/test/java/org/apache/ignite/client/RetryPolicyTest.java b/modules/client/src/test/java/org/apache/ignite/client/RetryPolicyTest.java index e757d933fb9..f0e9f0f415c 100644 --- a/modules/client/src/test/java/org/apache/ignite/client/RetryPolicyTest.java +++ b/modules/client/src/test/java/org/apache/ignite/client/RetryPolicyTest.java @@ -188,7 +188,7 @@ public void testRetryReadPolicyRetriesReadOperations() throws Exception { recView.get(null, Tuple.create().set("id", 1L)); loggerFactory.assertLogContains("Connection closed"); - loggerFactory.assertLogContains("Going to retry operation because of error [op=TUPLE_GET"); + loggerFactory.assertLogContains("Retrying operation [opCode=12, opType=TUPLE_GET, attempt=0, lastError=java.util"); } }