search

kaspanet / rusty-kaspa

Kaspa full-node reference implementation and related libraries in the Rust programming language
ISC License
476 stars 154 forks source link

Bug: Syncing during a pruning point shift idles the node (and probably corrupts the db). #189

Closed D-Stacks closed 1 year ago

D-Stacks commented 1 year ago

Describe the bug Syncing during a pruning point shift may result in the node not accepting blocks, idling in an endless progression of ibd header sync.

To Reproduce Steps to reproduce the behavior: sync a node and make sure it is in the ibd header syncing stage when a pruning point shift occurs.

Expected behavior A node that accepts blocks from peers

Desktop (please complete the following information): OS:

PRETTY_NAME="Ubuntu 22.04.2 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04.2 LTS (Jammy Jellyfish)"
VERSION_CODENAME=jammy
ID=ubuntu
ID_LIKE=debian
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
UBUNTU_CODENAME=jammy

Kaspad:

v. 0.1.0

commit 7f26aa6cac1086e8ac5dc4ed9e1d0f12710d4c89 (HEAD -> prune, origin/prune)
Author: Michael Sutton <msutton@cs.huji.ac.il>
Date:   Mon May 29 18:17:08 2023 +0000

    add lock yield logic to semaphore and rwlock

Additional context Logs:

2023-05-30 15:11:44.192Z [INFO ] kaspad v0.1.0 is when i restarted
...
2023-05-30 15:12:03.723Z [INFO ] Validating level 225 from the pruning point proof
...
2023-05-30 15:12:34.984Z [INFO ] Validating level 0 from the pruning point proof
2023-05-30 15:12:44.285Z [INFO ] Setting d706324b72daf8aa92f008f22d5a336a58fa333ff6572f99b820e84821d8d971 as the current pruning point
2023-05-30 15:12:44.285Z [INFO ] Building the proof which was just applied (sanity test)
2023-05-30 15:12:44.653Z [INFO ] Proof was locally built successfully
2023-05-30 15:12:44.898Z [INFO ] Starting to process 2644 trusted blocks
2023-05-30 15:12:45.898Z [INFO ] Processed 2471 trusted blocks in the last 1.00s (total 2471)
2023-05-30 15:12:45.937Z [INFO ] Done processing trusted blocks
2023-05-30 15:12:54.475Z [INFO ] Processed 3 blocks and 4184 headers in the last 10.00s (6 transactions; 7387 parent references; 0 UTXO-validated blocks; 2.00 avg txs per block; 34046 avg block mass)
2023-05-30 15:12:58.605Z [INFO ] IBD: Processed 3071 block headers (1%)
...
2023-05-30 15:32:48.207Z [INFO ] IBD: Processed 271508 block headers (100%)
2023-05-30 15:32:48.517Z [INFO ] Processed 0 blocks and 1697 headers in the last 10.00s (0 transactions; 2886 parent references; 0 UTXO-validated blocks; 0.00 avg txs per block; 0 avg block mass)
2023-05-30 15:32:49.355Z [INFO ] Received 99 UTXO set chunks so far, totaling in 99000 UTXOs
...
2023-05-30 15:34:19.916Z [INFO ] Finished receiving the UTXO set. Total UTXOs: 8117830
2023-05-30 15:34:19.917Z [INFO ] Importing the UTXO set of the pruning point d706324b72daf8aa92f008f22d5a336a58fa333ff6572f99b820e84821d8d971
2023-05-30 15:34:58.818Z [INFO ] Resyncing the utxoindex...
2023-05-30 15:35:36.515Z [INFO ] Registering p2p flows for peer 49.0.240.99:45994 for protocol version 5
2023-05-30 15:35:36.515Z [INFO ] P2P Connected to incoming peer 49.0.240.99:45994
2023-05-30 15:36:01.118Z [INFO ] P2P, Router receive loop - incoming stream ended from peer 38.242.139.17:16111
2023-05-30 15:36:04.434Z [INFO ] IBD with peer 38.242.139.17:16111 completed with error: ConnectionClosed
2023-05-30 15:36:04.813Z [INFO ] IBD started with peer 51.91.82.136:50408
2023-05-30 15:36:08.575Z [INFO ] Processed 0 blocks and 424 headers in the last 10.00s (0 transactions; 762 parent references; 0 UTXO-validated blocks; 0.00 avg txs per block; 0 avg block mass)
2023-05-30 15:36:12.375Z [INFO ] IBD: Processed 1025 block headers (74%)
2023-05-30 15:36:15.451Z [INFO ] IBD: Processed 1387 block headers (100%)
...
2023-05-30 15:38:41.209Z [INFO ] IBD: Processed 6 block headers (100%)
2023-05-30 15:38:43.077Z [INFO ] P2P, Router receive loop - incoming stream ended from peer 77.37.202.136:16111
2023-05-30 15:38:43.078Z [INFO ] IBD with peer 77.37.202.136:16111 completed with error: ConnectionClosed
2023-05-30 15:38:43.230Z [INFO ] IBD started with peer 193.198.102.245:16111
2023-05-30 15:38:43.382Z [INFO ] IBD: Processed 1 block headers (100%)
2023-05-30 15:38:45.153Z [INFO ] P2P, Router receive loop - incoming stream ended from peer 193.198.102.245:16111
2023-05-30 15:38:45.154Z [INFO ] IBD with peer 193.198.102.245:16111 completed with error: ConnectionClosed
2023-05-30 15:38:45.349Z [INFO ] IBD started with peer 54.39.129.199:40084
2023-05-30 15:38:45.713Z [INFO ] IBD: Processed 3 block headers (100%)

Note: Buggy Behavior is consistent when restarting the node without the --reset-db flag

D-Stacks commented 1 year ago

I believe this issue has been solved.