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.

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

Improve vc logs #13573

Merged
merged 11 commits into from
Feb 8, 2024
Merged

Improve vc logs #13573

merged 11 commits into from
Feb 8, 2024

Conversation

rkapka
Copy link
Contributor

@rkapka rkapka commented Feb 1, 2024

What type of PR is this?

Other

What does this PR do? Why is it needed?

The purpose of this PR is to make validator logs more clean/consistent/useful:

  • Duties
    • Added a Schedule for epoch log before logs for individual slot duties, which allows to extract the totalAttestersInEpoch log that was repeated for every slot. The new log also displays the proposer count.
    • Removed timeTillDuty because I don't think it's useful.
    • Merged Attestation schedule and Proposal schedule into a single Duties schedule log.
  • Submitted atts
    • Validator pubkeys instead of indices are displayed. This is consistent with what we when logging duties

@rkapka rkapka added the v5 label Feb 1, 2024
@rkapka rkapka requested a review from a team as a code owner February 1, 2024 18:02
@rkapka rkapka added the Blocked Blocked by research or external factors label Feb 1, 2024
Comment on lines 237 to 241
h, err := hash.Proto(data)
r, err := data.HashTreeRoot()
Copy link
Member

Choose a reason for hiding this comment

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

Have we benchmarked against the two?

@nalepae
Copy link
Contributor

nalepae commented Feb 2, 2024

Duties schedule spam:

  INFO validator: Validator activated index=1567133 pubKey=0x8b508ff750a3 publicKey=0x8b508ff750a3 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xae80a236b3f7 status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567137 pubKey=0xb83fc46c5fc9 publicKey=0xb83fc46c5fc9 status=ACTIVE
[2024-02-02 16:41:08]  INFO validator: Schedule for epoch 28609 attesterCount=18 proposerCount=0
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0x8d6d2b60eac7] slot=915488 slotInEpoch=0
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0x8b508ff750a3] slot=915489 slotInEpoch=1
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0xaa3ec86b3d54] slot=915491 slotInEpoch=3
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0x95a4b504ba2f] slot=915492 slotInEpoch=4
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0xb92d55e0157f] slot=915494 slotInEpoch=6
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0x93ae299ee8c2] slot=915499 slotInEpoch=11
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0xaf3f7a466278] slot=915500 slotInEpoch=12
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0x90c409ed5de3] slot=915501 slotInEpoch=13
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=2 attesterPubkeys=[0x802f24fa9f80 0xa17524bcf06d] slot=915502 slotInEpoch=14
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=2 attesterPubkeys=[0x80f408a41341 0xad975197a132] slot=915503 slotInEpoch=15
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0x8ae1e4efc47f] slot=915504 slotInEpoch=16
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=1 attesterPubkeys=[0x84d7fa31925c] slot=915508 slotInEpoch=20
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=2 attesterPubkeys=[0xb7519fc3ec1f 0xb83fc46c5fc9] slot=915512 slotInEpoch=24
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule
[2024-02-02 16:41:08]  INFO validator: Duties schedule attesterCount=2 attesterPubkeys=[0x8df7346b379b 0x8c3683846835] slot=915518 slotInEpoch=30
[2024-02-02 16:41:08]  INFO validator: Duties schedule

What's the point of Submitting attestation vs. Submitted new attestations?

 INFO Submitting attestation 0xd7937228c74b3d7ac7354b6d4d704697b60dac685b140286fb1e003ac4afcef0
