Hello All,
in date 20-07-2017 a major fork occurred in the SHIFT network.
PRE Within a forging round a single delegate can only forge 1 block unless tsome other previous delegates skip their block.
In the forging round 8851
(blocks from: 893851 - 893951), the last block in round (893951
) was forged by worldcoinpool
which has also forged block 896186.
Most of the nodes within the network reacted to 893951 with a fork #3. Any resync from a previous point in time caused fork #3. Why? Cause the delegate suppoused to forge 893951 was shoosh
.
So why some nodes accepted worldcoinpool
block? and Why worldcoinpool
decided to forge that block even if it was not his slot?
I've spent almost 10hours trying to figure out why some nodes thought that worldcoinpool had that forging slot.
At first I thought it was due to bad delegates sorting and slot allocation caused by different implementations of the sha256
algorithm that creates the seed used to allocate active delegates.
Then I thought it was some wrong math done by js (which is known to have issues with math).
All of the above resulted in false assumptions.
Then it hit me and I thought a very rare race condition that I've been able to partly certify thanks to the logs that were given to me from a node that accepted worldcoinpool
block
Preface:
- Bob is the suppoused last block forger (shoosh above)
- Alice is the last block taker (worldcoinpool above)
This happens only when all of the following conditions are met!:
- we are in last block of a round
- Bob double forges the block
- First block with id #2 (id lowered for the sake of clarity)
- Second block with id #3
- Alice receives Bobs block #3
- Alice receives Bobs block #2
- Alice forges a block with id < #2
- There were some votes in the round that will lead to ranking changes for both Bob and Alice (that should be applied when next round starts)
Note As you can see this is a very rare (and fairly hard to debug) race condition!
When in 3
Alice accepts Bob block #3, then when block #2 arrives then
- Fork 5 happens
- since block #2 has an id < than 3 we:
- backtick the round (BUGGed)
- delete block #3
- process block #2 -> fork #3
<--- WHY? read later
- forge kicks in and Alice forge the block + broadcast
- IF Alice's block has an id < #2 then a major network disruption happens
Meanwhile the network that received both Bobs blocks
Fork #3 happens because when the first block from Bob comes, round finishes and delegate votes are reaccounted changing the active delegates chart.
When Bob receives block #2 the chart is changed and not restored correctly by "modules/rounds.js backTick" which does not rollback properly the votes (and other stuff I guess). For this reason, when bob receives block #2 he thinks that Alice is not the correct delegate -> Fork #3.
Short answer? NO.
Long answer? ->
forge routine triggers every 1s. If the forging routine triggers just after block#3 is deleted (or while block #2 is being processed) then this will happen!
====
When evaluating a fork #5 we should check if previous accepted block has same delegate than new block in correlation with round position.
(Of course) implement a proper rollback in backwardTick
delegate 9a4d***
=> Bob
delegate 20be***
=> Alice
[inf] 2017-07-20 14:20:43 | Received new block id: 1951415658472361437 height: 893951 round: 8851 slot: 1350046 reward: 110000000
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:43 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:43 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:43 | Last block stands
[inf] 2017-07-20 14:20:44 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:44 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:44 | Last block stands
[inf] 2017-07-20 14:20:44 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:44 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:44 | Last block stands
[inf] 2017-07-20 14:20:44 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:44 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:44 | Last block stands
[inf] 2017-07-20 14:20:45 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[WRN] 2017-07-20 14:20:45 | Delegate forging on multiple nodes - 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3
[inf] 2017-07-20 14:20:45 | Last block stands
[inf] 2017-07-20 14:20:46 | Fork - {"delegate":"20bef0f43dee2291391c83d100fb77b886aa762e18e96c85663c754e96de5cbe","block":{"id":"15598365189616631313","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[inf] 2017-07-20 14:20:46 | Last block loses
[WRN] 2017-07-20 14:20:46 | Deleting last block - {"version":0,"totalAmount":187139653,"totalFee":3000000,"reward":110000000,"payloadHash":"adca7fe47243803b25d214c9983150913bf14a2a235c4a8e304ceaa9ae54b15e","timestamp":36451242,"numberOfTransactions":3,"payloadLength":543,"previousBlock":"7993208541717327000","generatorPublicKey":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","transactions":[{"type":0,"amount":36865529,"senderPublicKey":"30f34b1f3c13820698e65b60573d10b57d600f9468616e7401ea11df11afb80c","timestamp":36451182,"asset":{},"recipientId":"14675176465578734374S","signature":"075adf2bc46533dc96d6888efef234cb2b67359bc3434da974ec073e741a234e440f1f1605547d2f931d8e74aeb8750fa984ca97cbd8d7cba12dc82472ae9909","signSignature":"bb3c62a3a9f032a9ed68bafb6098e4b2c0d35e880b34b122f4e25c717090533d777e7378f69d094c3232a9d70f8159724ed179bc289dfa84f822956c26cc4d07","id":"15098583552945968542","fee":1000000,"senderId":"7876956936945693367S","relays":2,"receivedAt":"2017-07-20T14:19:55.427Z","blockId":"1951415658472361437"},{"type":0,"amount":67298517,"senderPublicKey":"30f34b1f3c13820698e65b60573d10b57d600f9468616e7401ea11df11afb80c","timestamp":36451213,"asset":{},"recipientId":"18113470329236636101S","signature":"1e12ab50fa80d95c35f23e7cfa8b31ed34c9758f7079b22a4184c3cfd10126d917c12464e891f3240c1f60d65751a4db926ccc4505fdda11d31e73802d1cce0d","signSignature":"80cc093f3bb77d9cd1544d5d47ae695f3fcff9494ba3b3df203aa573ea4d47c095a405c3db7f9ab5471dbbd0dcda12b0cc25c0d7ab500fd51b586c1b608c1304","id":"9290290874924302612","fee":1000000,"senderId":"7876956936945693367S","relays":2,"receivedAt":"2017-07-20T14:20:25.458Z","blockId":"1951415658472361437"},{"type":0,"amount":82975607,"senderPublicKey":"30f34b1f3c13820698e65b60573d10b57d600f9468616e7401ea11df11afb80c","timestamp":36451223,"asset":{},"recipientId":"14982205216512991131S","signature":"3be68da459b9b6eba9b31945fc3478905d28f7b4f39e19ae432368dc4522d37be369fcc4ac790c1d7baf8f93a652b26a5eafa945c8ce4a2a06a0a5501fd16d09","signSignature":"aadd43e588451bb343db0faabaa6f923b2e984cb88f8f02ba0b15c9949af97776ef5b716c4166509e6d3ce5d455e5ba800434aba5a504593144dade06292c900","id":"5444443047466608768","fee":1000000,"senderId":"7876956936945693367S","relays":2,"receivedAt":"2017-07-20T14:20:35.465Z","blockId":"1951415658472361437"}],"blockSignature":"8b715a5f0aed6b6d959c228469ad1cc3eefee7c50bd80d3957b5db310aa329d76848118aa18e97f1a4dcb2c2249524765196b7c8f94cfac81c1f244bf8853f05","id":"1951415658472361437","height":893951,"secondsAgo":4.01,"fresh":true,"relays":2}
[inf] 2017-07-20 14:20:46 | Received new block id: 15598365189616631313 height: 893951 round: 8851 slot: 1350046 reward: 110000000
[inf] 2017-07-20 14:20:46 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"1951415658472361437","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[inf] 2017-07-20 14:20:46 | Last block stands
[inf] 2017-07-20 14:20:46 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"1951415658472361437","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[inf] 2017-07-20 14:20:46 | Last block stands
[inf] 2017-07-20 14:20:46 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"1951415658472361437","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[inf] 2017-07-20 14:20:46 | Last block stands
[inf] 2017-07-20 14:20:46 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[inf] 2017-07-20 14:20:46 | Last block stands
[inf] 2017-07-20 14:20:46 | Fork - {"delegate":"9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3","block":{"id":"858346963379129312","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":5}
[inf] 2017-07-20 14:20:46 | Last block stands
[inf] 2017-07-20 14:21:10 | Received new block id: 9519699560334209750 height: 893952 round: 8852 slot: 1350047 reward: 110000000
Notice how this node received the 2 forged nodes in order (by id) but that caused Alice block to get accepted anyway.
[inf] 2017-07-21 15:47:54 | Found common block: 7993208541717327000 with: 51.15.52.54:9305
[inf] 2017-07-21 15:47:54 | Loading blocks from: 51.15.52.54:9305
[ERR] 2017-07-21 15:47:54 | Expected generator: 9a4d69d5ba637fea3934dafbb613b4ba235b07e569fef5dcf1185debde131dc3 Received generator: 20bef0f43dee2291391c83d100fb77b886aa762e18e96c85663c754e96de5cbe
[inf] 2017-07-21 15:47:54 | Fork - {"delegate":"20bef0f43dee2291391c83d100fb77b886aa762e18e96c85663c754e96de5cbe","block":{"id":"15598365189616631313","timestamp":36451242,"height":893951,"previousBlock":"7993208541717327000"},"cause":3}
[ERR] 2017-07-21 15:47:54 | Error loading blocks: Failed to verify slot: 1350046
===
I've set up a PoC code. It basically does the following:
- run lisk like app.js do (copied and pasted the code there)
- when ready:
- generate blocks till lastBlockInRound - 2
- find last block delegate
- create a vote/unvote tx for such delegate (so that its ranking changes in the next round)
- forge block "lastBlockInRound - 1"
- forge block "lastBlockInRound"
- craft a new block with lower id (changing version)
- call
modules.blocks.submodules.process.onReceiveBlock
to simulate an incoming block - here happens the following:
fork 5
- previously forged block "lastBlockInRound" gets:
- deleted since new one has an higher id (not always -> see last line in this doc)
- rounds.backtick! (where the bug is)
- new incoming block gets discarded due to invalid version
- lastBlock is now back at lastBlockInRound - 1
- I verify that the next delegate changed since round votes were not rolled back.
It requires the following:
- running redis (-> test/config.json)
- running postgres (w/ login details -> test/config.json)
- node 7
- reinstall node_modules after node 7 switch
- change line 90 of
logic/transaction.js
to accept timestamp from input (just for the test)
var trs = {
type: data.type,
amount: 0,
senderPublicKey: data.sender.publicKey,
requesterPublicKey: data.requester ? data.requester.publicKey.toString('hex') : null,
timestamp: data.timestamp || slots.getTime(),
asset: {}
};
- place vekexasiabug.js in the root folder of lisk
- run it at least twice. (Every time you launch it it will generate 101 blocks manually forging the blocks)
Note Relevant code starts at line 715
till end of file. (onInit
is being called after app initialization. (copied from app.js) )
If the code ends with DIDNt rollback properly! WTF?
it's because there is another minor bug here. Comment says: .... keep one with lower id
but id comparison is lexicographical not "numeric" since block.id is a string (or could be a string in my tests)
This is what you should see: