Pandora sends invalid slot to validator

[atif-konasl]

Expected behaviour

Pandora should send valid current slot for producing new block to validator. And validator also checks the incoming slot number. If the incoming slot number does not match with current slot number then validator discards the block for that slot.

Pandora should calculate right block number from its end.

Actual behaviour

pandora sends current slot + 1 when i spin a new archive node and connect with existing network. After that, validator always fails to produce block because of pandora sends invalid slot number.

Steps to reproduce the behaviour

make geth
cd ./build/bin
./geth --datadir ./pandora init ./genesis.json
./geth --datadir ./pandora --ethstats dev-pandora-anando-0:VIyf7EjWlR49@catalyst.silesiacoin.com  --bootnodes enode://967db4f56ad0a1a35e3d30632fa600565329a23aff50c9762181810166f3c15b078cca522f930d1a2747778893232336bffd1ea5d2ca60543f1801d4360ea63a@10.0.6.3:0?discport=30301 --networkid 4004181 --rpcaddr 0.0.0.0 --rpcapi admin,eth,net --rpc --rpccorsdomain "*" --miner.etherbase 0xb46d14ef42ac9bb01303ba1842ea784e2460c7e7 --mine --verbosity 10

Open geth json console using:
geth attach http://127.0.0.1:8545
admin.addPeer("enode")

Backtrace

time="2021-06-22 14:17:17" level=info msg="Submitted new attestations" AggregatorIndices=[1426] AttesterIndices=[1426 1746 897 841 1617 1441 1195 1235 136 510 550 1136 1421 1636 540 81 660 783 981 1044 1511 736 1545 1801 1388 1287 1006 1659 794 853 1003 1 1093 377 922 1736 499 1809 982 234 1500 1140 211 756 313 1845 582 877 1415 239 1847 1169 562 592 1016 1768 1961 1886 682 901 1565 339] BeaconBlockRoot=0x91afd45e5af0 CommitteeIndex=0 Slot=830 SourceEpoch=5 SourceRoot=0x0010836ab3a0 TargetEpoch=25 TargetRoot=0x91afd45e5af0 prefix=validator
time="2021-06-22 14:17:19" level=debug msg="gRPC request finished." backend=[] duration=7.38173ms method="/ethereum.eth.v1alpha1.BeaconNodeValidator/MultipleValidatorStatus"
time="2021-06-22 14:17:19" level=debug msg="Set deadline for proposals and attestations" deadline=2021-06-22 14:17:25 +0000 UTC prefix=validator slot=831
time="2021-06-22 14:17:19" level=debug msg="gRPC request finished." backend=[] duration=905.437µs method="/ethereum.eth.v1alpha1.BeaconNodeValidator/DomainData"
time="2021-06-22 14:17:19" level=debug msg="gRPC request finished." backend=[] duration=612.324µs method="/ethereum.eth.v1alpha1.BeaconNodeValidator/DomainData"
time="2021-06-22 14:17:19" level=debug msg="gRPC request finished." backend=[] duration=728.149µs method="/ethereum.eth.v1alpha1.BeaconNodeValidator/DomainData"
time="2021-06-22 14:17:19" level=debug msg="gRPC request finished." backend=[] duration=1.356241ms method="/ethereum.eth.v1alpha1.BeaconNodeValidator/DomainData"
time="2021-06-22 14:17:19" level=debug msg="gRPC request finished." backend=[] duration=794.237µs method="/ethereum.eth.v1alpha1.BeaconNodeValidator/ValidatorIndex"
time="2021-06-22 14:17:19" level=debug msg="gRPC request finished." backend=[] duration=386.243608ms method="/ethereum.eth.v1alpha1.BeaconNodeValidator/GetBlock"
time="2021-06-22 14:17:19" level=debug msg="Got header info from pandora" extraData={832 25 32} generatedHeaderHash=[40 168 130 172 202 60 74 208 106 215 70 53 203 211 88 47 160 201 183 26 29 46 168 126 248 184 66 175 253 134 126 239] header=&{[46 59 94 155 67 116 133 247 157 250 11 224 16 97 177 198 193 72 78 166 29 230 95 128 41 110 143 6 141 61 203 176] [29 204 77 232 222 199 93 122 171 133 181 103 182 204 212 26 211 18 69 27 148 138 116 19 240 161 66 253 64 212 147 71] [180 109 20 239 66 172 155 176 19 3 186 24 66 234 120 78 36 96 199 231] [6 189 108 16 191 226 105 27 182 107 28 182 119 233 168 38 80 112 76 69 22 141 218 8 247 187 246 222 2 164 83 246] [86 232 31 23 27 204 85 166 255 131 69 230 146 192 248 110 91 72 224 27 153 108 173 192 1 98 47 181 227 99 180 33] [86 232 31 23 27 204 85 166 255 131 69 230 146 192 248 110 91 72 224 27 153 108 173 192 1 98 47 181 227 99 180 33] [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] 1 165 5521046 0 1624371433 [197 130 3 64 25 32] [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] [0 0 0 0 0 0 0 0]} headerHash=[76 104 165 244 30 193 126 1 68 38 152 179 103 222 190 115 35 232 176 146 8 226 111 18 183 217 85 23 251 181 40 130] prefix=pandora
time="2021-06-22 14:17:19" level=error msg="invalid slot from pandora chain" error="invalid slot" extraDataSlot=832 header=[197 130 3 64 25 32] prefix=validator slot=831
time="2021-06-22 14:17:19" level=error msg="Failed to validate pandora block header" blockSlot=831 error="invalid slot" fmtKey=0xb843004f3651e4ff70065ea8f5b55193a86d7ff72cfa2ea1ec8e53ed9af5f7aabb2936f23e1fa921b2677424a6c1b786 prefix=validator
time="2021-06-22 14:17:19" level=error msg="Failed to process pandora chain shard header" error="invalid slot" prefix=validator pubKey=0xb843004f3651e4ff70065ea8f5b55193a86d7ff72cfa2ea1ec8e53ed9af5f7aabb2936f23e1fa921b2677424a6c1b786 slot=831
time="2021-06-22 14:17:21" level=debug msg="gRPC request finished." backend=[] duration=101.220432ms method="/ethereum.eth.v1alpha1.BeaconNodeValidator/GetAttestationData"
tim

