Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

beacon/log: augment logs with block roots #5675

Merged
merged 7 commits into from
Apr 29, 2020
Merged

beacon/log: augment logs with block roots #5675

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
3f0c28d
beacon/log: augment synced log with block root and finalized root
q9f Apr 29, 2020
98cacf0
beacon/log: augment initial sync log with block root
q9f Apr 29, 2020
28ef01c
beacon/sync: degrade pending block log to DEBUG level
q9f Apr 29, 2020
3054e2c
beacon/log: restore info level for state transition
q9f Apr 29, 2020
5d4d69f
beacon/log: improve info logging
q9f Apr 29, 2020
9e1d7ae
Merge branch 'master' into q9-log-block
q9f Apr 29, 2020
1c63401
Merge branch 'master' into q9-log-block
q9f Apr 29, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 11 additions & 1 deletion beacon-chain/blockchain/log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package blockchain

import (
"encoding/hex"
"fmt"

ethpb "github.com/prysmaticlabs/ethereumapis/eth/v1alpha1"
Expand All @@ -15,7 +16,6 @@ var log = logrus.WithField("prefix", "blockchain")
// logs state transition related data every slot.
func logStateTransitionData(b *ethpb.BeaconBlock) {
log.WithFields(logrus.Fields{
"slot": b.Slot,
"attestations": len(b.Body.Attestations),
"deposits": len(b.Body.Deposits),
"attesterSlashings": len(b.Body.AttesterSlashings),
Expand All @@ -24,6 +24,16 @@ func logStateTransitionData(b *ethpb.BeaconBlock) {
}).Info("Finished applying state transition")
}

func logBlockSyncStatus(block *ethpb.BeaconBlock, blockRoot [32]byte, finalized *ethpb.Checkpoint) {
log.WithFields(logrus.Fields{
"slot": block.Slot,
"block": fmt.Sprintf("0x%s...", hex.EncodeToString(blockRoot[:])[:8]),
"epoch": helpers.SlotToEpoch(block.Slot),
"finalizedEpoch": finalized.Epoch,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My argument for this is 99% of users/non developers don't care about finalizedEpoch and finalizedRoot when syncing. So perhaps move it to debug?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not seeing the finality is my main pain point. Everyone should care about finality :)

Burying it in DEBUG level would be very unfortunate due to the noise.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Marinated a bit more with this. I'm on board with this rationale

"finalizedRoot": fmt.Sprintf("0x%s...", hex.EncodeToString(finalized.Root[:])[:8]),
}).Info("Synced new block")
}

func logEpochData(beaconState *stateTrie.BeaconState) {
log.WithFields(logrus.Fields{
"epoch": helpers.CurrentEpoch(beaconState),
Expand Down
2 changes: 1 addition & 1 deletion beacon-chain/blockchain/process_block.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -77,7 +77,7 @@ func (s *Service) onBlock(ctx context.Context, signed *ethpb.SignedBeaconBlock)
log.WithFields(logrus.Fields{
"slot": b.Slot,
"root": fmt.Sprintf("0x%s...", hex.EncodeToString(root[:])[:8]),
}).Info("Executing state transition on block")
}).Debug("Executing state transition on block")
q9f marked this conversation as resolved.
Show resolved Hide resolved

postState, err := state.ExecuteStateTransition(ctx, preState, signed)
if err != nil {
Expand Down
6 changes: 6 additions & 0 deletions beacon-chain/blockchain/receive_block.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,6 +118,9 @@ func (s *Service) ReceiveBlockNoPubsub(ctx context.Context, block *ethpb.SignedB
// Reports on block and fork choice metrics.
reportSlotMetrics(blockCopy.Block.Slot, s.headSlot(), s.CurrentSlot(), s.finalizedCheckpt)

// Log block sync status.
logBlockSyncStatus(blockCopy.Block, root, s.finalizedCheckpt)

// Log state transition data.
logStateTransitionData(blockCopy.Block)

Expand Down Expand Up @@ -168,6 +171,9 @@ func (s *Service) ReceiveBlockNoPubsubForkchoice(ctx context.Context, block *eth
// Reports on block and fork choice metrics.
reportSlotMetrics(blockCopy.Block.Slot, s.headSlot(), s.CurrentSlot(), s.finalizedCheckpt)

// Log block sync status.
logBlockSyncStatus(blockCopy.Block, root, s.finalizedCheckpt)

// Log state transition data.
logStateTransitionData(blockCopy.Block)

Expand Down
1 change: 1 addition & 0 deletions beacon-chain/sync/initial-sync/BUILD.bazel
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ go_library(
"//beacon-chain/db:go_default_library",
"//beacon-chain/flags:go_default_library",
"//beacon-chain/p2p:go_default_library",
"//beacon-chain/state/stateutil:go_default_library",
"//beacon-chain/sync:go_default_library",
"//proto/beacon/p2p/v1:go_default_library",
"//shared:go_default_library",
Expand Down
10 changes: 9 additions & 1 deletion beacon-chain/sync/initial-sync/round_robin.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package initialsync

import (
"context"
"encoding/hex"
"fmt"
"io"
"time"
Expand All @@ -15,6 +16,7 @@ import (
"github.com/prysmaticlabs/prysm/beacon-chain/core/helpers"
"github.com/prysmaticlabs/prysm/beacon-chain/core/state"
"github.com/prysmaticlabs/prysm/beacon-chain/p2p"
"github.com/prysmaticlabs/prysm/beacon-chain/state/stateutil"
prysmsync "github.com/prysmaticlabs/prysm/beacon-chain/sync"
p2ppb "github.com/prysmaticlabs/prysm/proto/beacon/p2p/v1"
"github.com/prysmaticlabs/prysm/shared/bytesutil"
Expand Down Expand Up @@ -179,14 +181,20 @@ func (s *Service) logSyncStatus(genesis time.Time, blk *eth.BeaconBlock, counter
rate = 1
}
timeRemaining := time.Duration(float64(helpers.SlotsSince(genesis)-blk.Slot)/rate) * time.Second
blockRoot := "unknown"
root, err := stateutil.BlockRoot(blk)
if err == nil {
blockRoot = fmt.Sprintf("0x%s...", hex.EncodeToString(root[:])[:8])
}
log.WithField(
"peers",
len(s.p2p.Peers().Connected()),
).WithField(
"blocksPerSecond",
fmt.Sprintf("%.1f", rate),
).Infof(
"Processing block %d/%d - estimated time remaining %s",
"Processing block %s %d/%d - estimated time remaining %s",
blockRoot,
blk.Slot,
helpers.SlotsSince(genesis),
timeRemaining,
Expand Down
2 changes: 1 addition & 1 deletion beacon-chain/sync/pending_blocks_queue.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -130,7 +130,7 @@ func (r *Service) processPendingBlocks(ctx context.Context) error {
log.WithFields(logrus.Fields{
"slot": s,
"blockRoot": hex.EncodeToString(bytesutil.Trunc(blkRoot[:])),
}).Info("Processed pending block and cleared it in cache")
}).Debug("Processed pending block and cleared it in cache")
q9f marked this conversation as resolved.
Show resolved Hide resolved

span.End()
}
Expand Down