ironfish
ironfish copied to clipboard
iron-fish
Node stuck after running rescan
What happened?
I run ironfish accounts:rescan, however after 1 day, node stuck. At the moment;
ironfish accounts:rescan command output is;
Scanning Blocks: [===============-------------------------] 51666/142392 36% 0/sec | 2829h 30m 45s
ironfish status command output is;
Version 0.1.46 @ 46d759c
Node STARTED
Node Name Thanos
Block Graffiti pentafenolin
Memory Heap: 421.18 MiB -> 453.27 MiB / 4.00 GiB (10.3%), RSS: 1.47 GiB (9.5%), Free: 11.13 GiB (28.3%)
P2P Network CONNECTED - In: 9.78 KB/s, Out: 103.59 KB/s, peers 47
Mining STARTED - 0 miners, 0 mined
Mem Pool Size: 22469 tx, Bytes: 34.10 MiB
Syncer SYNCING - 0 blocks per seconds, avg time to add block 3355.19 ms
Blockchain 000000000000297ea6f75f924bdd5ae80586887650f9ebb1b5a6a43705de4cea (188034), Since HEAD: 8h 37m (SYNCED)
Accounts SCANNING - 51666 / 142392
Telemetry STARTED - 48694 <- 0 pending
Workers STARTED - 458 -> 6 / 6 - -4.05 jobs Δ, 8.51 jobs/s
ironfish.log output is;
...
[11:12:34.942] [info] [start:ironfishsdk:ironfishnode:blockchain] Added block seq: 188020, hash: 00000...4604a, txs: 83, progress: 100.00%, time: 24210.2ms
[11:14:46.169] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 9 blocks from zWvNMFO (irontest)
[11:16:09.923] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from zWvNMFO (irontest). work: +-342578753484828438, ours: 188021, theirs: 188033
[11:16:09.924] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...efa86 (188021) from peer zWvNMFO (irontest) at 188033
[11:16:10.112] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer zWvNMFO (irontest) ancestor 00000...efa86, syncing from 188021 -> 188033 (12) after 1 requests
[11:16:10.112] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...efa86 (188021) from zWvNMFO (irontest)
[14:22:10.285] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 12 blocks from zWvNMFO (irontest)
[14:22:38.323] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from 0/dyknY (watashix). work: +53686459280722480, ours: 188033, theirs: 188223
[14:22:38.327] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...705b4 (188033) from peer 0/dyknY (watashix) at 188223
[14:22:38.417] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer 0/dyknY (watashix) ancestor 00000...705b4, syncing from 188033 -> 188223 (190) after 1 requests
[14:22:38.418] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...705b4 (188033) from 0/dyknY (watashix)
Right now, time is 19:55 +03:00 UTC and iron fish.log file is far behind the current time. However, iron fish status command shows blockchain is synced but in fact it is not. If I stop and restart the rescan and ironfish node, iron fish will start to sync.
This issue caused the problem in #2175.
Version
v0.1.46
Debug output
Database in use, skipping output that requires database.
Stop the node and run the debug command again to show full output.
Iron Fish version 0.1.46 @ 46d759c
Iron Fish library 0.0.23 @ 46d759c
Operating system Linux x64
CPU model(s) Intel(R) Core(TM) i7-7920HQ CPU @ 3.10GHz
CPU threads 8
RAM total 15.52 GiB
Heap total 4.01 GiB
Node version v16.17.0
ironfish in PATH true
Garbage Collector Exposed false
Telemetry enabled true
Node name Thanos
Block graffiti pentafenolin
Relevant log output
[10:42:03.468] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...74a11 (187991) from zWvNMFO (irontest)
[10:42:14.307] [warn] [start:ironfishsdk:ironfishnode:blockchain] Reorganizing chain from 00000...da6b0 (187992) for 00000...c1d79 (187992) on prev 00000...74a11 (187991)
[10:42:14.351] [warn] [start:ironfishsdk:ironfishnode:blockchain] Reorganized chain. blocks: 1, old: 00000...da6b0 (187992), new: 00000...74a11 (187991), fork: 00000...74a11 (187991)
[10:42:42.542] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 3 blocks from zWvNMFO (irontest)
[10:44:18.027] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from zWvNMFO (irontest). work: +-327175280290526623, ours: 187995, theirs: 187997
[10:44:18.028] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...4519f (187995) from peer zWvNMFO (irontest) at 187997
[10:44:18.791] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer zWvNMFO (irontest) ancestor 00000...4519f, syncing from 187995 -> 187997 (2) after 1 requests
[10:44:18.792] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...4519f (187995) from zWvNMFO (irontest)
[10:45:06.173] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 2 blocks from zWvNMFO (irontest), skipped 1
[10:45:14.907] [warn] [start:ironfishsdk:ironfishnode:blockchain] Reorganizing chain from 00000...4acc1 (187997) for 00000...d19aa (187997) on prev 00000...d62e6 (187996)
[10:45:14.955] [warn] [start:ironfishsdk:ironfishnode:blockchain] Reorganized chain. blocks: 1, old: 00000...4acc1 (187997), new: 00000...d62e6 (187996), fork: 00000...d62e6 (187996)
[10:46:18.609] [warn] [start:ironfishsdk:ironfishnode:blockchain] Reorganizing chain from 00000...d19aa (187997) for 00000...edb80 (187998) on prev 00000...4acc1 (187997)
[10:46:19.186] [warn] [start:ironfishsdk:ironfishnode:blockchain] Reorganized chain. blocks: 2, old: 00000...d19aa (187997), new: 00000...4acc1 (187997), fork: 00000...d62e6 (187996)
[10:47:56.682] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from zWvNMFO (irontest). work: +-328947588250927588, ours: 187998, theirs: 188000
[10:47:56.682] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...edb80 (187998) from peer zWvNMFO (irontest) at 188000
[10:47:56.834] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer zWvNMFO (irontest) ancestor 00000...edb80, syncing from 187998 -> 188000 (2) after 1 requests
[10:47:56.834] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...edb80 (187998) from zWvNMFO (irontest)
[10:50:03.291] [info] [start:ironfishsdk:ironfishnode:blockchain] Added block seq: 188000, hash: 00000...4c89c, txs: 245, progress: 100.00%, time: 33457.7ms
[10:50:03.291] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 2 blocks from zWvNMFO (irontest), skipped 1
[10:51:22.632] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from zWvNMFO (irontest). work: +-330128831535364300, ours: 188000, theirs: 188003
[10:51:22.632] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...4c89c (188000) from peer zWvNMFO (irontest) at 188003
[10:51:22.802] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer zWvNMFO (irontest) ancestor 00000...4c89c, syncing from 188000 -> 188003 (3) after 1 requests
[10:51:22.803] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...4c89c (188000) from zWvNMFO (irontest)
[10:53:27.390] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 3 blocks from zWvNMFO (irontest), skipped 1
[10:54:57.291] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from zWvNMFO (irontest). work: +-331898238714623571, ours: 188003, theirs: 188006
[10:54:57.291] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...d9020 (188003) from peer zWvNMFO (irontest) at 188006
[10:54:57.458] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer zWvNMFO (irontest) ancestor 00000...d9020, syncing from 188003 -> 188006 (3) after 1 requests
[10:54:57.458] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...d9020 (188003) from zWvNMFO (irontest)
[10:57:09.647] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 3 blocks from zWvNMFO (irontest)
[10:57:40.584] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from zWvNMFO (irontest). work: +-333664156805955848, ours: 188006, theirs: 188012
[10:57:40.584] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...99775 (188006) from peer zWvNMFO (irontest) at 188012
[10:57:40.787] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer zWvNMFO (irontest) ancestor 00000...99775, syncing from 188006 -> 188012 (6) after 1 requests
[10:57:40.787] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...99775 (188006) from zWvNMFO (irontest)
[10:59:08.342] [warn] [start:ironfishsdk:ironfishnode:blockchain] Added block to fork seq: 188007, head-seq: 188007, hash: 00000...fce4d, head-hash: 00000...6f43d, work: 9925460440230392191, head-work: 9925460440230392191, work-diff: 0
[11:04:21.695] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 6 blocks from zWvNMFO (irontest)
[11:04:39.256] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from zWvNMFO (irontest). work: +-337213521382921349, ours: 188012, theirs: 188021
[11:04:39.256] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...ffcac (188012) from peer zWvNMFO (irontest) at 188021
[11:04:39.451] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer zWvNMFO (irontest) ancestor 00000...ffcac, syncing from 188012 -> 188021 (9) after 1 requests
[11:04:39.451] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...ffcac (188012) from zWvNMFO (irontest)
[11:12:34.942] [info] [start:ironfishsdk:ironfishnode:blockchain] Added block seq: 188020, hash: 00000...4604a, txs: 83, progress: 100.00%, time: 24210.2ms
[11:14:46.169] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 9 blocks from zWvNMFO (irontest)
[11:16:09.923] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from zWvNMFO (irontest). work: +-342578753484828438, ours: 188021, theirs: 188033
[11:16:09.924] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...efa86 (188021) from peer zWvNMFO (irontest) at 188033
[11:16:10.112] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer zWvNMFO (irontest) ancestor 00000...efa86, syncing from 188021 -> 188033 (12) after 1 requests
[11:16:10.112] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...efa86 (188021) from zWvNMFO (irontest)
[14:22:10.285] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 12 blocks from zWvNMFO (irontest)
[14:22:38.323] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from 0/dyknY (watashix). work: +53686459280722480, ours: 188033, theirs: 188223
[14:22:38.327] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...705b4 (188033) from peer 0/dyknY (watashix) at 188223
[14:22:38.417] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer 0/dyknY (watashix) ancestor 00000...705b4, syncing from 188033 -> 188223 (190) after 1 requests
[14:22:38.418] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...705b4 (188033) from 0/dyknY (watashix)
Graffiti
pentafenolin
Almost 2 hours passed from my post and time stamp of last record in ironfish.log is still 14:22:38.418.
UPDATE:
I stopped node by iron fish stop
Scanning Blocks: [===============-------------------------] 51669/142392 36% 0/sec | 2194h 3m 51s
Log Output:
[14:22:10.285] [info] [start:ironfishsdk:ironfishnode:syncer] Finished syncing 12 blocks from zWvNMFO (irontest)
[14:22:38.323] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from 0/dyknY (watashix). work: +53686459280722480, ours: 188033, theirs: 188223
[14:22:38.327] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...705b4 (188033) from peer 0/dyknY (watashix) at 188223
[14:22:38.417] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer 0/dyknY (watashix) ancestor 00000...705b4, syncing from 188033 -> 188223 (190) after 1 requests
[14:22:38.418] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...705b4 (188033) from 0/dyknY (watashix)
[02:12:31.226] [info] [start:ironfishsdk:ironfishnode:stopnode] Shutting down
[02:12:31.291] [info] [start:ironfishsdk:ironfishnode:peernetwork] Not connected to the Iron Fish network
I restarted Node and the status is below:
Version 0.1.46 @ 46d759c
Node STARTED
Node Name Thanos
Block Graffiti pentafenolin
Memory Heap: 49.40 MiB -> 71.44 MiB / 4.00 GiB (1.2%), RSS: 463.51 MiB (2.9%), Free: 12.12 GiB (21.9%)
P2P Network CONNECTED - In: 1.66 KB/s, Out: 2.83 KB/s, peers 7
Mining STARTED - 0 miners, 0 mined
Mem Pool Size: 0 tx, Bytes: 0 B
Syncer SYNCING - 0 blocks per seconds, progress: 99.52%
Blockchain 0000000000000d42aeb69907f2e85e1c495e9edad5196d26749648b1959c29da (188037), Since HEAD: 14h 58m (NOT SYNCED)
Accounts 00000000000520ffc08594303998a3cafcb92d641328e2b95a107b0fb313dc9f (142460)
Telemetry STARTED - 0 <- 1 pending
Workers STARTED - 0 -> 1 / 6 - 0.01 jobs Δ, 273.26 jobs/s
Log Output:
[14:22:38.417] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer 0/dyknY (watashix) ancestor 00000...705b4, syncing from 188033 -> 188223 (190) after 1 requests
[14:22:38.418] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...705b4 (188033) from 0/dyknY (watashix)
[02:12:31.226] [info] [start:ironfishsdk:ironfishnode:stopnode] Shutting down
[02:12:31.291] [info] [start:ironfishsdk:ironfishnode:peernetwork] Not connected to the Iron Fish network
[02:19:13.633] [info] [start:ironfishsdk:ironfishnode:peernetwork] WebSocket server started at :::9033
[02:19:14.022] [info] [start:ironfishsdk:ironfishnode:peernetwork] Connected to the Iron Fish network
[02:19:34.026] [info] [start:ironfishsdk:ironfishnode:syncer] Starting sync from 0tklKbP (xutrusnode). work: +363696156281560485, ours: 188037, theirs: 188640
[02:19:34.026] [info] [start:ironfishsdk:ironfishnode:syncer] Finding ancestor using linear search on last 3 blocks starting at 00000...c29da (188037) from peer 0tklKbP (xutrusnode) at 188640
[02:19:34.271] [info] [start:ironfishsdk:ironfishnode:syncer] Found peer 0tklKbP (xutrusnode) ancestor 00000...c29da, syncing from 188037 -> 188640 (603) after 1 requests
[02:19:34.271] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...c29da (188037) from 0tklKbP (xutrusnode)
[02:19:41.149] [info] [start:ironfishsdk:ironfishnode:blockchain] Added block seq: 188040, hash: 00000...766a6, txs: 14, progress: 99.52%, time: 177.9ms
[02:20:04.046] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...2f07c (188057) from 0tklKbP (xutrusnode)
[02:20:10.820] [info] [start:ironfishsdk:ironfishnode:blockchain] Added block seq: 188060, hash: 00000...1cadd, txs: 26, progress: 99.54%, time: 473.3ms
[02:20:31.561] [info] [start:ironfishsdk:ironfishnode:syncer] Requesting 20 blocks starting at 00000...a210a (188077) from 0tklKbP (xutrusnode)
Closing due to staleness. If the issue persists in versions 1.0.0+ - please file a new issue
