From b17e96e121bfd424b064d5639b41bc280acbf00c Mon Sep 17 00:00:00 2001 From: catbref Date: Sat, 13 Aug 2022 15:42:24 +0100 Subject: [PATCH 1/5] Log count & total size of peer messages sent & received when a peer is disconnected. Requires org.qortal.net.Peer logging level set to DEBUG --- src/main/java/org/qortal/network/Peer.java | 54 ++++++++++++++++++++++ 1 file changed, 54 insertions(+) diff --git a/src/main/java/org/qortal/network/Peer.java b/src/main/java/org/qortal/network/Peer.java index f99a94b1..31eb4569 100644 --- a/src/main/java/org/qortal/network/Peer.java +++ b/src/main/java/org/qortal/network/Peer.java @@ -27,6 +27,8 @@ import java.nio.channels.SocketChannel; import java.security.SecureRandom; import java.util.*; import java.util.concurrent.*; +import java.util.concurrent.atomic.LongAccumulator; +import java.util.concurrent.atomic.LongAdder; import java.util.regex.Matcher; import java.util.regex.Pattern; @@ -153,6 +155,16 @@ public class Peer { */ private CommonBlockData commonBlockData; + // Message stats + + private static class MessageStats { + public final LongAdder count = new LongAdder(); + public final LongAdder totalBytes = new LongAdder(); + } + + private final Map receivedMessageStats = new ConcurrentHashMap<>(); + private final Map sentMessageStats = new ConcurrentHashMap<>(); + // Constructors /** @@ -542,11 +554,18 @@ public class Peer { // Tidy up buffers: this.byteBuffer.flip(); // Read-only, flipped buffer's position will be after end of message, so copy that + long messageByteSize = readOnlyBuffer.position(); this.byteBuffer.position(readOnlyBuffer.position()); // Copy bytes after read message to front of buffer, // adjusting position accordingly, reset limit to capacity this.byteBuffer.compact(); + // Record message stats + MessageStats messageStats = this.receivedMessageStats.computeIfAbsent(message.getType(), k -> new MessageStats()); + // Ideally these two operations would be atomic, we could pack 'count' in top X bits of the 64-bit long, but meh + messageStats.count.increment(); + messageStats.totalBytes.add(messageByteSize); + // Unsupported message type? Discard with no further processing if (message.getType() == MessageType.UNSUPPORTED) continue; @@ -609,6 +628,12 @@ public class Peer { LOGGER.trace("[{}] Sending {} message with ID {} to peer {}", this.peerConnectionId, this.outputMessageType, this.outputMessageId, this); + + // Record message stats + MessageStats messageStats = this.sentMessageStats.computeIfAbsent(message.getType(), k -> new MessageStats()); + // Ideally these two operations would be atomic, we could pack 'count' in top X bits of the 64-bit long, but meh + messageStats.count.increment(); + messageStats.totalBytes.add(this.outputBuffer.limit()); } catch (MessageException e) { // Something went wrong converting message to bytes, so discard but allow another round LOGGER.warn("[{}] Failed to send {} message with ID {} to peer {}: {}", this.peerConnectionId, @@ -799,8 +824,11 @@ public class Peer { } public void shutdown() { + boolean logStats = false; + if (!isStopping) { LOGGER.debug("[{}] Shutting down peer {}", this.peerConnectionId, this); + logStats = true; } isStopping = true; @@ -812,8 +840,34 @@ public class Peer { LOGGER.debug("[{}] IOException while trying to close peer {}", this.peerConnectionId, this); } } + + if (logStats) { + StringBuilder statsBuilder = new StringBuilder(1024); + statsBuilder.append("peer ").append(this).append(" message stats:\n=received="); + appendMessageStats(statsBuilder, this.receivedMessageStats); + statsBuilder.append("\n=sent="); + appendMessageStats(statsBuilder, this.sentMessageStats); + + LOGGER.debug(statsBuilder.toString()); + } } + private static void appendMessageStats(StringBuilder statsBuilder, Map messageStats) { + if (messageStats.isEmpty()) { + statsBuilder.append("\n none"); + return; + } + + messageStats.keySet().stream() + .sorted(Comparator.comparing(MessageType::name)) + .forEach(messageType -> { + MessageStats stats = messageStats.get(messageType); + + statsBuilder.append("\n ").append(messageType.name()) + .append(": count=").append(stats.count.sum()) + .append(", total bytes=").append(stats.totalBytes.sum()); + }); + } // Minimum version From 19197812d359edb6ecf26685ac619cc737e945ae Mon Sep 17 00:00:00 2001 From: CalDescent Date: Fri, 19 Aug 2022 22:54:52 +0100 Subject: [PATCH 2/5] Log DataException during transaction validation. --- src/main/java/org/qortal/block/Block.java | 1 + 1 file changed, 1 insertion(+) diff --git a/src/main/java/org/qortal/block/Block.java b/src/main/java/org/qortal/block/Block.java index c48ab234..2ef97ef5 100644 --- a/src/main/java/org/qortal/block/Block.java +++ b/src/main/java/org/qortal/block/Block.java @@ -1220,6 +1220,7 @@ public class Block { } } } catch (DataException e) { + LOGGER.info("DataException during transaction validation", e); return ValidationResult.TRANSACTION_INVALID; } finally { // Rollback repository changes made by test-processing transactions above From a1365e57d8090ceb93f8848399902a6bd5d6082f Mon Sep 17 00:00:00 2001 From: CalDescent Date: Sun, 21 Aug 2022 12:14:12 +0100 Subject: [PATCH 3/5] Don't log network stats if no messages have been received, as otherwise this floods the logs with empty stats due to failed connections. --- src/main/java/org/qortal/network/Peer.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main/java/org/qortal/network/Peer.java b/src/main/java/org/qortal/network/Peer.java index 31eb4569..cac0ccc9 100644 --- a/src/main/java/org/qortal/network/Peer.java +++ b/src/main/java/org/qortal/network/Peer.java @@ -841,7 +841,7 @@ public class Peer { } } - if (logStats) { + if (logStats && this.receivedMessageStats.size() > 0) { StringBuilder statsBuilder = new StringBuilder(1024); statsBuilder.append("peer ").append(this).append(" message stats:\n=received="); appendMessageStats(statsBuilder, this.receivedMessageStats); From b23500fdd0519af56071e47a981445c365014384 Mon Sep 17 00:00:00 2001 From: CalDescent Date: Sun, 21 Aug 2022 12:16:44 +0100 Subject: [PATCH 4/5] Attempt to hold peer connections for 1-4 hours instead of 5-60 mins, as the constant disconnections are causing too much data to be sent over and over. If this proves to not have any significant bad effects on re-orgs, we could consider setting these even higher or even disabling the auto disconnect by default. --- src/main/java/org/qortal/settings/Settings.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/main/java/org/qortal/settings/Settings.java b/src/main/java/org/qortal/settings/Settings.java index 92730b30..22bf313b 100644 --- a/src/main/java/org/qortal/settings/Settings.java +++ b/src/main/java/org/qortal/settings/Settings.java @@ -210,9 +210,9 @@ public class Settings { private boolean allowConnectionsWithOlderPeerVersions = true; /** Minimum time (in seconds) that we should attempt to remain connected to a peer for */ - private int minPeerConnectionTime = 5 * 60; // seconds + private int minPeerConnectionTime = 60 * 60; // seconds /** Maximum time (in seconds) that we should attempt to remain connected to a peer for */ - private int maxPeerConnectionTime = 60 * 60; // seconds + private int maxPeerConnectionTime = 4 * 60 * 60; // seconds /** Maximum time (in seconds) that a peer should remain connected when requesting QDN data */ private int maxDataPeerConnectionTime = 2 * 60; // seconds From 9658f0cdd4f1bb8fd573982e083aec37b5447028 Mon Sep 17 00:00:00 2001 From: CalDescent Date: Sun, 21 Aug 2022 12:18:40 +0100 Subject: [PATCH 5/5] Revert "Rewrite of isNotOldPeer predicate, to fix logic issue." This rewrite may have been causing problems with connections in the network, due to peers being forgotten too easily. Reverting for now to see if it solves the problem. This reverts commit d81071f2544ec72807f70892388ae2ddec8dbc8c. # Conflicts: # src/main/java/org/qortal/network/Network.java --- src/main/java/org/qortal/network/Network.java | 27 +++++++------------ 1 file changed, 9 insertions(+), 18 deletions(-) diff --git a/src/main/java/org/qortal/network/Network.java b/src/main/java/org/qortal/network/Network.java index 10f02d52..57073e99 100644 --- a/src/main/java/org/qortal/network/Network.java +++ b/src/main/java/org/qortal/network/Network.java @@ -1375,26 +1375,17 @@ public class Network { // We attempted to connect within the last day // but we last managed to connect over a week ago. Predicate isNotOldPeer = peerData -> { - - // First check if there was a connection attempt within the last day - if (peerData.getLastAttempted() != null - && peerData.getLastAttempted() > now - OLD_PEER_ATTEMPTED_PERIOD) { - - // There was, so now check if we had a successful connection in the last 7 days - if (peerData.getLastConnected() != null - && peerData.getLastConnected() > now - OLD_PEER_CONNECTION_PERIOD) { - - // We did, so this is NOT an 'old' peer - return true; - } - - // Last successful connection was more than 1 week ago - this is an 'old' peer - return false; - } - else { - // Best to wait until we have a connection attempt - assume not an 'old' peer until then + if (peerData.getLastAttempted() == null + || peerData.getLastAttempted() < now - OLD_PEER_ATTEMPTED_PERIOD) { return true; } + + if (peerData.getLastConnected() == null + || peerData.getLastConnected() > now - OLD_PEER_CONNECTION_PERIOD) { + return true; + } + + return false; }; // Disregard peers that are NOT 'old'