[blazejkrzak]

Also another bug happens:

time="2021-06-23 12:44:05" level=error msg="invalid timestamp from pandora chain" error="invalid timestamp" prefix=validator
time="2021-06-23 12:44:05" level=error msg="Failed to validate pandora block header" blockSlot=177 error="invalid timestamp" fmtKey=0xb876db47bf1d1868b3a39cdba4171adde47eae91b3631dcb5c59d28cb100ecda604a446ffcb000448c462d72526ebdf1 prefix=validator
time="2021-06-23 12:44:05" level=error msg="Failed to process pandora chain shard header" error="invalid timestamp" prefix=validator pubKey=0xb876db47bf1d1868b3a39cdba4171adde47eae91b3631dcb5c59d28cb100ecda604a446ffcb000448c462d72526ebdf1 slot=177

[blazejkrzak]

It looks like its not related with peers at all

[blazejkrzak]

Also another bug happens:

time="2021-06-23 12:44:05" level=error msg="invalid timestamp from pandora chain" error="invalid timestamp" prefix=validator
time="2021-06-23 12:44:05" level=error msg="Failed to validate pandora block header" blockSlot=177 error="invalid timestamp" fmtKey=0xb876db47bf1d1868b3a39cdba4171adde47eae91b3631dcb5c59d28cb100ecda604a446ffcb000448c462d72526ebdf1 prefix=validator
time="2021-06-23 12:44:05" level=error msg="Failed to process pandora chain shard header" error="invalid timestamp" prefix=validator pubKey=0xb876db47bf1d1868b3a39cdba4171adde47eae91b3631dcb5c59d28cb100ecda604a446ffcb000448c462d72526ebdf1 slot=177

Found possible fix for this one This code sample should fix it

// verify timestamp. Timestamp should not be future time
    if header.Time > uint64(timeutils.Now().Unix()) {
        log.WithError(errInvalidTimestamp).Error("invalid timestamp from pandora chain")
        return errInvalidTimestamp
    }