[2024-02-02 16:44:04]  INFO validator: Submitted new attestations aggregatorPubkeys=[] attesterPubkeys=[0xb83fc46c5fc9] beaconBlockRoot=0x179391d5d835 committeeIndex=22 slot=915520 sourceEpoch=28609 sourceRoot=0xcb1bf33d1c96 targetEpoch=28610 targetRoot=0x179391d5d835
[2024-02-02 16:44:40]  INFO Submitting attestation 0xb3372090dc95c56e7fd3e1cb5e392a2b50ec6a54b4d6d4f25b158cd4af2d3689
[2024-02-02 16:44:40]  INFO validator: Submitted new attestations aggregatorPubkeys=[] attesterPubkeys=[0x8c3683846835] beaconBlockRoot=0xc55dca84219f committeeIndex=54 slot=915523 sourceEpoch=28609 sourceRoot=0xcb1bf33d1c96 targetEpoch=28610 targetRoot=0x179391d5d835
[2024-02-02 16:44:52]  INFO Submitting attestation 0xe0eb51ed68c075d43d28cc4581747aca366bf17b8b57a56f65963433cfab8b27
[2024-02-02 16:44:52]  INFO validator: Submitted new attestations aggregatorPubkeys=[] attesterPubkeys=[0x93ae299ee8c2] beaconBlockRoot=0x92c4064732e2 committeeIndex=43 slot=915524 sourceEpoch=28609 sourceRoot=0xcb1bf33d1c96 targetEpoch=28610 targetRoot=0x179391d5d835
[2024-02-02 16:45:04]  INFO Submitting attestation 0x97299753038d49a12f10bd153d79fc2a9c86a1a31710267de42c9df736bf67a1
[2024-02-02 16:45:04]  INFO validator: Submitted new attestations aggregatorPubkeys=[] attesterPubkeys=[0xaf3f7a466278] beaconBlockRoot=0x6a087ca8d661 committeeIndex=6 slot=915525 sourceEpoch=28609 sourceRoot=0xcb1bf33d1c96 targetEpoch=28610 targetRoot=0x179391d5d835
[2024-02-02 16:45:40]  INFO Submitting attestation 0x4c78cf774263942eea6334d9d530ac388e5d0b1462ddd47f7905544b6b1cf78c

@nalepae
Copy link
Contributor

nalepae commented Feb 2, 2024

Also, I'm wondering if the Validating for public key logs are useful, since the same kind of logs (with more detailed information like the status) are displayed just after:

[2024-02-02 16:41:07]  INFO validator: Beacon chain started genesisTime=2023-09-28 14:00:00 +0200 CEST
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x80f408a41341
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x8ae1e4efc47f
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x8d0af7e73bde
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xa246821f8b14
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x84d7fa31925c
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xad975197a132
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xaa3ec86b3d54
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xaf3f7a466278
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x8df7346b379b
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x8c3683846835
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x90c409ed5de3
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xa5e8b3e6cf74
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xa4b4eb53df49
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x8d6d2b60eac7
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xb08da1e537f8
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x802f24fa9f80
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x9471e0558cb1
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xa17524bcf06d
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x93ae299ee8c2
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x9410beb4eaee
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xa42ee7f163cf
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x95a4b504ba2f
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xb92d55e0157f
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x8bfa9328b39f
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xb7519fc3ec1f
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xa809b6eeb878
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xaf9304700a7d
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0x8b508ff750a3
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xae80a236b3f7
[2024-02-02 16:41:07]  INFO validator: Validating for public key publicKey=0xb83fc46c5fc9
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567120 pubKey=0x80f408a41341 publicKey=0x80f408a41341 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567130 pubKey=0x8ae1e4efc47f publicKey=0x8ae1e4efc47f status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0x8d0af7e73bde status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xa246821f8b14 status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567122 pubKey=0x84d7fa31925c publicKey=0x84d7fa31925c status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567126 pubKey=0xad975197a132 publicKey=0xad975197a132 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567129 pubKey=0xaa3ec86b3d54 publicKey=0xaa3ec86b3d54 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567125 pubKey=0xaf3f7a466278 publicKey=0xaf3f7a466278 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567136 pubKey=0x8df7346b379b publicKey=0x8df7346b379b status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567138 pubKey=0x8c3683846835 publicKey=0x8c3683846835 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567131 pubKey=0x90c409ed5de3 publicKey=0x90c409ed5de3 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xa5e8b3e6cf74 status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xa4b4eb53df49 status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567127 pubKey=0x8d6d2b60eac7 publicKey=0x8d6d2b60eac7 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xb08da1e537f8 status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567128 pubKey=0x802f24fa9f80 publicKey=0x802f24fa9f80 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0x9471e0558cb1 status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567121 pubKey=0xa17524bcf06d publicKey=0xa17524bcf06d status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567135 pubKey=0x93ae299ee8c2 publicKey=0x93ae299ee8c2 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0x9410beb4eaee status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xa42ee7f163cf status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567123 pubKey=0x95a4b504ba2f publicKey=0x95a4b504ba2f status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567124 pubKey=0xb92d55e0157f publicKey=0xb92d55e0157f status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0x8bfa9328b39f status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567132 pubKey=0xb7519fc3ec1f publicKey=0xb7519fc3ec1f status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xa809b6eeb878 status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xaf9304700a7d status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567133 pubKey=0x8b508ff750a3 publicKey=0x8b508ff750a3 status=ACTIVE
[2024-02-02 16:41:07]  INFO validator: Waiting for deposit to be observed by beacon node pubKey=0xae80a236b3f7 status=UNKNOWN_STATUS
[2024-02-02 16:41:07]  INFO validator: Validator activated index=1567137 pubKey=0xb83fc46c5fc9 publicKey=0xb83fc46c5fc9 status=ACTIVE
[2024-02-02 16:41:08]  INFO validator: Schedule for epoch 28609 attesterCount=18 proposerCount=0

