throttle warnings in KeepAlive and PeerExchange handlers #1468

This commit is contained in:
woodser 2024-12-14 18:15:26 -05:00
parent 0275de3ff6
commit 19398bb73e
3 changed files with 41 additions and 15 deletions

View file

@ -175,9 +175,9 @@ public class Connection implements HasCapabilities, Runnable, MessageListener {
// throttle logs of reported invalid requests // throttle logs of reported invalid requests
private static final long LOG_THROTTLE_INTERVAL_MS = 30000; // throttle logging rule violations and warnings to once every 30 seconds private static final long LOG_THROTTLE_INTERVAL_MS = 30000; // throttle logging rule violations and warnings to once every 30 seconds
private static long lastLoggedInvalidRequestReportTs = 0; private static long lastLoggedInvalidRequestReportTs = 0;
private static int numUnloggedInvalidRequestReports = 0; private static int numThrottledInvalidRequestReports = 0;
private static long lastLoggedWarningTs = 0; private static long lastLoggedWarningTs = 0;
private static int numUnloggedWarnings = 0; private static int numThrottledWarnings = 0;
/////////////////////////////////////////////////////////////////////////////////////////// ///////////////////////////////////////////////////////////////////////////////////////////
// Constructor // Constructor
@ -620,7 +620,7 @@ public class Connection implements HasCapabilities, Runnable, MessageListener {
boolean logReport = System.currentTimeMillis() - lastLoggedInvalidRequestReportTs > LOG_THROTTLE_INTERVAL_MS; boolean logReport = System.currentTimeMillis() - lastLoggedInvalidRequestReportTs > LOG_THROTTLE_INTERVAL_MS;
// count the number of unlogged reports since last log entry // count the number of unlogged reports since last log entry
if (!logReport) numUnloggedInvalidRequestReports++; if (!logReport) numThrottledInvalidRequestReports++;
// handle report // handle report
if (logReport) log.warn("We got reported the ruleViolation {} at connection with address={}, uid={}, errorMessage={}", ruleViolation, connection.getPeersNodeAddressProperty(), connection.getUid(), errorMessage); if (logReport) log.warn("We got reported the ruleViolation {} at connection with address={}, uid={}, errorMessage={}", ruleViolation, connection.getPeersNodeAddressProperty(), connection.getUid(), errorMessage);
@ -654,8 +654,8 @@ public class Connection implements HasCapabilities, Runnable, MessageListener {
private static synchronized void resetReportedInvalidRequestsThrottle(boolean logReport) { private static synchronized void resetReportedInvalidRequestsThrottle(boolean logReport) {
if (logReport) { if (logReport) {
if (numUnloggedInvalidRequestReports > 0) log.warn("We received {} other reports of invalid requests since the last log entry", numUnloggedInvalidRequestReports); if (numThrottledInvalidRequestReports > 0) log.warn("We received {} other reports of invalid requests since the last log entry", numThrottledInvalidRequestReports);
numUnloggedInvalidRequestReports = 0; numThrottledInvalidRequestReports = 0;
lastLoggedInvalidRequestReportTs = System.currentTimeMillis(); lastLoggedInvalidRequestReportTs = System.currentTimeMillis();
} }
} }
@ -940,11 +940,11 @@ public class Connection implements HasCapabilities, Runnable, MessageListener {
boolean logWarning = System.currentTimeMillis() - lastLoggedWarningTs > LOG_THROTTLE_INTERVAL_MS; boolean logWarning = System.currentTimeMillis() - lastLoggedWarningTs > LOG_THROTTLE_INTERVAL_MS;
if (logWarning) { if (logWarning) {
log.warn(msg); log.warn(msg);
if (numUnloggedWarnings > 0) log.warn("We received {} other log warnings since the last log entry", numUnloggedWarnings); if (numThrottledWarnings > 0) log.warn("{} warnings were throttled since the last log entry", numThrottledWarnings);
numUnloggedWarnings = 0; numThrottledWarnings = 0;
lastLoggedWarningTs = System.currentTimeMillis(); lastLoggedWarningTs = System.currentTimeMillis();
} else { } else {
numUnloggedWarnings++; numThrottledWarnings++;
} }
} }
} }

View file

