diff --git a/ethereum/spec/src/main/java/tech/pegasys/teku/spec/logic/versions/deneb/blobs/BlobSidecarsAndValidationResult.java b/ethereum/spec/src/main/java/tech/pegasys/teku/spec/logic/versions/deneb/blobs/BlobSidecarsAndValidationResult.java index fa5a45d802e..09bdb79ef8e 100644 --- a/ethereum/spec/src/main/java/tech/pegasys/teku/spec/logic/versions/deneb/blobs/BlobSidecarsAndValidationResult.java +++ b/ethereum/spec/src/main/java/tech/pegasys/teku/spec/logic/versions/deneb/blobs/BlobSidecarsAndValidationResult.java @@ -126,7 +126,7 @@ public int hashCode() { public String toLogString() { return String.format( - "result %s, blob sidecars: %d, cause: %s", + "%s, blob sidecars: %d, cause: %s", validationResult, blobSidecars.size(), cause.map(ExceptionUtil::getMessageOrSimpleName)); } } diff --git a/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockImportPerformance.java b/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockImportPerformance.java index ac0b15ffccb..5bfbb853a1f 100644 --- a/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockImportPerformance.java +++ b/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockImportPerformance.java @@ -129,6 +129,10 @@ public void processingComplete( totalProcessingDuration, TOTAL_PROCESSING_TIME_LABEL, resultMetricLabelValue), (totalDuration, timings) -> eventLogger.lateBlockImport( - block.getRoot(), block.getSlot(), block.getProposerIndex(), timings)); + block.getRoot(), + block.getSlot(), + block.getProposerIndex(), + timings, + resultMetricLabelValue)); } } diff --git a/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockManager.java b/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockManager.java index 78afb7dd65a..aa51fbd841b 100644 --- a/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockManager.java +++ b/ethereum/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockManager.java @@ -30,6 +30,7 @@ import tech.pegasys.teku.spec.datastructures.execution.ExecutionPayloadSummary; import tech.pegasys.teku.spec.datastructures.validator.BroadcastValidationLevel; import tech.pegasys.teku.spec.logic.common.statetransition.results.BlockImportResult; +import tech.pegasys.teku.spec.logic.common.statetransition.results.BlockImportResult.FailureReason; import tech.pegasys.teku.statetransition.blobs.BlobSidecarManager.RemoteOrigin; import tech.pegasys.teku.statetransition.blobs.BlockBlobSidecarsTrackersPool; import tech.pegasys.teku.statetransition.util.FutureItems; @@ -289,9 +290,7 @@ private SafeFuture handleBlockImport( FailedPayloadExecutionSubscriber::onPayloadExecutionFailed, block); break; case FAILED_DATA_AVAILABILITY_CHECK_NOT_AVAILABLE: - LOG.warn( - "Unable to import block {} due to data unavailability", - block.toLogString()); + logFailedBlockImport(block, result.getFailureReason()); blockBlobSidecarsTrackersPool.enableBlockImportOnCompletion(block); break; case FAILED_DATA_AVAILABILITY_CHECK_INVALID: @@ -300,7 +299,7 @@ private SafeFuture handleBlockImport( // pool and discard. // If next block builds on top of this one, we will re-download all blobSidecars // and block again via RPC by root. - LOG.warn("Unable to import block {} due to invalid data", block.toLogString()); + logFailedBlockImport(block, result.getFailureReason()); blockBlobSidecarsTrackersPool.removeAllForBlock(block.getRoot()); break; case FAILED_BROADCAST_VALIDATION: @@ -314,16 +313,18 @@ private SafeFuture handleBlockImport( FAILED_WEAK_SUBJECTIVITY_CHECKS, DESCENDANT_OF_INVALID_BLOCK, INTERNAL_ERROR: - LOG.trace( - "Unable to import block for reason {}: {}", - result.getFailureReason(), - block); + logFailedBlockImport(block, result.getFailureReason()); dropInvalidBlock(block, result); } } }); } + private void logFailedBlockImport( + final SignedBeaconBlock block, final FailureReason failureReason) { + LOG.trace("Unable to import block for reason {}: {}", failureReason, block); + } + private String getExecutionPayloadInfoForLog(final SignedBeaconBlock block) { return block .getMessage() 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 6c4d1973643..a4bf4ad30c7 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 @@ -538,7 +538,7 @@ private BlockImportResult importBlockAndState( case VALID, NOT_REQUIRED -> LOG.debug( "blobSidecars validation result: {}", blobSidecarsAndValidationResult::toLogString); case NOT_AVAILABLE -> { - LOG.warn( + LOG.debug( "blobSidecars validation result: {}", blobSidecarsAndValidationResult::toLogString); return BlockImportResult.failedDataAvailabilityCheckNotAvailable( blobSidecarsAndValidationResult.getCause()); diff --git a/ethereum/statetransition/src/test/java/tech/pegasys/teku/statetransition/block/BlockManagerTest.java b/ethereum/statetransition/src/test/java/tech/pegasys/teku/statetransition/block/BlockManagerTest.java index d2648826cfa..a9b9928856c 100644 --- a/ethereum/statetransition/src/test/java/tech/pegasys/teku/statetransition/block/BlockManagerTest.java +++ b/ethereum/statetransition/src/test/java/tech/pegasys/teku/statetransition/block/BlockManagerTest.java @@ -770,7 +770,8 @@ void onValidateAndImportBlock_shouldLogSlowImport() { + TRANSACTION_COMMITTED_EVENT_LABEL + " +0ms, " + COMPLETED_EVENT_LABEL - + " +0ms"); + + " +0ms", + "success"); } @Test diff --git a/infrastructure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/EventLogger.java b/infrastructure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/EventLogger.java index 6ae514219bb..b2eaa0c55a0 100644 --- a/infrastructure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/EventLogger.java +++ b/infrastructure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/EventLogger.java @@ -273,11 +273,15 @@ public void terminalPowBlockTtdEta(final UInt256 ttd, final Duration eta, final } public void lateBlockImport( - final Bytes32 root, final UInt64 slot, final UInt64 proposer, final String timings) { - String slowBlockLog = + final Bytes32 root, + final UInt64 slot, + final UInt64 proposer, + final String timings, + final String result) { + final String slowBlockLog = String.format( - "Late Block Import *** Block: %s proposer %s %s", - LogFormatter.formatBlock(slot, root), proposer, timings); + "Late Block Import *** Block: %s Proposer: %s Result: %s %s", + LogFormatter.formatBlock(slot, root), proposer, result, timings); warn(slowBlockLog, Color.YELLOW); }