search

input-output-hk / jormungandr

privacy voting blockchain node
https://input-output-hk.github.io/jormungandr/
Apache License 2.0
364 stars 132 forks source link

Block created with existing parent not propagated on 0.8.8 #1681

Closed zmeel closed 4 years ago

zmeel commented 4 years ago

Describe the bug After creating a block with an existing parent, block not propagated to chain:

- created_at_time: "2020-01-30T10:21:49.637367969+00:00"
  enclave_leader_id: 1
  finished_at_time: "2020-01-30T10:48:31.004159999+00:00"
  scheduled_at_date: "47.28047"
  scheduled_at_time: "2020-01-30T10:48:31+00:00"
  status:
    Block:
      block: 4a0d95e699e9a86c10f91ec510ba632b830730da599262156a126e2bfb88a726
      chain_length: 145920
  wake_at_time: "2020-01-30T10:48:31.000351061+00:00"

I run two nodes with leadership fail over and both nodes were fully sync and not forked as could be seen from my onw log files from a script were I compare last block height and hashes with Pooltool block height.

Thu Jan 30 10:47:16 UTC 2020: Jormungandr-PI last Block height: 145917 and Block Hash: d392cbd39c5235d8208df8ef9867ea4382e66a30d84680a1f5eea43dffa921ce
Thu Jan 30 10:47:16 UTC 2020: Jormungandr-VPS last Block height: 145917 and Block Hash: d392cbd39c5235d8208df8ef9867ea4382e66a30d84680a1f5eea43dffa921ce
Thu Jan 30 10:47:27 UTC 2020: Jormungandr-PI last Block height: 145917 and Block Hash: d392cbd39c5235d8208df8ef9867ea4382e66a30d84680a1f5eea43dffa921ce

Block d392cbd39c5235d8208df8ef9867ea4382e66a30d84680a1f5eea43dffa921ce exists —> child 2f45b0b0c3814b9e587d95ad169cd9e86106fac3c5c893999f501d60d77dbb91

Thu Jan 30 10:47:27 UTC 2020: Jormungandr-VPS last Block height: 145918 and Block Hash: 2f45b0b0c3814b9e587d95ad169cd9e86106fac3c5c893999f501d60d77dbb91
Thu Jan 30 10:47:27 UTC 2020: Pooltool: Jormungandr-VPS last Block height: 145918 Block Hash: 2f45b0b0c3814b9e587d95ad169cd9e86106fac3c5c893999f501d60d77dbb91 from Pool ID: b861d017de996613aff9f1eaa6710cf8506397559779fc6c8cd96c1d04582854

Block 2f45b0b0c3814b9e587d95ad169cd9e86106fac3c5c893999f501d60d77dbb91  exists —> child b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7

Thu Jan 30 10:47:39 UTC 2020: Jormungandr-PI last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:47:39 UTC 2020: Jormungandr-VPS last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:47:50 UTC 2020: Jormungandr-PI last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:47:50 UTC 2020: Jormungandr-VPS last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:47:50 UTC 2020: Majority Max Block height: 145919
Thu Jan 30 10:48:01 UTC 2020: Jormungandr-PI last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:48:01 UTC 2020: Jormungandr-VPS last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:48:01 UTC 2020: Majority Max Block height: 145919
Thu Jan 30 10:48:12 UTC 2020: Jormungandr-PI last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:48:12 UTC 2020: Jormungandr-VPS last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:48:12 UTC 2020: Majority Max Block height: 145919
Thu Jan 30 10:48:23 UTC 2020: Jormungandr-PI last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:48:23 UTC 2020: Jormungandr-VPS last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:48:23 UTC 2020: Majority Max Block height: 145919
Thu Jan 30 10:48:23 UTC 2020: Pooltool: Jormungandr-VPS last Block height: 145919 Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7 from Pool ID: 26c1deb80f2e041fe5a6d67d3f4c4b27dde24ea532a11633ec0d6cfc14a880f7
Thu Jan 30 10:48:35 UTC 2020: Jormungandr-PI last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:48:35 UTC 2020: Majority Max Block height: 145919
Thu Jan 30 10:48:46 UTC 2020: Jormungandr-PI last Block height: 145919 and Block Hash: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7
Thu Jan 30 10:48:46 UTC 2020: Majority Max Block height: 145919
Thu Jan 30 10:48:57 UTC 2020: Majority Max Block height: 145919

Block b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7 exists —> child 42c6e9f03bd52c27c85ec32de2a86245444d6266ac98ed707f713ea8424a0516

So block 145917, 145918 and 145919 were all on the chain and my node was scheduled for the next block: (grep 47.28047 node.out)

