Improve logging (#8169)

Consensys · Apr 4, 2024 · 5ac0f2d · 5ac0f2d
1 parent 64007a3
commit 5ac0f2d
Show file tree

Hide file tree

Showing 6 changed files with 26 additions and 16 deletions.
diff --git a/...va/tech/pegasys/teku/spec/logic/versions/deneb/blobs/BlobSidecarsAndValidationResult.java b/...va/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/...nsition/src/main/java/tech/pegasys/teku/statetransition/block/BlockImportPerformance.java b/...nsition/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/...m/statetransition/src/main/java/tech/pegasys/teku/statetransition/block/BlockManager.java b/...m/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<BlockImportResult> 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<BlockImportResult> 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<BlockImportResult> 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/...tatetransition/src/main/java/tech/pegasys/teku/statetransition/forkchoice/ForkChoice.java b/...tatetransition/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/...atetransition/src/test/java/tech/pegasys/teku/statetransition/block/BlockManagerTest.java b/...atetransition/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/...structure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/EventLogger.java b/...structure/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);
   }