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 index 9abb88efc87..b4a9bd24556 100644 --- 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 index 2eea311ffbb..f0cd3fa4dba 100644 --- 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 arrivalTimestamp, final Bytes originalMessage) { + final String topic, + final Optional arrivalTimestamp, + final Bytes originalMessage, + final Throwable error) { if (!enabled) { return; } @@ -70,16 +73,19 @@ 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 arrivalTimestamp, final Bytes decodedMessage) { + final String topic, + final Optional arrivalTimestamp, + final Bytes decodedMessage, + final Optional reason) { if (!enabled) { return; } @@ -87,57 +93,73 @@ public void saveGossipRejectedMessageToFile( 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 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 index 32c506997e4..a4965f33c3e 100644 --- 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 arrivalTimestamp, final Bytes originalMessage) {} + final String topic, + final Optional arrivalTimestamp, + final Bytes originalMessage, + final Throwable error) {} @Override public void saveGossipRejectedMessageToFile( - final String topic, final Optional arrivalTimestamp, final Bytes decodedMessage) {} + final String topic, + final Optional arrivalTimestamp, + final Bytes decodedMessage, + final Optional 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 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 index 7a36fda287e..c9bf3db7612 100644 --- 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,8 +307,9 @@ 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); @@ -316,7 +317,9 @@ void onBlock_consensusValidationShouldNotResolveWhenStateTransitionFails() .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 index 877c9844168..6e143850ce3 100644 --- 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 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 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 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 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 index 7129962ae68..76b54d32b58 100644 --- 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 index 6ca1be93498..02bd0d9aa86 100644 --- 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 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 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 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 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);