@ -40,8 +40,10 @@ import java.util.concurrent.TimeUnit;
class KeepAliveHandler implements MessageListener { class KeepAliveHandler implements MessageListener {
private static final Logger log = LoggerFactory.getLogger(KeepAliveHandler.class); private static final Logger log = LoggerFactory.getLogger(KeepAliveHandler.class);
private static final int DELAY_MS = 10_000; private static final int DELAY_MS = 10_000;
private static final long LOG_THROTTLE_INTERVAL_MS = 60000; // throttle logging warnings to once every 60 seconds
private static long lastLoggedWarningTs = 0;
private static int numThrottledWarnings = 0;
/////////////////////////////////////////////////////////////////////////////////////////// ///////////////////////////////////////////////////////////////////////////////////////////
@ -147,9 +149,8 @@ class KeepAliveHandler implements MessageListener {
cleanup(); cleanup();
listener.onComplete(); listener.onComplete();
} else { } else {
log.warn("Nonce not matching. That should never happen.\n\t" + throttleWarn("Nonce not matching. That should never happen.\n" +
"We drop that message. nonce={} / requestNonce={}", "\tWe drop that message. nonce=" + nonce + ", requestNonce=" + pong.getRequestNonce() + ", peerNodeAddress=" + connection.getPeersNodeAddressOptional().orElseGet(null));
nonce, pong.getRequestNonce());
} }
} else { } else {
log.trace("We have stopped already. We ignore that onMessage call."); log.trace("We have stopped already. We ignore that onMessage call.");
@ -167,4 +168,16 @@ class KeepAliveHandler implements MessageListener {
delayTimer = null; delayTimer = null;
} }
} }
private synchronized void throttleWarn(String msg) {
boolean logWarning = System.currentTimeMillis() - lastLoggedWarningTs > LOG_THROTTLE_INTERVAL_MS;
if (logWarning) {
log.warn(msg);
if (numThrottledWarnings > 0) log.warn("{} warnings were throttled since the last log entry", numThrottledWarnings);
numThrottledWarnings = 0;
lastLoggedWarningTs = System.currentTimeMillis();
} else {
numThrottledWarnings++;
}
}
} }

View file

@ -45,6 +45,9 @@ class PeerExchangeHandler implements MessageListener {
// We want to keep timeout short here // We want to keep timeout short here
private static final long TIMEOUT = 90; private static final long TIMEOUT = 90;
private static final int DELAY_MS = 500; private static final int DELAY_MS = 500;
private static final long LOG_THROTTLE_INTERVAL_MS = 60000; // throttle logging warnings to once every 60 seconds
private static long lastLoggedWarningTs = 0;
private static int numThrottledWarnings = 0;
/////////////////////////////////////////////////////////////////////////////////////////// ///////////////////////////////////////////////////////////////////////////////////////////
@ -173,9 +176,8 @@ class PeerExchangeHandler implements MessageListener {
cleanup(); cleanup();
listener.onComplete(); listener.onComplete();
} else { } else {
log.warn("Nonce not matching. That should never happen.\n\t" + throttleWarn("Nonce not matching. That should never happen.\n" +
"We drop that message. nonce={} / requestNonce={}", "\tWe drop that message. nonce=" + nonce + ", requestNonce=" + getPeersResponse.getRequestNonce() + ", peerNodeAddress=" + connection.getPeersNodeAddressOptional().orElseGet(null));
nonce, getPeersResponse.getRequestNonce());
} }
} else { } else {
log.trace("We have stopped that handler already. We ignore that onMessage call."); log.trace("We have stopped that handler already. We ignore that onMessage call.");
@ -216,4 +218,15 @@ class PeerExchangeHandler implements MessageListener {
} }
} }
private synchronized void throttleWarn(String msg) {
boolean logWarning = System.currentTimeMillis() - lastLoggedWarningTs > LOG_THROTTLE_INTERVAL_MS;
if (logWarning) {
log.warn(msg);
if (numThrottledWarnings > 0) log.warn("{} warnings were throttled since the last log entry", numThrottledWarnings);
numThrottledWarnings = 0;
lastLoggedWarningTs = System.currentTimeMillis();
} else {
numThrottledWarnings++;
}
}
} }