@nalepae
Copy link
Contributor

nalepae commented Feb 2, 2024

Also:

[2024-02-02 18:50:03]  INFO validator: Validator activated index=1567130 pubKey=0x8ae1e4efc47f publicKey=0x8ae1e4efc47f status=ACTIVE

We have both pubKey and publicKey in this log.

@rkapka rkapka removed the Blocked Blocked by research or external factors label Feb 7, 2024
@nalepae
Copy link
Contributor

nalepae commented Feb 8, 2024

Sometimes, it's pubkey, sometimes, pubKey.

INFO validator: Validator activated index=1567132 pubKey=0xb7519fc3ec1f status=ACTIVE
 INFO validator: Duties schedule attesterCount=1 pubkeys=[0xa17524bcf06d] slot=958882 slotInEpoch=2

@@ -258,7 +258,7 @@ func performRoles(slotCtx context.Context, allRoles map[[48]byte][]iface.Validat
defer span.End()
defer func() {
if err := recover(); err != nil { // catch any panic in logging
log.WithField("err", err).
log.WithField("error", err).
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Can't use WithError because err is of type any

"slot": epochStartSlot + i,
"slotInEpoch": (epochStartSlot + i) % params.BeaconConfig().SlotsPerEpoch,
"attesterCount": len(attesterKeys[i]),
"attesterPubkeys": attesterKeys[i],
Copy link
Contributor Author

Choose a reason for hiding this comment

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

we have a proposerPubkey field too, so can't use pubkeys

"status": status.status.Status.String(),
}
if status.index != nonexistentIndex {
fields["index"] = status.index
fields["validatorIndex"] = status.index
Copy link
Contributor Author

Choose a reason for hiding this comment

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

We have validatorIndex in other places. I prefer this way rather than index because it might be unclear what kind of index it is (maybe not in this exact place, but somewhere else).

nalepae
nalepae previously approved these changes Feb 8, 2024
for _, log := range v.attLogs {
if duty.CommitteeIndex == log.data.CommitteeIndex {
log.aggregatorIndices = append(log.aggregatorIndices, duty.ValidatorIndex)
for _, l := range v.submittedAtts {
Copy link
Contributor

Choose a reason for hiding this comment

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

Why using l as a variable name?
(the letter l is not in submittedAtts).

Why not using something like att?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

this is outdated

@rkapka rkapka enabled auto-merge February 8, 2024 18:17
@rkapka rkapka added this pull request to the merge queue Feb 8, 2024
Merged via the queue into develop with commit 91504eb Feb 8, 2024
17 checks passed
@rkapka rkapka deleted the improve-vc-logs branch February 8, 2024 18:30
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants