Update success logging to be consistent with P2PLogger

courtneyeh · courtneyeh · commit 721e66d091ae · 2024-04-13T12:34:27.000+10:00
diff --git a/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/forkchoice/ForkChoice.java b/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/forkchoice/ForkChoice.java
@@ -760,7 +760,12 @@ private void reportInvalidBlock(final SignedBeaconBlock block, final BlockImport
     if (result.getFailureReason() == FailureReason.BLOCK_IS_FROM_FUTURE) {
       return;
     }
-    debugDataDumper.saveInvalidBlockToFile(block.getSlot(), block.getRoot(), block.sszSerialize());
+    debugDataDumper.saveInvalidBlockToFile(
+        block.getSlot(),
+        block.getRoot(),
+        block.sszSerialize(),
+        result.getFailureReason().name(),
+        result.getFailureCause());
     P2P_LOG.onInvalidBlock(
         block.getSlot(),
         block.getRoot(),
diff --git a/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/util/DebugDataDumper.java b/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/util/DebugDataDumper.java
@@ -60,7 +60,10 @@ public DebugDataDumper(final Path directory, final boolean enabled) {
   }
 
   public void saveGossipMessageDecodingError(
-      final String topic, final Optional<UInt64> arrivalTimestamp, final Bytes originalMessage) {
+      final String topic,
+      final Optional<UInt64> arrivalTimestamp,
+      final Bytes originalMessage,
+      final Throwable error) {
     if (!enabled) {
       return;
     }
@@ -70,74 +73,93 @@ public void saveGossipMessageDecodingError(
         Path.of(GOSSIP_MESSAGES_DIR)
             .resolve(DECODING_ERROR_SUB_DIR)
             .resolve(topic.replaceAll("/", "_"));
-    final String identifiers = String.format("on topic %s at %s", topic, formattedTimestamp);
-    saveBytesToFile(
-        "gossip message with decoding error",
-        identifiers,
-        topicPath.resolve(fileName),
-        originalMessage);
+    final boolean success =
+        saveBytesToFile(
+            "gossip message with decoding error", topicPath.resolve(fileName), originalMessage);
+    if (success) {
+      LOG.warn("Failed to decode gossip message on topic {}", topic, error);
+    }
   }
 
   public void saveGossipRejectedMessageToFile(
-      final String topic, final Optional<UInt64> arrivalTimestamp, final Bytes decodedMessage) {
+      final String topic,
+      final Optional<UInt64> arrivalTimestamp,
+      final Bytes decodedMessage,
+      final Optional<String> reason) {
     if (!enabled) {
       return;
     }
     final String formattedTimestamp = formatOptionalTimestamp(arrivalTimestamp);
     final String fileName = String.format("%s.ssz", formattedTimestamp);
     final Path topicPath =
         Path.of(GOSSIP_MESSAGES_DIR).resolve(REJECTED_SUB_DIR).resolve(topic.replaceAll("/", "_"));
-    final String identifiers = String.format("on topic %s at %s", topic, formattedTimestamp);
-    saveBytesToFile(
-        "rejected gossip message", identifiers, topicPath.resolve(fileName), decodedMessage);
+    final boolean success =
+        saveBytesToFile("rejected gossip message", topicPath.resolve(fileName), decodedMessage);
+    if (success) {
+      LOG.warn(
+          "Rejecting gossip message on topic {}, reason: {}",
+          topic,
+          reason.orElse("failed validation"));
+    }
   }
 
   public void saveInvalidBlockToFile(
-      final UInt64 slot, final Bytes32 blockRoot, final Bytes blockSsz) {
+      final UInt64 slot,
+      final Bytes32 blockRoot,
+      final Bytes blockSsz,
+      final String failureReason,
+      final Optional<Throwable> failureCause) {
     if (!enabled) {
       return;
     }
     final String fileName = String.format("%s_%s.ssz", slot, blockRoot.toUnprefixedHexString());
-    final String identifiers = String.format("at slot %s(%s)", slot, blockRoot);
-    saveBytesToFile(
-        "invalid block", identifiers, Path.of(INVALID_BLOCK_DIR).resolve(fileName), blockSsz);
+    final boolean success =
+        saveBytesToFile("invalid block", Path.of(INVALID_BLOCK_DIR).resolve(fileName), blockSsz);
+    if (success) {
+      LOG.warn(
+          "Rejecting invalid block at slot {} with root {} because {}",
+          slot,
+          blockRoot,
+          failureReason,
+          failureCause.orElse(null));
+    }
   }
 
   @VisibleForTesting
-  protected void saveBytesToFile(
-      final String description,
-      final String identifiers,
-      final Path relativeFilePath,
-      final Bytes bytes) {
+  protected boolean saveBytesToFile(
+      final String description, final Path relativeFilePath, final Bytes bytes) {
     final Path path = directory.resolve(relativeFilePath);
     try {
       Files.write(path, bytes.toArray());
-      LOG.info("Saved {} {}", description, identifiers);
     } catch (NoSuchFileException e) {
       if (!path.getParent().toFile().mkdirs()) {
         LOG.error("Failed to save {} bytes to file.", description, e);
-        return;
+        return false;
       }
-      saveAfterCreatingTopicDirectory(description, relativeFilePath, bytes);
+      return saveAfterCreatingTopicDirectory(description, relativeFilePath, bytes);
     } catch (IOException e) {
       LOG.error("Failed to save {} bytes to file.", description, e);
+      return false;
     }
+    return true;
   }
 
-  private void saveAfterCreatingTopicDirectory(
+  private boolean saveAfterCreatingTopicDirectory(
       final String description, final Path relativeFilePath, final Bytes bytes) {
     final Path path = directory.resolve(relativeFilePath);
     try {
       Files.write(path, bytes.toArray());
-      LOG.info("Saved {} ", description);
     } catch (IOException e) {
       LOG.error("Failed to save {} bytes to file.", description, e);
       if (!path.getParent().toFile().exists()) {
+        this.enabled = false;
         LOG.error(
             "{} directory does not exist. Disabling saving debug data to file.",
             relativeFilePath.getParent());
       }
+      return false;
     }
+    return true;
   }
 
   private void createDirectory(
diff --git a/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/util/noop/NoOpDebugDataDumper.java b/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/util/noop/NoOpDebugDataDumper.java
@@ -28,13 +28,23 @@ public NoOpDebugDataDumper() {
 
   @Override
   public void saveGossipMessageDecodingError(
-      final String topic, final Optional<UInt64> arrivalTimestamp, final Bytes originalMessage) {}
+      final String topic,
+      final Optional<UInt64> arrivalTimestamp,
+      final Bytes originalMessage,
+      final Throwable error) {}
 
   @Override
   public void saveGossipRejectedMessageToFile(
-      final String topic, final Optional<UInt64> arrivalTimestamp, final Bytes decodedMessage) {}
+      final String topic,
+      final Optional<UInt64> arrivalTimestamp,
+      final Bytes decodedMessage,
+      final Optional<String> reason) {}
 
   @Override
   public void saveInvalidBlockToFile(
-      final UInt64 slot, final Bytes32 blockRoot, final Bytes blockSsz) {}
+      final UInt64 slot,
+      final Bytes32 blockRoot,
+      final Bytes blockSsz,
+      final String failureReason,
+      final Optional<Throwable> failureCause) {}
 }
diff --git a/ethereum/statetransition/src/test/java/tech/pegasys/teku/statetransition/forkchoice/ForkChoiceTest.java b/ethereum/statetransition/src/test/java/tech/pegasys/teku/statetransition/forkchoice/ForkChoiceTest.java
@@ -307,16 +307,19 @@ void onBlock_consensusValidationShouldNotResolveWhenStateTransitionFails()
 
     final BlockProcessor blockProcessor = mock(BlockProcessor.class);
     when(spec.getBlockProcessor(blockAndState.getSlot())).thenReturn(blockProcessor);
+    final Exception blockException = new StateTransitionException("error!");
     when(blockProcessor.processAndValidateBlock(any(), any(), any(), any()))
-        .thenThrow(new StateTransitionException("error!"));
+        .thenThrow(blockException);
 
     importBlockAndAssertFailure(blockAndState, FailureReason.FAILED_STATE_TRANSITION);
 
     verify(debugDataDumper)
         .saveInvalidBlockToFile(
             eq(blockAndState.getSlot()),
             eq(blockAndState.getBlock().getRoot()),
-            eq(blockAndState.getBlock().sszSerialize()));
+            eq(blockAndState.getBlock().sszSerialize()),
+            eq(FailureReason.FAILED_STATE_TRANSITION.toString()),
+            eq(Optional.of(blockException)));
     verify(blockBroadcastValidator, never()).onConsensusValidationSucceeded();
   }
 
@@ -347,7 +350,9 @@ void onBlock_consensusValidationShouldReturnRegardlessExecutionPayloadValidation
     // resolve with a failure
     payloadStatusSafeFuture.complete(PayloadStatus.invalid(Optional.empty(), Optional.empty()));
     assertBlockImportFailure(importResult, FailureReason.FAILED_STATE_TRANSITION);
-    verify(debugDataDumper).saveInvalidBlockToFile(any(), any(), any());
+    verify(debugDataDumper)
+        .saveInvalidBlockToFile(
+            any(), any(), any(), eq(FailureReason.FAILED_STATE_TRANSITION.toString()), any());
   }
 
   @Test
