Duty of epoch returns 0

[stefa2k]

{"level":"warn","service":"controller","impl":"standard","epoch":17714,"duty_slot":0,"time":"2020-10-22T06:29:44Z","message":"Attester duty has invalid slot for requested epoch; ignoring"}

I see this roughly every 6 minutes 2 times (4 beacons connected to vouch).

Switched vouch to trace but after restart of vouch it doesn't occur anymore.

[stefa2k]

Got it again:

{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"endpoint\":\"/beacon/fork\",\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"GET request\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.776846605Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"url\":\"http://lighthouse_beacon:5052/beacon/fork\",\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"GET request\"}\n","stream":"stderr","time":"2020-10-22T
16:05:44.776961189Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"response\":\"{\\\"previous_version\\\":\\\"0x00000001\\\",\\\"current_version\\\":\\\"0x00000001\\\",\\\"epoch\\\":0}\",\"time\":\"2020-10-22T16:05:44Z\",\
"message\":\"GET response\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.777035664Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"state\":\"569760\",\"slot\":569760,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Calculated from state ID\"}\n","stream":"stderr","time":"2020-10-22T16:0
5:44.777091736Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"response\":\"{\\\"previous_version\\\":\\\"0x00000001\\\",\\\"current_version\\\":\\\"0x00000001\\\",\\\"epoch\\\":0}\",\"time\":\"2020-10-22T16:05:44Z\",\
"message\":\"GET response\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.777100924Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"state\":\"569760\",\"slot\":569760,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Calculated from state ID\"}\n","stream":"stderr","time":"2020-10-22T16:0
5:44.777107151Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"state\":\"569760\",\"slot\":569760,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Calculated from state ID\"}\n","stream":"stderr","time":"2020-10-22T16:0
5:44.777172826Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"response\":\"{\\\"previous_version\\\":\\\"0x00000001\\\",\\\"current_version\\\":\\\"0x00000001\\\",\\\"epoch\\\":0}\",\"time\":\"2020-10-22T16:05:44Z\",\
"message\":\"GET response\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.777395931Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"state\":\"569760\",\"slot\":569760,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Calculated from state ID\"}\n","stream":"stderr","time":"2020-10-22T16:0
5:44.777453969Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"endpoint\":\"/beacon/fork\",\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"GET request\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.779084818Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"url\":\"http://lighthouse_beacon:5052/beacon/fork\",\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"GET request\"}\n","stream":"stderr","time":"2020-10-22T
16:05:44.779096261Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"endpoint\":\"/beacon/fork\",\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"GET request\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.779450696Z"}
{"log":"{\"level\":\"trace\",\"service\":\"client\",\"impl\":\"lighthousehttp\",\"url\":\"http://lighthouse_beacon:5052/beacon/fork\",\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"GET request\"}\n","stream":"stderr","time":"2020-10-22T
16:05:44.779467235Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.782978971Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.78301226Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.78301877Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783023705Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783028554Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783033358Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783038106Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783042939Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783047807Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783058128Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783063499Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.78306831Z"}
{"log":"{\"level\":\"warn\",\"service\":\"controller\",\"impl\":\"standard\",\"epoch\":17804,\"duty_slot\":0,\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Attester duty has invalid slot for requested epoch; ignoring\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783073053Z"}
{"log":"{\"level\":\"trace\",\"service\":\"controller\",\"impl\":\"standard\",\"slot\":569728,\"committee_indices\":[0,2,4,4,4,7,7,7,9,10,10,11,11,12,13,13,16,16],\"validator_indices\":[25,42,39,22,72,20,114,43,34,35,11,18,127,93,121,45,118,45],\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Received attester duty\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783578142Z"}
{"log":"{\"level\":\"trace\",\"service\":\"controller\",\"impl\":\"standard\",\"slot\":569729,\"committee_indices\":[0,0,1,1,2,2,3,4,5,5,6,6,7,9,10,11,11,11,14,14,15,15,16,16],\"validator_indices\":[75,9,69,123,74,96,15,15,125,14,62,78,65,45,115,25,82,85,111,78,122,60,13,74],\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Received attester duty\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783591552Z"}
{"log":"{\"level\":\"trace\",\"service\":\"controller\",\"impl\":\"standard\",\"slot\":569730,\"committee_indices\":[0,1,1,3,5,7,7,7,9,9,10,10,11,11,12,12,13,13,13,14,14,15],\"validator_indices\":[119,94,44,11,134,65,117,46,90,51,89,76,20,80,112,25,129,56,55,17,50,62],\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Received attester duty\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783597584Z"}
{"log":"{\"level\":\"trace\",\"service\":\"controller\",\"impl\":\"standard\",\"slot\":569731,\"committee_indices\":[0,2,3,3,4,4,4,5,5,6,6,7,8,9,9,11,11,11,11,11,12,13,13,14,16,16],\"validator_indices\":[109,81,13,102,48,91,86,115,45,8,72,19,18,127,79,46,57,77,15,32,48,116,118,76,70,32],\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Received attester duty\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783635562Z"}
{"log":"{\"level\":\"trace\",\"service\":\"controller\",\"impl\":\"standard\",\"slot\":569732,\"committee_indices\":[0,1,1,1,2,3,3,3,5,6,6,6,7,7,8,9,10,10,14,14,15,16],\"validator_indices\":[29,118,105,46,82,114,64,122,65,17,25,2,77,65,110,79,74,23,135,95,24,89],\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Received attester duty\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783643011Z"}
{"log":"{\"level\":\"trace\",\"service\":\"controller\",\"impl\":\"standard\",\"slot\":569733,\"committee_indices\":[1,2,6,8,8,9,9,14,14,14,15],\"validator_indices\":[126,41,98,26,64,120,86,74,128,114,6],\"time\":\"2020-10-22T16:05:44Z\",\"message\":\"Received attester duty\"}\n","stream":"stderr","time":"2020-10-22T16:05:44.783648255Z"}`

[mcdee]

Please could you supply more of the log prior to that above? Specifically, there should be a log entry Creating attester jobs and it is the logs from there on that are of interest. Thanks.

[stefa2k]

Here you go:

vouch.log.cut.txt

[mcdee]

This will be addressed in the upcoming 0.9.0 release.

[stefa2k]

Doesn't work:

vouch         | {"level":"warn","service":"controller","impl":"standard","time":"2020-11-20T05:14:18Z","message":"No active validating accounts; not validating"}
vouch         | {"level":"info","time":"2020-11-20T05:18:00Z","message":"Stopping vouch"}
vouch         | {"level":"info","version":"0.9.0","time":"2020-11-20T05:18:04Z","message":"Starting vouch"}
vouch         | {"level":"info","listen_address":"0.0.0.0:8081","time":"2020-11-20T05:18:04Z","message":"Started prometheus metrics service"}
vouch         | {"level":"info","time":"2020-11-20T05:18:04Z","message":"Starting dirk account manager"}
vouch         | {"level":"info","time":"2020-11-20T05:18:05Z","message":"Starting multinode submitter strategy"}
vouch         | {"level":"info","time":"2020-11-20T05:18:06Z","message":"Starting static graffiti provider"}
vouch         | {"level":"info","time":"2020-11-20T05:18:06Z","message":"Starting best beacon block proposal strategy"}
vouch         | {"level":"info","service":"controller","impl":"standard","accounts":10,"time":"2020-11-20T05:18:06Z","message":"Initial validating accounts"}
vouch         | {"level":"info","time":"2020-11-20T05:18:06Z","message":"All services operational"}
vouch         | {"level":"info","service":"controller","impl":"standard","old_accounts":0,"accounts":10,"time":"2020-11-20T05:18:06Z","message":"Change in number of validating accounts"}

Vouch simply doesn't recognize the accounts until restarted.

[mcdee]

Thank you for reporting this issue. We see this as well, and are currently testing a fix we will make available ASAP.

(In case you're interested: the standard API has a preference for using validator IDs to fetch information, due to their reduced size compared to public keys. The keymanager uses these, but for validators that have yet to be assigned an ID it sends '0' as the ID, as that's its internal number for such validators, and the results are thrown out because the public keys of the returned results don't match. Hence the validator never updates. The fix for this is to force Vouch to fetch data using its public keys in this instance).

[mcdee]

This should be fixed in release 1.0.0. If you encounter this again please re-open the issue.