[Bug] Chia full node cannot finish starting up

[yjiangnan]

What happened?

I upgraded from 1.2.3 that has been running smoothly for a long time to version 1.2.11. The starting up of full node never finish after hours:

:~/chia-blockchain-1.2.11$ chia start node
Daemon not started yet
Starting daemon
chia_full_node: started

:~/chia-blockchain-1.2.11$ chia show -c
Connection error. Check if full node rpc is running at 8555
This is normal if full node is still starting up

No matter how long I wait, chia show -c shows the same result. top command shows that chia_full_node is running, with less than 10% CPU usage. The log file shows ONLY the following:

2021-11-29T14:14:07.767 daemon chia.daemon.server         : INFO     Starting Daemon Server
2021-11-29T14:14:07.769 daemon chia.daemon.server         : INFO     Waiting Daemon WebSocketServer closure
2021-11-29T14:14:10.720 full_node chia.full_node.full_node: INFO     Default port field not found in config.

What is going wrong and what should I do?

Version

1.2.11

What platform are you using?

Linux

What ui mode are you using?

CLI

[Jangir92]

Здраствуйте. я думаю ошибка в последней версии chia.установите старую версию 1.1.2 и попробуйте зайти заново.

[Jangir92]

1.2.0

[loppefaaret]

perhaps if you can locate your debug.log and attach it to this discussion, i might be able to see if there is anything useful reported in there, that can shed some light on your issue ?

[max918]

it may up to 2 hours to startup the first full_node process if your database file store in a HDD

[yjiangnan]

@loppefaaret It seems that the problem is just that the new version is very slow and I eventually got connections. However, the farming may be just too slow for a larger farm as shown in the log that I saved for version 1.2.11:

2021-11-29T14:14:07.767 daemon chia.daemon.server         : INFO     Starting Daemon Server
2021-11-29T14:14:07.769 daemon chia.daemon.server         : INFO     Waiting Daemon WebSocketServer closure
2021-11-29T14:14:10.720 full_node chia.full_node.full_node: INFO     Default port field not found in config.
2021-11-29T14:40:05.282 full_node chia.full_node.full_node: INFO     Initializing blockchain from disk
2021-11-29T14:40:05.337 full_node chia.consensus.blockchain: INFO     Started 2 processes for block validation
2021-11-29T14:46:42.058 full_node full_node               : INFO     got signal 15
2021-11-29T14:46:42.059 full_node full_node               : INFO     Cancelling reconnect task
2021-11-29T14:46:42.059 full_node full_node               : INFO     Closing connections
2021-11-29T14:46:48.129 daemon chia.daemon.server         : INFO     sending term signal to chia_full_node
2021-11-29T14:46:48.132 full_node full_node               : INFO     got signal 15
2021-11-29T14:47:03.144 full_node full_node               : INFO     got signal 15
2021-11-29T14:47:03.155 daemon chia.daemon.server         : INFO     sending kill signal to chia_full_node
2021-11-29T14:47:03.194 daemon chia.daemon.server         : INFO     process chia_full_node returned -9
2021-11-29T14:47:03.195 daemon chia.daemon.server         : INFO     chia daemon exiting in 5 seconds
2021-11-29T14:47:03.195 daemon chia.daemon.server         : INFO     Daemon WebSocketServer closed
2021-11-29T14:58:17.472 full_node chia.full_node.full_node: ERROR    Error with syncing: <class 'RuntimeError'>Traceback (most recent call last):
  File "/home/dong/chia-blockchain-1.2.11/chia/full_node/full_node.py", line 807, in _sync
    raise RuntimeError(f"Weight proof did not arrive in time from peer: {weight_proof_peer.peer_host}")
RuntimeError: Weight proof did not arrive in time from peer: 51.154.0.79

