additional log information around invalid payloads (#15754)

* additional log information around invalid payloads

* fix test with reversed require.ErrorIs args

---------

Co-authored-by: Kasey Kirkham <kasey@users.noreply.github.com>

beacon-chain/blockchain/execution_engine.go

@@ -16,7 +16,7 @@ import (
 	"github.com/OffchainLabs/prysm/v6/beacon-chain/state"
 	"github.com/OffchainLabs/prysm/v6/config/features"
 	"github.com/OffchainLabs/prysm/v6/config/params"
-	consensusblocks "github.com/OffchainLabs/prysm/v6/consensus-types/blocks"
+	blocktypes "github.com/OffchainLabs/prysm/v6/consensus-types/blocks"
 	"github.com/OffchainLabs/prysm/v6/consensus-types/interfaces"
 	payloadattribute "github.com/OffchainLabs/prysm/v6/consensus-types/payload-attribute"
 	"github.com/OffchainLabs/prysm/v6/consensus-types/primitives"
@@ -218,24 +218,18 @@ func (s *Service) getPayloadHash(ctx context.Context, root []byte) ([32]byte, er
 
 // notifyNewPayload signals execution engine on a new payload.
 // It returns true if the EL has returned VALID for the block
-func (s *Service) notifyNewPayload(ctx context.Context, preStateVersion int,
+// stVersion should represent the version of the pre-state; header should also be from the pre-state.
-	preStateHeader interfaces.ExecutionData, blk interfaces.ReadOnlySignedBeaconBlock) (bool, error) {
+func (s *Service) notifyNewPayload(ctx context.Context, stVersion int, header interfaces.ExecutionData, blk blocktypes.ROBlock) (bool, error) {
 	ctx, span := trace.StartSpan(ctx, "blockChain.notifyNewPayload")
 	defer span.End()
 
 	// Execution payload is only supported in Bellatrix and beyond. Pre
 	// merge blocks are never optimistic
-	if blk == nil {
+	if stVersion < version.Bellatrix {
-		return false, errors.New("signed beacon block can't be nil")
-	}
-	if preStateVersion < version.Bellatrix {
 		return true, nil
 	}
-	if err := consensusblocks.BeaconBlockIsNil(blk); err != nil {
-		return false, err
-	}
 	body := blk.Block().Body()
-	enabled, err := blocks.IsExecutionEnabledUsingHeader(preStateHeader, body)
+	enabled, err := blocks.IsExecutionEnabledUsingHeader(header, body)
 	if err != nil {
 		return false, errors.Wrap(invalidBlock{error: err}, "could not determine if execution is enabled")
 	}
@@ -268,28 +262,32 @@ func (s *Service) notifyNewPayload(ctx context.Context, preStateVersion int,
 			return false, errors.New("nil execution requests")
 		}
 	}
-	lastValidHash, err = s.cfg.ExecutionEngineCaller.NewPayload(ctx, payload, versionedHashes, parentRoot, requests)
 
-	switch {
+	lastValidHash, err = s.cfg.ExecutionEngineCaller.NewPayload(ctx, payload, versionedHashes, parentRoot, requests)
-	case err == nil:
+	if err == nil {
 		newPayloadValidNodeCount.Inc()
 		return true, nil
-	case errors.Is(err, execution.ErrAcceptedSyncingPayloadStatus):
+	}
+	logFields := logrus.Fields{
+		"slot":             blk.Block().Slot(),
+		"parentRoot":       fmt.Sprintf("%#x", parentRoot),
+		"root":             fmt.Sprintf("%#x", blk.Root()),
+		"payloadBlockHash": fmt.Sprintf("%#x", bytesutil.Trunc(payload.BlockHash())),
+	}
+	if errors.Is(err, execution.ErrAcceptedSyncingPayloadStatus) {
 		newPayloadOptimisticNodeCount.Inc()
-		log.WithFields(logrus.Fields{
+		log.WithFields(logFields).Info("Called new payload with optimistic block")
-			"slot":             blk.Block().Slot(),
-			"payloadBlockHash": fmt.Sprintf("%#x", bytesutil.Trunc(payload.BlockHash())),
-		}).Info("Called new payload with optimistic block")
 		return false, nil
-	case errors.Is(err, execution.ErrInvalidPayloadStatus):
+	}
-		lvh := bytesutil.ToBytes32(lastValidHash)
+	if errors.Is(err, execution.ErrInvalidPayloadStatus) {
+		log.WithFields(logFields).WithError(err).Error("Invalid payload status")
 		return false, invalidBlock{
 			error:         ErrInvalidPayload,
-			lastValidHash: lvh,
+			lastValidHash: bytesutil.ToBytes32(lastValidHash),
 		}
-	default:
-		return false, errors.WithMessage(ErrUndefinedExecutionEngineError, err.Error())
 	}
+	log.WithFields(logFields).WithError(err).Error("Unexpected execution engine error")
+	return false, errors.WithMessage(ErrUndefinedExecutionEngineError, err.Error())
 }
 
 // reportInvalidBlock deals with the event that an invalid block was detected by the execution layer

beacon-chain/blockchain/execution_engine_test.go

@@ -481,33 +481,12 @@ func Test_NotifyNewPayload(t *testing.T) {
 	phase0State, _ := util.DeterministicGenesisState(t, 1)
 	altairState, _ := util.DeterministicGenesisStateAltair(t, 1)
 	bellatrixState, _ := util.DeterministicGenesisStateBellatrix(t, 2)
-	a := &ethpb.SignedBeaconBlockAltair{
+	a := util.NewBeaconBlockAltair()
-		Block: &ethpb.BeaconBlockAltair{
-			Body: &ethpb.BeaconBlockBodyAltair{},
-		},
-	}
 	altairBlk, err := consensusblocks.NewSignedBeaconBlock(a)
 	require.NoError(t, err)
-	blk := &ethpb.SignedBeaconBlockBellatrix{
+	blk := util.NewBeaconBlockBellatrix()
-		Block: &ethpb.BeaconBlockBellatrix{
+	blk.Block.Slot = 1
-			Slot: 1,
+	blk.Block.Body.ExecutionPayload.BlockNumber = 1
-			Body: &ethpb.BeaconBlockBodyBellatrix{
-				ExecutionPayload: &v1.ExecutionPayload{
-					BlockNumber:   1,
-					ParentHash:    make([]byte, fieldparams.RootLength),
-					FeeRecipient:  make([]byte, fieldparams.FeeRecipientLength),
-					StateRoot:     make([]byte, fieldparams.RootLength),
-					ReceiptsRoot:  make([]byte, fieldparams.RootLength),
-					LogsBloom:     make([]byte, fieldparams.LogsBloomLength),
-					PrevRandao:    make([]byte, fieldparams.RootLength),
-					ExtraData:     make([]byte, 0),
-					BaseFeePerGas: make([]byte, fieldparams.RootLength),
-					BlockHash:     make([]byte, fieldparams.RootLength),
-					Transactions:  make([][]byte, 0),
-				},
-			},
-		},
-	}
 	bellatrixBlk, err := consensusblocks.NewSignedBeaconBlock(util.HydrateSignedBeaconBlockBellatrix(blk))
 	require.NoError(t, err)
 	st := params.BeaconConfig().SlotsPerEpoch.Mul(uint64(epochsSinceFinalitySaveHotStateDB))
@@ -544,12 +523,6 @@ func Test_NotifyNewPayload(t *testing.T) {
 			blk:            altairBlk,
 			isValidPayload: true,
 		},
-		{
-			name:           "nil beacon block",
-			postState:      bellatrixState,
-			errString:      "signed beacon block can't be nil",
-			isValidPayload: false,
-		},
 		{
 			name:           "new payload with optimistic block",
 			postState:      bellatrixState,
@@ -576,15 +549,8 @@ func Test_NotifyNewPayload(t *testing.T) {
 			name:      "altair pre state, happy case",
 			postState: bellatrixState,
 			blk: func() interfaces.ReadOnlySignedBeaconBlock {
-				blk := &ethpb.SignedBeaconBlockBellatrix{
+				blk := util.NewBeaconBlockBellatrix()
-					Block: &ethpb.BeaconBlockBellatrix{
+				blk.Block.Body.ExecutionPayload.ParentHash = bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength)
-						Body: &ethpb.BeaconBlockBodyBellatrix{
-							ExecutionPayload: &v1.ExecutionPayload{
-								ParentHash: bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength),
-							},
-						},
-					},
-				}
 				b, err := consensusblocks.NewSignedBeaconBlock(blk)
 				require.NoError(t, err)
 				return b
@@ -595,24 +561,7 @@ func Test_NotifyNewPayload(t *testing.T) {
 			name:      "not at merge transition",
 			postState: bellatrixState,
 			blk: func() interfaces.ReadOnlySignedBeaconBlock {
-				blk := &ethpb.SignedBeaconBlockBellatrix{
+				blk := util.NewBeaconBlockBellatrix()
-					Block: &ethpb.BeaconBlockBellatrix{
-						Body: &ethpb.BeaconBlockBodyBellatrix{
-							ExecutionPayload: &v1.ExecutionPayload{
-								ParentHash:    make([]byte, fieldparams.RootLength),
-								FeeRecipient:  make([]byte, fieldparams.FeeRecipientLength),
-								StateRoot:     make([]byte, fieldparams.RootLength),
-								ReceiptsRoot:  make([]byte, fieldparams.RootLength),
-								LogsBloom:     make([]byte, fieldparams.LogsBloomLength),
-								PrevRandao:    make([]byte, fieldparams.RootLength),
-								ExtraData:     make([]byte, 0),
-								BaseFeePerGas: make([]byte, fieldparams.RootLength),
-								BlockHash:     make([]byte, fieldparams.RootLength),
-								Transactions:  make([][]byte, 0),
-							},
-						},
-					},
-				}
 				b, err := consensusblocks.NewSignedBeaconBlock(blk)
 				require.NoError(t, err)
 				return b
@@ -623,15 +572,8 @@ func Test_NotifyNewPayload(t *testing.T) {
 			name:      "happy case",
 			postState: bellatrixState,
 			blk: func() interfaces.ReadOnlySignedBeaconBlock {
-				blk := &ethpb.SignedBeaconBlockBellatrix{
+				blk := util.NewBeaconBlockBellatrix()
-					Block: &ethpb.BeaconBlockBellatrix{
+				blk.Block.Body.ExecutionPayload.ParentHash = bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength)
-						Body: &ethpb.BeaconBlockBodyBellatrix{
-							ExecutionPayload: &v1.ExecutionPayload{
-								ParentHash: bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength),
-							},
-						},
-					},
-				}
 				b, err := consensusblocks.NewSignedBeaconBlock(blk)
 				require.NoError(t, err)
 				return b
@@ -642,15 +584,8 @@ func Test_NotifyNewPayload(t *testing.T) {
 			name:      "undefined error from ee",
 			postState: bellatrixState,
 			blk: func() interfaces.ReadOnlySignedBeaconBlock {
-				blk := &ethpb.SignedBeaconBlockBellatrix{
+				blk := util.NewBeaconBlockBellatrix()
-					Block: &ethpb.BeaconBlockBellatrix{
+				blk.Block.Body.ExecutionPayload.ParentHash = bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength)
-						Body: &ethpb.BeaconBlockBodyBellatrix{
-							ExecutionPayload: &v1.ExecutionPayload{
-								ParentHash: bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength),
-							},
-						},
-					},
-				}
 				b, err := consensusblocks.NewSignedBeaconBlock(blk)
 				require.NoError(t, err)
 				return b
@@ -662,15 +597,8 @@ func Test_NotifyNewPayload(t *testing.T) {
 			name:      "invalid block hash error from ee",
 			postState: bellatrixState,
 			blk: func() interfaces.ReadOnlySignedBeaconBlock {
-				blk := &ethpb.SignedBeaconBlockBellatrix{
+				blk := util.NewBeaconBlockBellatrix()
-					Block: &ethpb.BeaconBlockBellatrix{
+				blk.Block.Body.ExecutionPayload.ParentHash = bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength)
-						Body: &ethpb.BeaconBlockBodyBellatrix{
-							ExecutionPayload: &v1.ExecutionPayload{
-								ParentHash: bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength),
-							},
-						},
-					},
-				}
 				b, err := consensusblocks.NewSignedBeaconBlock(blk)
 				require.NoError(t, err)
 				return b
@@ -701,7 +629,9 @@ func Test_NotifyNewPayload(t *testing.T) {
 			require.NoError(t, service.cfg.ForkChoiceStore.InsertNode(ctx, state, blkRoot))
 			postVersion, postHeader, err := getStateVersionAndPayload(tt.postState)
 			require.NoError(t, err)
-			isValidPayload, err := service.notifyNewPayload(ctx, postVersion, postHeader, tt.blk)
+			rob, err := consensusblocks.NewROBlock(tt.blk)
+			require.NoError(t, err)
+			isValidPayload, err := service.notifyNewPayload(ctx, postVersion, postHeader, rob)
 			if tt.errString != "" {
 				require.ErrorContains(t, tt.errString, err)
 				if tt.invalidBlock {
@@ -725,17 +655,12 @@ func Test_NotifyNewPayload_SetOptimisticToValid(t *testing.T) {
 	ctx := tr.ctx
 
 	bellatrixState, _ := util.DeterministicGenesisStateBellatrix(t, 2)
-	blk := &ethpb.SignedBeaconBlockBellatrix{
+	blk := util.NewBeaconBlockBellatrix()
-		Block: &ethpb.BeaconBlockBellatrix{
+	blk.Block.Body.ExecutionPayload.ParentHash = bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength)
-			Body: &ethpb.BeaconBlockBodyBellatrix{
-				ExecutionPayload: &v1.ExecutionPayload{
-					ParentHash: bytesutil.PadTo([]byte{'a'}, fieldparams.RootLength),
-				},
-			},
-		},
-	}
 	bellatrixBlk, err := consensusblocks.NewSignedBeaconBlock(blk)
 	require.NoError(t, err)
+	rob, err := consensusblocks.NewROBlock(bellatrixBlk)
+	require.NoError(t, err)
 	e := &mockExecution.EngineClient{BlockByHashMap: map[[32]byte]*v1.ExecutionBlock{}}
 	e.BlockByHashMap[[32]byte{'a'}] = &v1.ExecutionBlock{
 		Header: gethtypes.Header{
@@ -752,7 +677,7 @@ func Test_NotifyNewPayload_SetOptimisticToValid(t *testing.T) {
 	service.cfg.ExecutionEngineCaller = e
 	postVersion, postHeader, err := getStateVersionAndPayload(bellatrixState)
 	require.NoError(t, err)
-	validated, err := service.notifyNewPayload(ctx, postVersion, postHeader, bellatrixBlk)
+	validated, err := service.notifyNewPayload(ctx, postVersion, postHeader, rob)
 	require.NoError(t, err)
 	require.Equal(t, true, validated)
 }

beacon-chain/execution/engine_client.go

@@ -142,10 +142,9 @@ var ErrEmptyBlockHash = errors.New("Block hash is empty 0x0000...")
 func (s *Service) NewPayload(ctx context.Context, payload interfaces.ExecutionData, versionedHashes []common.Hash, parentBlockRoot *common.Hash, executionRequests *pb.ExecutionRequests) ([]byte, error) {
 	ctx, span := trace.StartSpan(ctx, "powchain.engine-api-client.NewPayload")
 	defer span.End()
-	start := time.Now()
+	defer func(start time.Time) {
-	defer func() {
 		newPayloadLatency.Observe(float64(time.Since(start).Milliseconds()))
-	}()
+	}(time.Now())
 
 	d := time.Now().Add(time.Duration(params.BeaconConfig().ExecutionEngineTimeoutValue) * time.Second)
 	ctx, cancel := context.WithDeadline(ctx, d)
@@ -183,7 +182,10 @@ func (s *Service) NewPayload(ctx context.Context, payload interfaces.ExecutionDa
 		return nil, errors.New("unknown execution data type")
 	}
 	if result.ValidationError != "" {
-		log.WithError(errors.New(result.ValidationError)).Error("Got a validation error in newPayload")
+		log.WithField("status", result.Status.String()).
+			WithField("parentRoot", fmt.Sprintf("%#x", parentBlockRoot)).
+			WithError(errors.New(result.ValidationError)).
+			Error("Got a validation error in newPayload")
 	}
 	switch result.Status {
 	case pb.PayloadStatus_INVALID_BLOCK_HASH:
@@ -195,7 +197,7 @@ func (s *Service) NewPayload(ctx context.Context, payload interfaces.ExecutionDa
 	case pb.PayloadStatus_VALID:
 		return result.LatestValidHash, nil
 	default:
-		return nil, ErrUnknownPayloadStatus
+		return nil, errors.Wrapf(ErrUnknownPayloadStatus, "unknown payload status: %s", result.Status.String())
 	}
 }
 

beacon-chain/execution/engine_client_test.go

@@ -928,7 +928,7 @@ func TestClient_HTTP(t *testing.T) {
 		wrappedPayload, err := blocks.WrappedExecutionPayload(execPayload)
 		require.NoError(t, err)
 		resp, err := client.NewPayload(ctx, wrappedPayload, []common.Hash{}, &common.Hash{}, nil)
-		require.ErrorIs(t, ErrUnknownPayloadStatus, err)
+		require.ErrorIs(t, err, ErrUnknownPayloadStatus)
 		require.DeepEqual(t, []uint8(nil), resp)
 	})
 	t.Run(BlockByNumberMethod, func(t *testing.T) {

changelog/kasey_log-invalid-ee-root.md

@@ -0,0 +1,2 @@
+### Ignored
+- Adding context to logs around execution engine notification failures.