https://github.com/lukso-network/vanguard-consensus-engine/commit/d0810d5ecc5ddb26c950bcc6ca8940ed17c4a423

[blazejkrzak]

Problem lays here on vanguard side

case slot := <-v.NextSlot():

[blazejkrzak]

Slot 88

time="2021-06-23 14:23:43" level=error msg="invalid slot from pandora chain" error="invalid slot" expectedTimeStart=1624458223 extraDataSlot=89 header=[195 89 2 25] headerTime=1624458223 prefix=validator slot=88
time="2021-06-23 14:23:43" level=error msg="Failed to validate pandora block header" blockSlot=88 error="invalid slot" fmtKey=0xa2a576a9ead4b1280ecd99309a8e5a9d80fc8b4bbd3d4602d1295e60307c4c8fc816db09f60aa61b9350eb295e348be8 prefix=validator
time="2021-06-23 14:23:43" level=error msg="Failed to process pandora chain shard header" error="invalid slot" prefix=validator pubKey=0xa2a576a9ead4b1280ecd99309a8e5a9d80fc8b4bbd3d4602d1295e60307c4c8fc816db09f60aa61b9350eb295e348be8 slot=88

Slot 89

time="2021-06-23 14:23:49" level=debug msg="Got header info from pandora" extraData={89 2 25} generatedHeaderHash=[40 63 31 226 136 195 166 180 19 213 16 60 174 35 189 81 211 30 242 224 245 149 216 110 73 251 48 178 87 176 182 206] header=&{[142 163 194 184 183 98 54 137 174 96 0 201 74 220 216 91 227 210 248 152 160 12 182 57 89 122 220 57 226 5 188 15] [29 204 77 232 222 199 93 122 171 133 181 103 182 204 212 26 211 18 69 27 148 138 116 19 240 161 66 253 64 212 147 71] [180 109 20 239 66 172 155 176 19 3 186 24 66 234 120 78 36 96 199 231] [228 208 83 190 103 52 149 57 114 199 215 231 252 59 57 187 84 187 153 54 37 169 215 162 41 69 87 53 160 33 84 182] [86 232 31 23 27 204 85 166 255 131 69 230 146 192 248 110 91 72 224 27 153 108 173 192 1 98 47 181 227 99 180 33] [86 232 31 23 27 204 85 166 255 131 69 230 146 192 248 110 91 72 224 27 153 108 173 192 1 98 47 181 227 99 180 33] [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] 1 68 5022436 0 1624458223 [195 89 2 25] [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] [0 0 0 0 0 0 0 0]} headerHash=[121 209 176 220 38 29 222 82 34 174 181 187 83 56 150 58 189 105 233 99 120 56 132 21 218 142 184 176 114 82 218 209] prefix=pandora
time="2021-06-23 14:23:49" level=debug msg="Sending header signature to pandora" prefix=pandora signature=[174 238 81 111 173 247 167 22 16 131 6 225 56 59 190 248 45 149 245 60 226 160 229 166 171 125 154 106 236 217 112 213 41 251 212 128 211 114 67 232 230 196 33 99 102 61 184 155 3 244 217 211 130 73 92 12 101 227 16 243 241 149 76 218 157 178 179 230 223 35 17 187 149 177 93 171 56 45 3 199 163 239 111 40 75 183 127 126 163 64 95 11 157 78 242 181]

[blazejkrzak]

The same header from Pandora got accepted. Pandora was having proper slot, but vanguard did not receive slot progression via channel 1624458223 Timestamp was accepted 2 seconds after, when vanguard received the slot progression signal

[blazejkrzak]

Right after vanguard received signal it accepted the block

[blazejkrzak]

3 seconds mismatch on the slot start between pandora and vanguard

[blazejkrzak]

Long story short: Pandora is right, its vanguard that is behind after attestations

[blazejkrzak]

Two things had happened which changed stall state to working state.

• recommit interval on pandora side was halved to 3s
• orchetrator substracts on the fly 3s from vanguard genesis time after it pushes it to pandora

Important note: Try to remove entirely substraction on the fly