2021-11-29T15:00:53.033 full_node chia.full_node.coin_store: WARNING  It took 13.12s to apply 171 additions and 14 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:02:37.937 full_node chia.full_node.coin_store: WARNING  It took 31.98s to apply 521 additions and 46 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:06:42.137 full_node chia.full_node.coin_store: WARNING  It took 33.08s to apply 653 additions and 33 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:08:30.169 full_node chia.full_node.coin_store: WARNING  It took 14.36s to apply 272 additions and 36 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:10:01.824 full_node chia.full_node.coin_store: WARNING  It took 39.98s to apply 781 additions and 200 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:10:49.937 full_node chia.full_node.coin_store: WARNING  It took 30.13s to apply 634 additions and 30 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:11:59.246 full_node chia.full_node.coin_store: WARNING  It took 12.24s to apply 245 additions and 100 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:12:40.157 full_node chia.full_node.coin_store: WARNING  It took 13.47s to apply 303 additions and 32 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:13:02.231 full_node chia.full_node.coin_store: WARNING  It took 10.02s to apply 221 additions and 56 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:14:19.954 full_node chia.full_node.coin_store: WARNING  It took 11.49s to apply 111 additions and 267 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:15:17.457 full_node chia.full_node.coin_store: WARNING  It took 36.23s to apply 783 additions and 34 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:16:47.011 full_node chia.full_node.coin_store: WARNING  It took 28.86s to apply 668 additions and 8 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:18:49.704 full_node chia.full_node.coin_store: WARNING  It took 33.47s to apply 762 additions and 168 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:33:52.599 full_node chia.full_node.full_node: WARNING  Block validation time: 3.84 seconds, pre_validation time: 0.21 seconds, cost: 452398979, percent full: 4.113%
2021-11-29T15:33:59.322 full_node chia.full_node.full_node: WARNING  Block validation time: 2.97 seconds, pre_validation time: 0.82 seconds, cost: 408435445, percent full: 3.713%
2021-11-29T15:34:03.715 full_node chia.full_node.full_node: WARNING  Block validation time: 4.39 seconds, pre_validation time: 0.18 seconds, cost: 528835035, percent full: 4.808%
2021-11-29T15:34:41.934 full_node chia.full_node.full_node: WARNING  Block validation time: 2.92 seconds, pre_validation time: 0.16 seconds, cost: 624604497, percent full: 5.678%
2021-11-29T15:36:58.386 full_node chia.full_node.full_node: WARNING  Block validation time: 5.79 seconds, pre_validation time: 0.19 seconds, cost: 454524230, percent full: 4.132%
2021-11-29T15:36:58.390 full_node full_node_server        : WARNING  Cannot write to closing transport 96.125.247.244
2021-11-29T15:38:08.203 full_node chia.full_node.full_node: WARNING  Block validation time: 5.66 seconds, pre_validation time: 0.17 seconds, cost: 733520527, percent full: 6.668%
2021-11-29T15:39:57.122 full_node chia.full_node.coin_store: WARNING  It took 13.26s to apply 327 additions and 76 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:39:59.244 full_node chia.full_node.full_node: WARNING  Block validation time: 15.61 seconds, pre_validation time: 0.17 seconds, cost: 1309576918, percent full: 11.905%
2021-11-29T15:40:41.788 full_node chia.full_node.full_node: WARNING  Block validation time: 2.05 seconds, pre_validation time: 0.18 seconds, cost: 226642496, percent full: 2.06%
2021-11-29T15:43:28.431 full_node chia.full_node.full_node: WARNING  Block validation time: 2.21 seconds, pre_validation time: 0.20 seconds, cost: 317768468, percent full: 2.889%
2021-11-29T15:45:49.638 full_node chia.full_node.full_node: WARNING  Block validation time: 2.19 seconds, pre_validation time: 0.23 seconds, cost: 624442203, percent full: 5.677%
2021-11-29T15:46:09.998 full_node full_node_server        : WARNING  Cannot write to closing transport 85.237.57.172
2021-11-29T15:47:01.917 full_node chia.full_node.full_node: WARNING  Block validation time: 5.00 seconds, pre_validation time: 0.22 seconds, cost: 1805982267, percent full: 16.418%
2021-11-29T15:50:00.295 full_node chia.full_node.full_node: WARNING  Block validation time: 3.48 seconds, pre_validation time: 0.18 seconds, cost: 459429875, percent full: 4.177%
2021-11-29T15:51:27.983 full_node chia.full_node.coin_store: WARNING  It took 31.41s to apply 737 additions and 17 removals to the coin store. Make sure blockchain database is on a fast drive
2021-11-29T15:51:30.568 full_node chia.full_node.full_node: WARNING  Block validation time: 34.35 seconds, pre_validation time: 0.25 seconds, cost: 1837911060, percent full: 16.708%
....... Similar results go on and on