@@ -747,7 +752,13 @@ void onBlock_shouldNotOptimisticallyImportInvalidExecutionPayload() {
     storageSystem.chainUpdater().setCurrentSlot(slotToImport.increment());
     importBlockAndAssertFailure(
         chainBuilder.generateNextBlock(), FailureReason.FAILED_STATE_TRANSITION);
-    verify(debugDataDumper).saveInvalidBlockToFile(eq(slotToImport.increment()), any(), any());
+    verify(debugDataDumper)
+        .saveInvalidBlockToFile(
+            eq(slotToImport.increment()),
+            any(),
+            any(),
+            eq(FailureReason.FAILED_STATE_TRANSITION.toString()),
+            any());
   }
 
   @Test
@@ -788,7 +799,9 @@ void onBlock_shouldChangeForkChoiceForLatestValidHashOnInvalidExecutionPayload()
         .saveInvalidBlockToFile(
             eq(invalidBlock.getSlot()),
             eq(invalidBlock.getRoot()),
-            eq(invalidBlock.getBlock().sszSerialize()));
+            eq(invalidBlock.getBlock().sszSerialize()),
+            eq(FailureReason.FAILED_STATE_TRANSITION.toString()),
+            any());
     assertHeadIsOptimistic(maybeValidBlock);
     assertThat(forkChoiceStrategy.getChainHeads().get(0).getRoot())
         .isEqualTo(maybeValidBlock.getRoot());