Jan 30 10:48:31.000 INFO Leader event started, event_remaining_time: 1s 999ms 612us 96ns, event_end: 2020-01-30T10:48:33+00:00, event_start: 2020-01-30T10:48:31+00:00, event_date: 47.28047, leader_id: 1, task: leadership
Jan 30 10:48:31.003 INFO receiving block from leadership service, date: 47.28047, parent: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7, hash: 4a0d95e699e9a86c10f91ec510ba632b830730da599262156a126e2bfb88a726, task: block
Jan 30 10:48:31.023 INFO block from leader event successfully stored, date: 47.28047, parent: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7, hash: 4a0d95e699e9a86c10f91ec510ba632b830730da599262156a126e2bfb88a726, task: block
Jan 30 10:48:31.023 INFO update current branch tip: b34273c3-000239ff-47.28017 -> 4a0d95e6-00023a00-47.28047, date: 47.28047, parent: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7, hash: 4a0d95e699e9a86c10f91ec510ba632b830730da599262156a126e2bfb88a726, task: block
Jan 30 10:48:45.167 INFO create new branch with tip b78cb38d-000239bd-47.27153 | current-tip 4a0d95e6-00023a00-47.28047, task: block
Jan 30 10:48:50.124 INFO create new branch with tip 42c6e9f0-00023a00-47.28056 | current-tip 4a0d95e6-00023a00-47.28047, task: block
Jan 30 10:49:33.024 INFO switching branch from 4a0d95e6-00023a00-47.28047 to 811e51fd-00023a01-47.28077, task: block
Jan 30 10:49:45.147 INFO create new branch with tip 4a0d95e6-00023a00-47.28047 | current-tip 811e51fd-00023a01-47.28077, task: block
Jan 30 10:50:45.155 INFO create new branch with tip 4a0d95e6-00023a00-47.28047 | current-tip 7ba695bc-00023a04-47.28108, task: block
Jan 30 10:51:45.147 INFO create new branch with tip 4a0d95e6-00023a00-47.28047 | current-tip 9bfac585-00023a07-47.28136, task: block

My node received the right parent: b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7 and created a block: 4a0d95e699e9a86c10f91ec510ba632b830730da599262156a126e2bfb88a726. However on the chain block b34273c3ba29f1d47e97438e8a39829659fe1a0804f2bb01ccbffb4a15be6ed7 had child 42c6e9f03bd52c27c85ec32de2a86245444d6266ac98ed707f713ea8424a0516 and not my block. This block is also in slot 47.28056 which is not my scheduled slot 47.28047. Where is my block?

Mandatory Information

  1. jcli --full-version output; jcli 0.8.8 (HEAD-4687999, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

  2. jormungandr --full-version output; jormungandr 0.8.8 (HEAD-4687999, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

To Reproduce Steps to reproduce the behavior: Run Jormungandr 0.8.8 and create a block

Expected behavior A clear and concise description of what you expected to happen. Blocks created succesfully should be on the chain

Additional context Add any other context about the problem here.

zmeel commented 4 years ago

I know this a probably a duplicate but there seems to be no response to these similar issues of what the community is calling a 'vaporized block'. I would really like to know (and probably other pool owners too) if this is normal behaviour or a bug. If this is normal how could we improve? This is killing my pool performance and reputation.

So please could you respond and explain this block creation behaviour?

I have INFO level log files of both nodes.

JSCSJSCS commented 4 years ago

47.38883#146726 - Vaporized? on v0.8.7 after 0.8.9 released.

{"msg":"Leader event started","level":"INFO","ts":"2020-01-30T08:49:43.000390700-08:00","event_remaining_time":"1s 999ms 609us 300ns","event_end":"2020-01-30T16:49:45+00:00","event_start":"2020-01-30T16:49:43+00:00","event_date":"47.38883","leader_id":"1","task":"leadership"}
{"msg":"receiving block from leadership service","level":"INFO","ts":"2020-01-30T08:49:43.001387800-08:00","date":"47.38883","parent":"b383538acac5df48c8d4a5789c37b1fd215ee3871fe4ae108d0fbdf3ee5fa51d","hash":"978fb9a6312f178273d929bd3628aa6168e21a9f11e5bbf56bac8cec59a4c618","task":"block"}
{"msg":"block from leader event successfully stored","level":"INFO","ts":"2020-01-30T08:49:43.005412100-08:00","date":"47.38883","parent":"b383538acac5df48c8d4a5789c37b1fd215ee3871fe4ae108d0fbdf3ee5fa51d","hash":"978fb9a6312f178273d929bd3628aa6168e21a9f11e5bbf56bac8cec59a4c618","task":"block"}
{"msg":"update current branch tip","level":"INFO","ts":"2020-01-30T08:49:43.006374600-08:00","date":"47.38883","parent":"b383538acac5df48c8d4a5789c37b1fd215ee3871fe4ae108d0fbdf3ee5fa51d","hash":"978fb9a6312f178273d929bd3628aa6168e21a9f11e5bbf56bac8cec59a4c618","task":"block"}

[cardano-wallet.stake-pool-monitor:Info:28] [2020-01-30 16:49:43.43 UTC] Applying blocks [47.38883 ... 47.38883]
[cardano-wallet.stake-pool-monitor:Info:28] [2020-01-30 16:49:43.43 UTC] Writing stake-distribution for epoch 47
[cardano-wallet.stake-pool-monitor:Info:28] [2020-01-30 16:50:24.10 UTC] Monitoring stake pools. Currently at b383538a-[47.38855#146725]
[cardano-wallet.stake-pool-monitor:Info:28] [2020-01-30 16:50:24.10 UTC] Applying blocks [47.38890 ... 47.38903]
[cardano-wallet.stake-pool-monitor:Info:28] [2020-01-30 16:50:24.11 UTC] Writing stake-distribution for epoch 47
[cardano-wallet.stake-pool-monitor:Info:28] [2020-01-30 16:50:34.15 UTC] Applying blocks [47.38907 ... 47.38907]
[cardano-wallet.stake-pool-monitor:Info:28] [2020-01-30 16:50:34.15 UTC] Writing stake-distribution for epoch 47

Date       Time       MyTip    Tip
01-30-2020 08:48:20   146723   146722
01-30-2020 08:49:22   146725   146725
01-30-2020 08:50:23   146726   146726
01-30-2020 08:51:24   146729   146729
01-30-2020 08:52:26   146731   146729
mzabaluev commented 4 years ago

Tracked under #1513