From f0e7ad4a071f3ec7e797f8aee98588866bb4963c Mon Sep 17 00:00:00 2001 From: Paul Harris Date: Wed, 16 Oct 2024 12:56:23 +1000 Subject: [PATCH 1/6] refactored logging for inclusion on gossip channels. Signed-off-by: Paul Harris --- .../eth2/gossip/AttestationGossipManager.java | 12 +++++- .../eth2/gossip/GossipFailureLogger.java | 43 ++++++++++--------- .../SyncCommitteeMessageGossipManager.java | 4 +- .../AttestationSubnetSubscriptions.java | 9 +++- .../SyncCommitteeSubnetSubscriptions.java | 10 ++++- .../SingleAttestationTopicHandler.java | 15 ++++++- .../eth2/gossip/GossipFailureLoggerTest.java | 16 +++---- .../p2p/libp2p/gossip/GossipHandler.java | 2 +- 8 files changed, 74 insertions(+), 37 deletions(-) diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/AttestationGossipManager.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/AttestationGossipManager.java index 5f93c7c288c..e434e9e0f7e 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/AttestationGossipManager.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/AttestationGossipManager.java @@ -62,18 +62,26 @@ public void onNewAttestation(final ValidatableAttestation validatableAttestation attestationPublishSuccessCounter.inc(); }, error -> { + LOG.trace( + "Failed to publish attestation {}{} at slot {}", + attestation.hashTreeRoot(), + attestation + .getCommitteeIndices() + .map(z -> String.format(" for validator %s", z)) + .orElse(""), + attestation.getData().getSlot()); gossipFailureLogger.logWithSuppression(error, attestation.getData().getSlot()); attestationPublishFailureCounter.inc(); }); } public void subscribeToSubnetId(final int subnetId) { - LOG.trace("Subscribing to subnet ID {}", subnetId); + LOG.trace("Subscribing to attestation subnet {}", subnetId); subnetSubscriptions.subscribeToSubnetId(subnetId); } public void unsubscribeFromSubnetId(final int subnetId) { - LOG.trace("Unsubscribing to subnet ID {}", subnetId); + LOG.trace("Unsubscribing to attestation subnet {}", subnetId); subnetSubscriptions.unsubscribeFromSubnetId(subnetId); } diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java index 3fbae013bf0..488288e7bc0 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java @@ -42,25 +42,28 @@ public synchronized void logWithSuppression(final Throwable error, final UInt64 lastErroredSlot = slot; lastRootCause = rootCause; - if (lastRootCause instanceof MessageAlreadySeenException) { - LOG.debug( - "Failed to publish {}(s) for slot {} because the message has already been seen", - messageType, - lastErroredSlot); - } else if (lastRootCause instanceof NoPeersForOutboundMessageException - || lastRootCause instanceof SemiDuplexNoOutboundStreamException) { - LOG.log( - suppress ? Level.DEBUG : Level.WARN, - "Failed to publish {}(s) for slot {} because no peers were available on the required gossip topic", - messageType, - lastErroredSlot); - } else { - LOG.log( - suppress ? Level.DEBUG : Level.ERROR, - "Failed to publish {}(s) for slot {}", - messageType, - lastErroredSlot, - error); - } + switch (lastRootCause) { + case MessageAlreadySeenException messageAlreadySeenException -> LOG.debug( + "Failed to publish {}(s) for slot {} because the message has already been seen", + messageType, + lastErroredSlot); + case NoPeersForOutboundMessageException noPeersForOutboundMessageException -> LOG.log( + Level.DEBUG, + "Failed to publish {}(s) for slot {}; {}", + messageType, + lastErroredSlot, + rootCause.getMessage()); + case SemiDuplexNoOutboundStreamException semiDuplexNoOutboundStreamException -> LOG.log( + suppress ? Level.DEBUG : Level.WARN, + "Failed to publish {}(s) for slot {} because no peers were available on the required gossip topic", + messageType, + lastErroredSlot); + default -> LOG.log( + suppress ? Level.DEBUG : Level.ERROR, + "Failed to publish {}(s) for slot {}", + messageType, + lastErroredSlot, + error); + } } } diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/SyncCommitteeMessageGossipManager.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/SyncCommitteeMessageGossipManager.java index 3c1692e90dc..fc8f35edba7 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/SyncCommitteeMessageGossipManager.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/SyncCommitteeMessageGossipManager.java @@ -115,12 +115,12 @@ private void publish(final SyncCommitteeMessage message, final int subnetId) { } public void subscribeToSubnetId(final int subnetId) { - LOG.trace("Subscribing to subnet ID {}", subnetId); + LOG.trace("Subscribing to sync committee subnet ID {}", subnetId); subnetSubscriptions.subscribeToSubnetId(subnetId); } public void unsubscribeFromSubnetId(final int subnetId) { - LOG.trace("Unsubscribing to subnet ID {}", subnetId); + LOG.trace("Unsubscribing to sync committee subnet {}", subnetId); subnetSubscriptions.unsubscribeFromSubnetId(subnetId); } diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java index de1231d38c0..7c1d2a39485 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java @@ -15,6 +15,8 @@ import com.google.common.annotations.VisibleForTesting; import java.util.Optional; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import tech.pegasys.teku.infrastructure.async.AsyncRunner; import tech.pegasys.teku.infrastructure.async.SafeFuture; import tech.pegasys.teku.networking.eth2.gossip.encoding.GossipEncoding; @@ -34,7 +36,7 @@ import tech.pegasys.teku.storage.client.RecentChainData; public class AttestationSubnetSubscriptions extends CommitteeSubnetSubscriptions { - + private static final Logger LOG = LogManager.getLogger(); private final Spec spec; private final AsyncRunner asyncRunner; private final RecentChainData recentChainData; @@ -73,6 +75,11 @@ public SafeFuture gossip(final Attestation attestation) { + attestation.getData().getSlot() + " because the state was not available"); } + LOG.trace( + "send attestation {} slot {} on subnet {}", + attestation.hashTreeRoot(), + attestation.getData().getSlot(), + subnetId.get()); final String topic = GossipTopics.getAttestationSubnetTopic( forkInfo.getForkDigest(spec), subnetId.get(), gossipEncoding); diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java index 5bd63e3ac62..4bc8f627554 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java @@ -13,6 +13,8 @@ package tech.pegasys.teku.networking.eth2.gossip.subnets; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import tech.pegasys.teku.infrastructure.async.AsyncRunner; import tech.pegasys.teku.infrastructure.async.SafeFuture; import tech.pegasys.teku.networking.eth2.gossip.encoding.GossipEncoding; @@ -31,7 +33,7 @@ import tech.pegasys.teku.storage.client.RecentChainData; public class SyncCommitteeSubnetSubscriptions extends CommitteeSubnetSubscriptions { - + private static final Logger LOG = LogManager.getLogger(); private final Spec spec; private final RecentChainData recentChainData; private final SchemaDefinitionsAltair schemaDefinitions; @@ -61,6 +63,12 @@ public SyncCommitteeSubnetSubscriptions( } public SafeFuture gossip(final SyncCommitteeMessage message, final int subnetId) { + LOG.trace( + "send sync committee message {} validator {}, subnet {} on slot slot {} ", + message.hashTreeRoot(), + message.getValidatorIndex(), + subnetId, + message.getSlot()); return gossipNetwork.gossip( GossipTopics.getSyncCommitteeSubnetTopic( forkInfo.getForkDigest(spec), subnetId, gossipEncoding), diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/SingleAttestationTopicHandler.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/SingleAttestationTopicHandler.java index 002b3de3d0f..a5a927662ec 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/SingleAttestationTopicHandler.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/SingleAttestationTopicHandler.java @@ -13,6 +13,8 @@ package tech.pegasys.teku.networking.eth2.gossip.topics.topichandlers; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import tech.pegasys.teku.infrastructure.async.AsyncRunner; import tech.pegasys.teku.networking.eth2.gossip.encoding.GossipEncoding; import tech.pegasys.teku.networking.eth2.gossip.topics.OperationMilestoneValidator; @@ -26,6 +28,7 @@ import tech.pegasys.teku.storage.client.RecentChainData; public class SingleAttestationTopicHandler { + private static final Logger LOG = LogManager.getLogger(); public static Eth2TopicHandler createHandler( final RecentChainData recentChainData, @@ -41,8 +44,16 @@ public static Eth2TopicHandler createHandler( final Spec spec = recentChainData.getSpec(); OperationProcessor convertingProcessor = (attMessage, arrivalTimestamp) -> - operationProcessor.process( - ValidatableAttestation.fromNetwork(spec, attMessage, subnetId), arrivalTimestamp); + operationProcessor + .process( + ValidatableAttestation.fromNetwork(spec, attMessage, subnetId), + arrivalTimestamp) + .thenPeek( + result -> + LOG.trace( + "validate attestation {}; result ({})", + attMessage.hashTreeRoot(), + result.code())); return new Eth2TopicHandler<>( recentChainData, diff --git a/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java b/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java index 6f87429ba32..a5b83d565fb 100644 --- a/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java +++ b/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java @@ -13,8 +13,8 @@ package tech.pegasys.teku.networking.eth2.gossip; +import io.libp2p.core.SemiDuplexNoOutboundStreamException; import io.libp2p.pubsub.MessageAlreadySeenException; -import io.libp2p.pubsub.NoPeersForOutboundMessageException; import org.junit.jupiter.api.Test; import tech.pegasys.infrastructure.logging.LogCaptor; import tech.pegasys.teku.infrastructure.unsigned.UInt64; @@ -43,7 +43,7 @@ void shouldLogAlreadySeenErrorsAtDebugLevel() { void shouldLogFirstNoPeersErrorsAtWarningLevel() { try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { logger.logWithSuppression( - new RuntimeException("Foo", new NoPeersForOutboundMessageException("So Lonely")), SLOT); + new RuntimeException("Foo", new SemiDuplexNoOutboundStreamException("So Lonely")), SLOT); logCaptor.assertWarnLog(NO_PEERS_MESSAGE); } } @@ -52,12 +52,12 @@ void shouldLogFirstNoPeersErrorsAtWarningLevel() { void shouldLogRepeatedNoPeersErrorsAtDebugLevel() { try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { logger.logWithSuppression( - new RuntimeException("Foo", new NoPeersForOutboundMessageException("So Lonely")), SLOT); + new RuntimeException("Foo", new SemiDuplexNoOutboundStreamException("So Lonely")), SLOT); logCaptor.clearLogs(); logger.logWithSuppression( new IllegalStateException( - "Foo", new NoPeersForOutboundMessageException("Not a friend in the world")), + "Foo", new SemiDuplexNoOutboundStreamException("Not a friend in the world")), SLOT); logCaptor.assertDebugLog(NO_PEERS_MESSAGE); } @@ -67,12 +67,12 @@ void shouldLogRepeatedNoPeersErrorsAtDebugLevel() { void shouldLogNoPeersErrorsWithDifferentSlotsAtWarnLevel() { try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { logger.logWithSuppression( - new RuntimeException("Foo", new NoPeersForOutboundMessageException("So Lonely")), SLOT); + new RuntimeException("Foo", new SemiDuplexNoOutboundStreamException("So Lonely")), SLOT); logCaptor.assertWarnLog(NO_PEERS_MESSAGE); logger.logWithSuppression( new IllegalStateException( - "Foo", new NoPeersForOutboundMessageException("Not a friend in the world")), + "Foo", new SemiDuplexNoOutboundStreamException("Not a friend in the world")), UInt64.valueOf(2)); logCaptor.assertWarnLog(noPeersMessage(2)); } @@ -82,7 +82,7 @@ void shouldLogNoPeersErrorsWithDifferentSlotsAtWarnLevel() { void shouldLogNoPeersErrorsAtWarnLevelWhenSeparatedByADifferentException() { try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { logger.logWithSuppression( - new RuntimeException("Foo", new NoPeersForOutboundMessageException("So Lonely")), SLOT); + new RuntimeException("Foo", new SemiDuplexNoOutboundStreamException("So Lonely")), SLOT); logCaptor.assertWarnLog(NO_PEERS_MESSAGE); logCaptor.clearLogs(); @@ -90,7 +90,7 @@ void shouldLogNoPeersErrorsAtWarnLevelWhenSeparatedByADifferentException() { logger.logWithSuppression( new IllegalStateException( - "Foo", new NoPeersForOutboundMessageException("Not a friend in the world")), + "Foo", new SemiDuplexNoOutboundStreamException("Not a friend in the world")), SLOT); logCaptor.assertWarnLog(NO_PEERS_MESSAGE); } diff --git a/networking/p2p/src/main/java/tech/pegasys/teku/networking/p2p/libp2p/gossip/GossipHandler.java b/networking/p2p/src/main/java/tech/pegasys/teku/networking/p2p/libp2p/gossip/GossipHandler.java index 73a0749c4e0..50ad98475cb 100644 --- a/networking/p2p/src/main/java/tech/pegasys/teku/networking/p2p/libp2p/gossip/GossipHandler.java +++ b/networking/p2p/src/main/java/tech/pegasys/teku/networking/p2p/libp2p/gossip/GossipHandler.java @@ -87,6 +87,6 @@ public void gossip(final Bytes bytes) { SafeFuture.of(publisher.publish(Unpooled.wrappedBuffer(bytes.toArrayUnsafe()), topic)) .finish( () -> LOG.trace("Successfully gossiped message on {}", topic), - err -> LOG.debug("Failed to gossip message on " + topic, err)); + err -> LOG.debug("Failed to gossip message on {}, {}", topic, err.getMessage())); } } From 4985d4d0cf91217c5013dea9f778ba8b8ae4b626 Mon Sep 17 00:00:00 2001 From: Paul Harris Date: Fri, 18 Oct 2024 13:51:20 +1000 Subject: [PATCH 2/6] more message tweaks Signed-off-by: Paul Harris --- .../eth2/gossip/GossipFailureLogger.java | 49 ++++++++++--------- .../AttestationSubnetSubscriptions.java | 2 +- .../SyncCommitteeSubnetSubscriptions.java | 2 +- .../p2p/libp2p/gossip/GossipHandler.java | 7 ++- 4 files changed, 34 insertions(+), 26 deletions(-) diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java index 488288e7bc0..5da65069875 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java @@ -42,28 +42,31 @@ public synchronized void logWithSuppression(final Throwable error, final UInt64 lastErroredSlot = slot; lastRootCause = rootCause; - switch (lastRootCause) { - case MessageAlreadySeenException messageAlreadySeenException -> LOG.debug( - "Failed to publish {}(s) for slot {} because the message has already been seen", - messageType, - lastErroredSlot); - case NoPeersForOutboundMessageException noPeersForOutboundMessageException -> LOG.log( - Level.DEBUG, - "Failed to publish {}(s) for slot {}; {}", - messageType, - lastErroredSlot, - rootCause.getMessage()); - case SemiDuplexNoOutboundStreamException semiDuplexNoOutboundStreamException -> LOG.log( - suppress ? Level.DEBUG : Level.WARN, - "Failed to publish {}(s) for slot {} because no peers were available on the required gossip topic", - messageType, - lastErroredSlot); - default -> LOG.log( - suppress ? Level.DEBUG : Level.ERROR, - "Failed to publish {}(s) for slot {}", - messageType, - lastErroredSlot, - error); - } + if (lastRootCause instanceof MessageAlreadySeenException) { + LOG.debug( + "Failed to publish {}(s) for slot {} because the message has already been seen", + messageType, + lastErroredSlot); + } else if (lastRootCause instanceof NoPeersForOutboundMessageException) { + LOG.log( + suppress ? Level.DEBUG : Level.WARN, + "Failed to publish {}(s) for slot {}; {}", + messageType, + lastErroredSlot, + rootCause.getMessage()); + } else if (lastRootCause instanceof SemiDuplexNoOutboundStreamException) { + LOG.log( + suppress ? Level.DEBUG : Level.WARN, + "Failed to publish {}(s) for slot {} because no peers were available on the required gossip topic", + messageType, + lastErroredSlot); + } else { + LOG.log( + suppress ? Level.DEBUG : Level.ERROR, + "Failed to publish {}(s) for slot {}", + messageType, + lastErroredSlot, + error); + } } } diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java index 7c1d2a39485..24bd96c5da0 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java @@ -76,7 +76,7 @@ public SafeFuture gossip(final Attestation attestation) { + " because the state was not available"); } LOG.trace( - "send attestation {} slot {} on subnet {}", + "Send attestation {} slot {} on subnet {}", attestation.hashTreeRoot(), attestation.getData().getSlot(), subnetId.get()); diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java index 4bc8f627554..3e928b8c37b 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java @@ -64,7 +64,7 @@ public SyncCommitteeSubnetSubscriptions( public SafeFuture gossip(final SyncCommitteeMessage message, final int subnetId) { LOG.trace( - "send sync committee message {} validator {}, subnet {} on slot slot {} ", + "Send sync committee message {} validator {}, subnet {} on slot slot {} ", message.hashTreeRoot(), message.getValidatorIndex(), subnetId, diff --git a/networking/p2p/src/main/java/tech/pegasys/teku/networking/p2p/libp2p/gossip/GossipHandler.java b/networking/p2p/src/main/java/tech/pegasys/teku/networking/p2p/libp2p/gossip/GossipHandler.java index 50ad98475cb..c06b5f9d22f 100644 --- a/networking/p2p/src/main/java/tech/pegasys/teku/networking/p2p/libp2p/gossip/GossipHandler.java +++ b/networking/p2p/src/main/java/tech/pegasys/teku/networking/p2p/libp2p/gossip/GossipHandler.java @@ -13,6 +13,7 @@ package tech.pegasys.teku.networking.p2p.libp2p.gossip; +import com.google.common.base.Throwables; import io.libp2p.core.pubsub.MessageApi; import io.libp2p.core.pubsub.PubsubPublisherApi; import io.libp2p.core.pubsub.Topic; @@ -87,6 +88,10 @@ public void gossip(final Bytes bytes) { SafeFuture.of(publisher.publish(Unpooled.wrappedBuffer(bytes.toArrayUnsafe()), topic)) .finish( () -> LOG.trace("Successfully gossiped message on {}", topic), - err -> LOG.debug("Failed to gossip message on {}, {}", topic, err.getMessage())); + err -> + LOG.debug( + "Failed to gossip message on {}, {}", + topic, + Throwables.getRootCause(err).getMessage())); } } From 40602d1d6a893a126842dfc1430ca241ebbb5bb2 Mon Sep 17 00:00:00 2001 From: Paul Harris Date: Wed, 23 Oct 2024 14:54:46 +1000 Subject: [PATCH 3/6] removed some of the trace Signed-off-by: Paul Harris --- .../eth2/gossip/AttestationGossipManager.java | 8 -------- .../subnets/AttestationSubnetSubscriptions.java | 8 -------- .../subnets/SyncCommitteeSubnetSubscriptions.java | 9 --------- .../SingleAttestationTopicHandler.java | 15 ++------------- 4 files changed, 2 insertions(+), 38 deletions(-) diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/AttestationGossipManager.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/AttestationGossipManager.java index e434e9e0f7e..11851a9b07d 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/AttestationGossipManager.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/AttestationGossipManager.java @@ -62,14 +62,6 @@ public void onNewAttestation(final ValidatableAttestation validatableAttestation attestationPublishSuccessCounter.inc(); }, error -> { - LOG.trace( - "Failed to publish attestation {}{} at slot {}", - attestation.hashTreeRoot(), - attestation - .getCommitteeIndices() - .map(z -> String.format(" for validator %s", z)) - .orElse(""), - attestation.getData().getSlot()); gossipFailureLogger.logWithSuppression(error, attestation.getData().getSlot()); attestationPublishFailureCounter.inc(); }); diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java index 24bd96c5da0..ab57636db84 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java @@ -15,8 +15,6 @@ import com.google.common.annotations.VisibleForTesting; import java.util.Optional; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; import tech.pegasys.teku.infrastructure.async.AsyncRunner; import tech.pegasys.teku.infrastructure.async.SafeFuture; import tech.pegasys.teku.networking.eth2.gossip.encoding.GossipEncoding; @@ -36,7 +34,6 @@ import tech.pegasys.teku.storage.client.RecentChainData; public class AttestationSubnetSubscriptions extends CommitteeSubnetSubscriptions { - private static final Logger LOG = LogManager.getLogger(); private final Spec spec; private final AsyncRunner asyncRunner; private final RecentChainData recentChainData; @@ -75,11 +72,6 @@ public SafeFuture gossip(final Attestation attestation) { + attestation.getData().getSlot() + " because the state was not available"); } - LOG.trace( - "Send attestation {} slot {} on subnet {}", - attestation.hashTreeRoot(), - attestation.getData().getSlot(), - subnetId.get()); final String topic = GossipTopics.getAttestationSubnetTopic( forkInfo.getForkDigest(spec), subnetId.get(), gossipEncoding); diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java index 3e928b8c37b..cffecfd3309 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java @@ -13,8 +13,6 @@ package tech.pegasys.teku.networking.eth2.gossip.subnets; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; import tech.pegasys.teku.infrastructure.async.AsyncRunner; import tech.pegasys.teku.infrastructure.async.SafeFuture; import tech.pegasys.teku.networking.eth2.gossip.encoding.GossipEncoding; @@ -33,7 +31,6 @@ import tech.pegasys.teku.storage.client.RecentChainData; public class SyncCommitteeSubnetSubscriptions extends CommitteeSubnetSubscriptions { - private static final Logger LOG = LogManager.getLogger(); private final Spec spec; private final RecentChainData recentChainData; private final SchemaDefinitionsAltair schemaDefinitions; @@ -63,12 +60,6 @@ public SyncCommitteeSubnetSubscriptions( } public SafeFuture gossip(final SyncCommitteeMessage message, final int subnetId) { - LOG.trace( - "Send sync committee message {} validator {}, subnet {} on slot slot {} ", - message.hashTreeRoot(), - message.getValidatorIndex(), - subnetId, - message.getSlot()); return gossipNetwork.gossip( GossipTopics.getSyncCommitteeSubnetTopic( forkInfo.getForkDigest(spec), subnetId, gossipEncoding), diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/SingleAttestationTopicHandler.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/SingleAttestationTopicHandler.java index a5a927662ec..002b3de3d0f 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/SingleAttestationTopicHandler.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/SingleAttestationTopicHandler.java @@ -13,8 +13,6 @@ package tech.pegasys.teku.networking.eth2.gossip.topics.topichandlers; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; import tech.pegasys.teku.infrastructure.async.AsyncRunner; import tech.pegasys.teku.networking.eth2.gossip.encoding.GossipEncoding; import tech.pegasys.teku.networking.eth2.gossip.topics.OperationMilestoneValidator; @@ -28,7 +26,6 @@ import tech.pegasys.teku.storage.client.RecentChainData; public class SingleAttestationTopicHandler { - private static final Logger LOG = LogManager.getLogger(); public static Eth2TopicHandler createHandler( final RecentChainData recentChainData, @@ -44,16 +41,8 @@ public static Eth2TopicHandler createHandler( final Spec spec = recentChainData.getSpec(); OperationProcessor convertingProcessor = (attMessage, arrivalTimestamp) -> - operationProcessor - .process( - ValidatableAttestation.fromNetwork(spec, attMessage, subnetId), - arrivalTimestamp) - .thenPeek( - result -> - LOG.trace( - "validate attestation {}; result ({})", - attMessage.hashTreeRoot(), - result.code())); + operationProcessor.process( + ValidatableAttestation.fromNetwork(spec, attMessage, subnetId), arrivalTimestamp); return new Eth2TopicHandler<>( recentChainData, From ec2c8f0132c252d5bb219691ff7638c821006bba Mon Sep 17 00:00:00 2001 From: Paul Harris Date: Wed, 23 Oct 2024 15:59:22 +1000 Subject: [PATCH 4/6] cleanup Signed-off-by: Paul Harris --- .../eth2/gossip/SyncCommitteeMessageGossipManager.java | 2 +- .../eth2/gossip/subnets/AttestationSubnetSubscriptions.java | 1 + .../eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java | 1 + 3 files changed, 3 insertions(+), 1 deletion(-) diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/SyncCommitteeMessageGossipManager.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/SyncCommitteeMessageGossipManager.java index fc8f35edba7..572291cd344 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/SyncCommitteeMessageGossipManager.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/SyncCommitteeMessageGossipManager.java @@ -115,7 +115,7 @@ private void publish(final SyncCommitteeMessage message, final int subnetId) { } public void subscribeToSubnetId(final int subnetId) { - LOG.trace("Subscribing to sync committee subnet ID {}", subnetId); + LOG.trace("Subscribing to sync committee subnet {}", subnetId); subnetSubscriptions.subscribeToSubnetId(subnetId); } diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java index ab57636db84..de1231d38c0 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/AttestationSubnetSubscriptions.java @@ -34,6 +34,7 @@ import tech.pegasys.teku.storage.client.RecentChainData; public class AttestationSubnetSubscriptions extends CommitteeSubnetSubscriptions { + private final Spec spec; private final AsyncRunner asyncRunner; private final RecentChainData recentChainData; diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java index cffecfd3309..5bd63e3ac62 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/subnets/SyncCommitteeSubnetSubscriptions.java @@ -31,6 +31,7 @@ import tech.pegasys.teku.storage.client.RecentChainData; public class SyncCommitteeSubnetSubscriptions extends CommitteeSubnetSubscriptions { + private final Spec spec; private final RecentChainData recentChainData; private final SchemaDefinitionsAltair schemaDefinitions; From f75b9e139231535737c962545f81b76881feb0a7 Mon Sep 17 00:00:00 2001 From: Enrico Del Fante Date: Wed, 23 Oct 2024 12:41:20 +0200 Subject: [PATCH 5/6] update "no active outbound stream" message update tests --- .../eth2/gossip/GossipFailureLogger.java | 4 +- .../eth2/gossip/GossipFailureLoggerTest.java | 42 +++++++++++++------ 2 files changed, 31 insertions(+), 15 deletions(-) diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java index 5da65069875..d266f19f26a 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java @@ -50,14 +50,14 @@ public synchronized void logWithSuppression(final Throwable error, final UInt64 } else if (lastRootCause instanceof NoPeersForOutboundMessageException) { LOG.log( suppress ? Level.DEBUG : Level.WARN, - "Failed to publish {}(s) for slot {}; {}", + "Failed to publish {}(s) for slot {}: {}", messageType, lastErroredSlot, rootCause.getMessage()); } else if (lastRootCause instanceof SemiDuplexNoOutboundStreamException) { LOG.log( suppress ? Level.DEBUG : Level.WARN, - "Failed to publish {}(s) for slot {} because no peers were available on the required gossip topic", + "Failed to publish {}(s) for slot {} because no active outbound stream for the required gossip topic", messageType, lastErroredSlot); } else { diff --git a/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java b/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java index a5b83d565fb..24d97e96449 100644 --- a/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java +++ b/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java @@ -15,6 +15,7 @@ import io.libp2p.core.SemiDuplexNoOutboundStreamException; import io.libp2p.pubsub.MessageAlreadySeenException; +import io.libp2p.pubsub.NoPeersForOutboundMessageException; import org.junit.jupiter.api.Test; import tech.pegasys.infrastructure.logging.LogCaptor; import tech.pegasys.teku.infrastructure.unsigned.UInt64; @@ -24,7 +25,12 @@ class GossipFailureLoggerTest { public static final String ALREADY_SEEN_MESSAGE = "Failed to publish thingy(s) for slot 1 because the message has already been seen"; public static final UInt64 SLOT = UInt64.ONE; + public static final SemiDuplexNoOutboundStreamException NO_ACTIVE_STREAM_EXCEPTION = + new SemiDuplexNoOutboundStreamException("So Lonely"); + public static final NoPeersForOutboundMessageException NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION = + new NoPeersForOutboundMessageException("no peers"); public static final String NO_PEERS_MESSAGE = noPeersMessage(SLOT.intValue()); + public static final String NO_ACTIVE_STREAM_MESSAGE = noActiveStreamMessage(SLOT.intValue()); public static final String GENERIC_FAILURE_MESSAGE = "Failed to publish thingy(s) for slot 1"; @@ -43,22 +49,28 @@ void shouldLogAlreadySeenErrorsAtDebugLevel() { void shouldLogFirstNoPeersErrorsAtWarningLevel() { try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { logger.logWithSuppression( - new RuntimeException("Foo", new SemiDuplexNoOutboundStreamException("So Lonely")), SLOT); + new RuntimeException("Foo", NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION), SLOT); logCaptor.assertWarnLog(NO_PEERS_MESSAGE); } } + @Test + void shouldLogFirstNoActiveStreamErrorsAtWarningLevel() { + try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { + logger.logWithSuppression(new RuntimeException("Foo", NO_ACTIVE_STREAM_EXCEPTION), SLOT); + logCaptor.assertWarnLog(NO_ACTIVE_STREAM_MESSAGE); + } + } + @Test void shouldLogRepeatedNoPeersErrorsAtDebugLevel() { try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { logger.logWithSuppression( - new RuntimeException("Foo", new SemiDuplexNoOutboundStreamException("So Lonely")), SLOT); + new RuntimeException("Foo", NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION), SLOT); logCaptor.clearLogs(); logger.logWithSuppression( - new IllegalStateException( - "Foo", new SemiDuplexNoOutboundStreamException("Not a friend in the world")), - SLOT); + new IllegalStateException("Foo", NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION), SLOT); logCaptor.assertDebugLog(NO_PEERS_MESSAGE); } } @@ -67,12 +79,11 @@ void shouldLogRepeatedNoPeersErrorsAtDebugLevel() { void shouldLogNoPeersErrorsWithDifferentSlotsAtWarnLevel() { try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { logger.logWithSuppression( - new RuntimeException("Foo", new SemiDuplexNoOutboundStreamException("So Lonely")), SLOT); + new RuntimeException("Foo", NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION), SLOT); logCaptor.assertWarnLog(NO_PEERS_MESSAGE); logger.logWithSuppression( - new IllegalStateException( - "Foo", new SemiDuplexNoOutboundStreamException("Not a friend in the world")), + new IllegalStateException("Foo", NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION), UInt64.valueOf(2)); logCaptor.assertWarnLog(noPeersMessage(2)); } @@ -82,16 +93,14 @@ void shouldLogNoPeersErrorsWithDifferentSlotsAtWarnLevel() { void shouldLogNoPeersErrorsAtWarnLevelWhenSeparatedByADifferentException() { try (final LogCaptor logCaptor = LogCaptor.forClass(GossipFailureLogger.class)) { logger.logWithSuppression( - new RuntimeException("Foo", new SemiDuplexNoOutboundStreamException("So Lonely")), SLOT); + new RuntimeException("Foo", NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION), SLOT); logCaptor.assertWarnLog(NO_PEERS_MESSAGE); logCaptor.clearLogs(); logger.logWithSuppression(new MessageAlreadySeenException("Dupe"), SLOT); logger.logWithSuppression( - new IllegalStateException( - "Foo", new SemiDuplexNoOutboundStreamException("Not a friend in the world")), - SLOT); + new IllegalStateException("Foo", NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION), SLOT); logCaptor.assertWarnLog(NO_PEERS_MESSAGE); } } @@ -136,6 +145,13 @@ void shouldLogMultipleGenericErrorsWithDifferentCausesAtErrorLevel() { private static String noPeersMessage(final int slot) { return "Failed to publish thingy(s) for slot " + slot - + " because no peers were available on the required gossip topic"; + + ": " + + NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION.getMessage(); + } + + private static String noActiveStreamMessage(final int slot) { + return "Failed to publish thingy(s) for slot " + + slot + + " because no active outbound stream for the required gossip topic"; } } From 5ccd4604535b95e5d0a04aebda873ff0340764f7 Mon Sep 17 00:00:00 2001 From: Enrico Del Fante Date: Wed, 23 Oct 2024 12:47:30 +0200 Subject: [PATCH 6/6] revert to semicolon --- .../teku/networking/eth2/gossip/GossipFailureLogger.java | 2 +- .../teku/networking/eth2/gossip/GossipFailureLoggerTest.java | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java index d266f19f26a..a726ec68980 100644 --- a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java +++ b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLogger.java @@ -50,7 +50,7 @@ public synchronized void logWithSuppression(final Throwable error, final UInt64 } else if (lastRootCause instanceof NoPeersForOutboundMessageException) { LOG.log( suppress ? Level.DEBUG : Level.WARN, - "Failed to publish {}(s) for slot {}: {}", + "Failed to publish {}(s) for slot {}; {}", messageType, lastErroredSlot, rootCause.getMessage()); diff --git a/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java b/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java index 24d97e96449..88b457f393d 100644 --- a/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java +++ b/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/GossipFailureLoggerTest.java @@ -145,7 +145,7 @@ void shouldLogMultipleGenericErrorsWithDifferentCausesAtErrorLevel() { private static String noPeersMessage(final int slot) { return "Failed to publish thingy(s) for slot " + slot - + ": " + + "; " + NO_PEERS_FOR_OUTBOUND_MESSAGE_EXCEPTION.getMessage(); }