Unable to publish SyncCommitteeContribution - SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT

[twoeths]

Describe the bug

Found this error in lodestar-geth instance of pithos

Oct-25 03:39:48.628 [API]             error: Req req-143nl publishContributionAndProofs error code=SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT, currentSlot=76674, slot=76673
Error: SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT
    at validateGossipSyncCommitteeExceptSig (/usr/app/node_modules/@chainsafe/lodestar/src/chain/validation/syncCommittee.ts:81:11)
    at validateSyncCommitteeGossipContributionAndProof (/usr/app/node_modules/@chainsafe/lodestar/src/chain/validation/syncCommitteeContributionAndProof.ts:25:39)
    at /usr/app/node_modules/@chainsafe/lodestar/src/api/impl/validator/index.ts:458:66
    at Array.map (<anonymous>)
    at Object.publishContributionAndProofs (/usr/app/node_modules/@chainsafe/lodestar/src/api/impl/validator/index.ts:455:31)
    at Object.handler (/usr/app/node_modules/@chainsafe/lodestar-api/src/server/utils/server.ts:70:42)
    at preHandlerCallback (/usr/app/node_modules/fastify/lib/handleRequest.js:124:28)
    at preValidationCallback (/usr/app/node_modules/fastify/lib/handleRequest.js:107:5)
    at handler (/usr/app/node_modules/fastify/lib/handleRequest.js:70:7)
    at done (/usr/app/node_modules/fastify/lib/contentTypeParser.js:151:7)

it looks like the validator client is frequently late to submit ContributionAndProof

at validator side

Oct-25 03:46:50.227 []                error: Error publishing SyncCommitteeContribution slot=76708, index=0 message=Internal Server Error: SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT
Error: Internal Server Error: SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT
    at HttpClient.request (/usr/app/node_modules/@chainsafe/lodestar-api/src/client/utils/httpClient.ts:91:15)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
    at HttpClient.json (/usr/app/node_modules/@chainsafe/lodestar-api/src/client/utils/httpClient.ts:58:12)
    at Object.request [as publishContributionAndProofs] (/usr/app/node_modules/@chainsafe/lodestar-api/src/client/utils/client.ts:72:19)
    at SyncCommitteeService.produceAndPublishAggregates (/usr/app/node_modules/@chainsafe/lodestar-validator/src/services/syncCommittee.ts:178:9)
    at /usr/app/node_modules/@chainsafe/lodestar-validator/src/services/syncCommittee.ts:67:11
    at async Promise.all (index 3)
    at SyncCommitteeService.runSyncCommitteeTasks (/usr/app/node_modules/@chainsafe/lodestar-validator/src/services/syncCommittee.ts:62:7)
    at Clock.runAtMostEvery (/usr/app/node_modules/@chainsafe/lodestar-validator/src/util/clock.ts:70:7)

the consensus node

Oct-25 03:46:49.476 [CHAIN]         verbose: Clock slot slot=76709

Oct-25 03:46:50.219 [API]             error: Error on publishContributionAndProofs [0] slot=76708, subCommitteeIndex=1 code=SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT, currentSlot=76709, slot=76708
Error: SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT
Oct-25 03:46:50.221 [API]             error: Req req-14487 publishContributionAndProofs error code=SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT, currentSlot=76709, slot=76708
Error: SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT
Oct-25 03:46:50.226 [API]             error: Req req-14488 publishContributionAndProofs error code=SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT, currentSlot=76709, slot=76708
Error: SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT
Oct-25 03:46:50.224 [API]             error: Error on publishContributionAndProofs [0] slot=76708, subCommitteeIndex=0 code=SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT, currentSlot=76709, slot=76708
Error: SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT
Oct-25 03:47:00.341 [CHAIN]         verbose: Clock slot slot=76710

Expected behavior

No error

[twoeths]

there seems to be performance issue at node side that make it unable to accept requests

validator logs

Oct-25 03:46:44.752 []              ^[[36mverbose^[[39m: Producing SyncCommitteeContribution slot=76708, index=1
Oct-25 03:46:44.753 []              ^[[36mverbose^[[39m: Producing SyncCommitteeContribution slot=76708, index=0

but node can only accepts request ~3s later

Oct-25 03:46:47.334 [API]             ^[[34mdebug^[[39m: Req req-14481 127.0.0.1 GET:/eth/v1/validator/sync_committee_contribution
Oct-25 03:46:47.335 [API]             ^[[34mdebug^[[39m: Res req-14481 produceSyncCommitteeContribution - 200
Oct-25 03:46:47.335 [API]             ^[[34mdebug^[[39m: Req req-14482 127.0.0.1 GET:/eth/v1/validator/sync_committee_contribution
Oct-25 03:46:47.335 [API]             ^[[34mdebug^[[39m: Res req-14482 produceSyncCommitteeContribution - 200

then validator was able to sign SyncCommitteeContribution

Oct-25 03:46:47.346 []                ^[[34mdebug^[[39m: Signed SyncCommitteeContribution slot=76708, index=1, validatorIndex=17782
Oct-25 03:46:47.348 []                ^[[34mdebug^[[39m: Signed SyncCommitteeContribution slot=76708, index=0, validatorIndex=17520

maybe due to the same reason, server can only see publishContributionAndProofs request 3s later

Oct-25 03:46:50.211 [API]             ^[[34mdebug^[[39m: Req req-14483 127.0.0.1 POST:/eth/v1/validator/aggregate_and_proofs
Oct-25 03:46:50.219 [API]             ^[[31merror^[[39m: Error on publishContributionAndProofs [0] slot=76708, subCommitteeIndex=1 code=SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLOT, currentSlot=76709, slot=76708
Error: SYNC_COMMITTEE_ERROR_NOT_CURRENT_SLO

slot 76708 started at 3:46:36

[dapplion]

It seems to show that the node is very busy delaying processing

[twoeths]

It seems to show that the node is very busy delaying processing

root cause may be #3390

[dapplion]

I've also observed that any HTTP API request takes > 2 sec to be replied which makes it very likely for the contribution to be late

[dapplion]

Closing for root cause #3694