We have a 5P farm with ~350 disks (16T each) distributed on 10 harvesters.
The database file is indeed stored in HDD, but our farm works very well before I upgraded to the newest version. The new version apparently is too inefficient for larger farms. If it took 30s to apply changes, does that affect the chance of winning blocks?

[cciollaro]

For the Default port field not found in config.:

You can edit your ~/.chia/mainnet/config/config.yaml and add the following line: https://github.com/Chia-Network/chia-blockchain/blob/main/chia/util/initial-config.yaml#L73

At least that helped me - it seems like older versions of chia-blockchain didn't include that config value and then at some point it became required?

[yjiangnan]

@cciollaro Maybe. I ended up recreating the config file and the warning is now gone.
Why is the full node so slow now and it often takes 30 ~ 60s to finish some steps? Should I be concerned? Does it affect farming?

2021-12-06T01:03:04.192 full_node chia.full_node.coin_store: WARNING  It took 48.47s to apply 811 additions and 28 removals to the coin store. Make sure blockchain databas
e is on a fast drive
2021-12-06T01:03:04.225 full_node chia.full_node.mempool_manager: WARNING  add_spendbundle 07d12c42b5bba0a010e9e8d37e6e42dd4f359df95d135c73686cf0360129e976 took 38.78 seco
nds. Cost: 610010476 (5.546% of max block cost)
2021-12-06T01:03:08.569 full_node chia.full_node.mempool_manager: WARNING  add_spendbundle 1da8fb13496559f3421b2a72af884ba98dbab44791a4191fb8d5f8f79470a050 took 4.26 secon
ds. Cost: 13302342 (0.121% of max block cost)
2021-12-06T01:03:08.600 full_node chia.full_node.full_node: WARNING  Block validation time: 52.97 seconds, cost: 2125468483, percent full: 19.322%
2021-12-06T01:03:24.446 full_node chia.full_node.coin_store: WARNING  It took 15.12s to apply 257 additions and 5 removals to the coin store. Make sure blockchain database
 is on a fast drive
2021-12-06T01:03:24.588 full_node chia.full_node.full_node: WARNING  Block validation time: 15.85 seconds, cost: 626270032, percent full: 5.693%
2021-12-06T01:06:38.004 full_node chia.full_node.full_node: WARNING  Block validation time: 2.31 seconds, cost: 283078405, percent full: 2.573%
2021-12-06T01:07:10.236 full_node chia.full_node.full_node: WARNING  Block validation time: 2.63 seconds, cost: 115803374, percent full: 1.053%
2021-12-06T01:08:06.632 full_node chia.full_node.coin_store: WARNING  It took 18.36s to apply 327 additions and 6 removals to the coin store. Make sure blockchain database
 is on a fast drive
2021-12-06T01:08:08.076 full_node chia.full_node.full_node: WARNING  Block validation time: 20.11 seconds, cost: 796241824, percent full: 7.239%
2021-12-06T01:10:08.042 full_node chia.full_node.mempool_manager: WARNING  add_spendbundle b9d0a98d958d43325210f7f0290d93350293c1c35b3c54b03615502105bd3ae6 took 1.52 secon
ds. Cost: 240766192 (2.189% of max block cost)
2021-12-06T01:10:38.652 full_node chia.full_node.full_node: WARNING  Block validation time: 2.21 seconds, cost: 201547256, percent full: 1.832%
2021-12-06T01:12:09.474 full_node chia.full_node.mempool_manager: WARNING  add_spendbundle e11dd061accbdcb331d269eff3621ead575efba397a4c1c64c74a07201916646 took 1.26 secon
ds. Cost: 128564081 (1.169% of max block cost)
2021-12-06T01:13:08.929 full_node chia.full_node.full_node: WARNING  Block validation time: 3.88 seconds, cost: 655908123, percent full: 5.963%
2021-12-06T01:14:56.968 full_node chia.full_node.full_node: WARNING  Block validation time: 2.97 seconds, cost: 288330399, percent full: 2.621%

[loppefaaret]

Yes, having the node in some instances taking 50+ seconds to validate a single block, makes it fall behind so far, that the next couple of rounds are lost! if you were to have a winning proof in the round after a 30+ seconds block validation, it would be lost - i would aim to keep it below 10 seconds, and take steps to improve perfomance if it ever hits 20... you can get fairly cheap SSD's now a days, that are plenty big enough to hold the entire blockchain database for some time. That being said - work on improving the database is ongoing, and are looking promising