diff --git a/ethereum/statetransition/src/test/java/tech/pegasys/teku/statetransition/util/DebugDataDumperTest.java b/ethereum/statetransition/src/test/java/tech/pegasys/teku/statetransition/util/DebugDataDumperTest.java
@@ -47,7 +47,8 @@ void saveGossipMessageDecodingError_shouldSaveToFile(@TempDir Path tempDir) {
     final DebugDataDumper manager = new DebugDataDumper(tempDir, true);
     final Bytes messageBytes = dataStructureUtil.stateBuilderPhase0().build().sszSerialize();
     final Optional<UInt64> arrivalTimestamp = Optional.of(timeProvider.getTimeInMillis());
-    manager.saveGossipMessageDecodingError("/eth/test/topic", arrivalTimestamp, messageBytes);
+    manager.saveGossipMessageDecodingError(
+        "/eth/test/topic", arrivalTimestamp, messageBytes, new Throwable());
 
     final String fileName =
         String.format("%s.ssz", manager.formatTimestamp(timeProvider.getTimeInMillis()));
@@ -65,7 +66,8 @@ void saveGossipMessageDecodingError_shouldNotSaveToFileWhenDisabled(@TempDir Pat
     final DebugDataDumper manager = new DebugDataDumper(tempDir, false);
     final Bytes messageBytes = dataStructureUtil.stateBuilderPhase0().build().sszSerialize();
     final Optional<UInt64> arrivalTimestamp = Optional.of(timeProvider.getTimeInMillis());
-    manager.saveGossipMessageDecodingError("/eth/test/topic", arrivalTimestamp, messageBytes);
+    manager.saveGossipMessageDecodingError(
+        "/eth/test/topic", arrivalTimestamp, messageBytes, new Throwable());
     assertThat(manager.isEnabled()).isFalse();
 
     final String fileName =
@@ -84,7 +86,8 @@ void saveGossipRejectedMessageToFile_shouldSaveToFile(@TempDir Path tempDir) {
     final DebugDataDumper manager = new DebugDataDumper(tempDir, true);
     final Bytes messageBytes = dataStructureUtil.stateBuilderPhase0().build().sszSerialize();
     final Optional<UInt64> arrivalTimestamp = Optional.of(timeProvider.getTimeInMillis());
-    manager.saveGossipRejectedMessageToFile("/eth/test/topic", arrivalTimestamp, messageBytes);
+    manager.saveGossipRejectedMessageToFile(
+        "/eth/test/topic", arrivalTimestamp, messageBytes, Optional.of("reason"));
 
     final String fileName =
         String.format("%s.ssz", manager.formatTimestamp(timeProvider.getTimeInMillis()));
@@ -102,7 +105,8 @@ void saveGossipRejectedMessageToFile_shouldNotSaveToFileWhenDisabled(@TempDir Pa
     final DebugDataDumper manager = new DebugDataDumper(tempDir, false);
     final Bytes messageBytes = dataStructureUtil.stateBuilderPhase0().build().sszSerialize();
     final Optional<UInt64> arrivalTimestamp = Optional.of(timeProvider.getTimeInMillis());
-    manager.saveGossipRejectedMessageToFile("/eth/test/topic", arrivalTimestamp, messageBytes);
+    manager.saveGossipRejectedMessageToFile(
+        "/eth/test/topic", arrivalTimestamp, messageBytes, Optional.of("reason"));
     assertThat(manager.isEnabled()).isFalse();
 
     final String fileName = String.format("%s.ssz", arrivalTimestamp);
@@ -119,7 +123,12 @@ void saveGossipRejectedMessageToFile_shouldNotSaveToFileWhenDisabled(@TempDir Pa
   void saveInvalidBlockToFile_shouldSaveToFile(@TempDir Path tempDir) {
     final DebugDataDumper manager = new DebugDataDumper(tempDir, true);
     final SignedBeaconBlock block = dataStructureUtil.randomSignedBeaconBlock();
-    manager.saveInvalidBlockToFile(block.getSlot(), block.getRoot(), block.sszSerialize());
+    manager.saveInvalidBlockToFile(
+        block.getSlot(),
+        block.getRoot(),
+        block.sszSerialize(),
+        "reason",
+        Optional.of(new Throwable()));
 
     final String fileName =
         String.format("%s_%s.ssz", block.getSlot(), block.getRoot().toUnprefixedHexString());
@@ -131,7 +140,8 @@ void saveInvalidBlockToFile_shouldSaveToFile(@TempDir Path tempDir) {
   void saveInvalidBlockToFile_shouldNotSaveToFileWhenDisabled(@TempDir Path tempDir) {
     final DebugDataDumper manager = new DebugDataDumper(tempDir, false);
     final SignedBeaconBlock block = dataStructureUtil.randomSignedBeaconBlock();
-    manager.saveInvalidBlockToFile(block.getSlot(), block.getRoot(), block.sszSerialize());
+    manager.saveInvalidBlockToFile(
+        block.getSlot(), block.getRoot(), block.sszSerialize(), "reason", Optional.empty());
     assertThat(manager.isEnabled()).isFalse();
 
     final String fileName =
@@ -144,9 +154,12 @@ void saveInvalidBlockToFile_shouldNotSaveToFileWhenDisabled(@TempDir Path tempDi
   void saveBytesToFile_shouldNotThrowExceptionWhenNoDirectory(@TempDir Path tempDir) {
     final DebugDataDumper manager = new DebugDataDumper(tempDir, true);
     assertDoesNotThrow(
-        () ->
-            manager.saveBytesToFile(
-                "object", "at slot 1", Path.of("invalid").resolve("file.ssz"), Bytes.EMPTY));
+        () -> {
+          final boolean success =
+              manager.saveBytesToFile(
+                  "object", Path.of("invalid").resolve("file.ssz"), Bytes.EMPTY);
+          assertThat(success).isTrue(); // creates directory
+        });
   }
 
   @Test
@@ -157,9 +170,12 @@ void saveBytesToFile_shouldNotEscalateWhenIOException(@TempDir Path tempDir) {
     assertThat(invalidPath.mkdirs()).isTrue();
     assertThat(invalidPath.setWritable(false)).isTrue();
     assertDoesNotThrow(
-        () ->
-            manager.saveBytesToFile(
-                "object", "at slot 1", Path.of("invalid").resolve("file.ssz"), Bytes.EMPTY));
+        () -> {
+          final boolean success =
+              manager.saveBytesToFile(
+                  "object", Path.of("invalid").resolve("file.ssz"), Bytes.EMPTY);
+          assertThat(success).isFalse();
+        });
   }
 
   @Test
diff --git a/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/Eth2TopicHandler.java b/networking/eth2/src/main/java/tech/pegasys/teku/networking/eth2/gossip/topics/topichandlers/Eth2TopicHandler.java
@@ -138,7 +138,8 @@ private void processMessage(
         debugDataDumper.saveGossipRejectedMessageToFile(
             getTopic(),
             message.getArrivalTimestamp(),
-            message.getDecodedMessage().getDecodedMessage().orElse(Bytes.EMPTY));
+            message.getDecodedMessage().getDecodedMessage().orElse(Bytes.EMPTY),
+            internalValidationResult.getDescription());
         P2P_LOG.onGossipRejected(
             getTopic(),
             message.getDecodedMessage().getDecodedMessage().orElse(Bytes.EMPTY),
@@ -172,7 +173,7 @@ protected ValidationResult handleMessageProcessingError(
     if (ExceptionUtil.hasCause(err, DecodingException.class)) {
 
       debugDataDumper.saveGossipMessageDecodingError(
-          getTopic(), message.getArrivalTimestamp(), message.getOriginalMessage());
+          getTopic(), message.getArrivalTimestamp(), message.getOriginalMessage(), err);
       P2P_LOG.onGossipMessageDecodingError(getTopic(), message.getOriginalMessage(), err);
       response = ValidationResult.Invalid;
     } else if (ExceptionUtil.hasCause(err, RejectedExecutionException.class)) {
diff --git a/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/topics/Eth2TopicHandlerTest.java b/networking/eth2/src/test/java/tech/pegasys/teku/networking/eth2/gossip/topics/Eth2TopicHandlerTest.java
@@ -92,7 +92,7 @@ public void handleMessage_invalid() {
         topicHandler.handleMessage(topicHandler.prepareMessage(blockBytes, Optional.empty()));
     asyncRunner.executeQueuedActions();
     verify(debugDataDumper)
-        .saveGossipRejectedMessageToFile(eq(topicHandler.getTopic()), any(), any());
+        .saveGossipRejectedMessageToFile(eq(topicHandler.getTopic()), any(), any(), any());
     assertThatSafeFuture(result).isCompletedWithValue(ValidationResult.Invalid);
   }
 
@@ -125,7 +125,7 @@ public void handleMessage_invalidBytes() {
     final SafeFuture<ValidationResult> result =
         topicHandler.handleMessage(topicHandler.prepareMessage(invalidBytes, Optional.empty()));
     verify(debugDataDumper)
-        .saveGossipMessageDecodingError(eq(topicHandler.getTopic()), any(), any());
+        .saveGossipMessageDecodingError(eq(topicHandler.getTopic()), any(), any(), any());
     asyncRunner.executeQueuedActions();
 
     assertThatSafeFuture(result).isCompletedWithValue(ValidationResult.Invalid);
@@ -148,7 +148,7 @@ public void handleMessage_errorWhileProcessing_decodingException() {
     final SafeFuture<ValidationResult> result =
         topicHandler.handleMessage(topicHandler.prepareMessage(blockBytes, Optional.empty()));
     verify(debugDataDumper)
-        .saveGossipMessageDecodingError(eq(topicHandler.getTopic()), any(), any());
+        .saveGossipMessageDecodingError(eq(topicHandler.getTopic()), any(), any(), any());
     asyncRunner.executeQueuedActions();
 
     assertThatSafeFuture(result).isCompletedWithValue(ValidationResult.Invalid);
@@ -171,7 +171,7 @@ public void handleMessage_errorWhileProcessing_wrappedDecodingException() {
     final SafeFuture<ValidationResult> result =
         topicHandler.handleMessage(topicHandler.prepareMessage(blockBytes, Optional.empty()));
     verify(debugDataDumper)
-        .saveGossipMessageDecodingError(eq(topicHandler.getTopic()), any(), any());
+        .saveGossipMessageDecodingError(eq(topicHandler.getTopic()), any(), any(), any());
     asyncRunner.executeQueuedActions();
 
     assertThatSafeFuture(result).isCompletedWithValue(ValidationResult.Invalid);
@@ -194,7 +194,7 @@ public void handleMessage_errorWhileProcessing_decodingExceptionWithCause() {
     final SafeFuture<ValidationResult> result =
         topicHandler.handleMessage(topicHandler.prepareMessage(blockBytes, Optional.empty()));
     verify(debugDataDumper)
-        .saveGossipMessageDecodingError(eq(topicHandler.getTopic()), any(), any());
+        .saveGossipMessageDecodingError(eq(topicHandler.getTopic()), any(), any(), any());
     asyncRunner.executeQueuedActions();
 
     assertThatSafeFuture(result).isCompletedWithValue(ValidationResult.Invalid);
