search

trezor / blockbook

:blue_book: Trezor address/account balance backend
https://trezor.io
GNU Affero General Public License v3.0
651 stars 647 forks source link

MQ server shutdown errors logged during normal service stop #587

Closed mcudev closed 3 years ago

mcudev commented 3 years ago

i built and ran a litecoin testnet node from commit 1f6cddd4abaae586f5f1f1b7b6841a056b9fc79c

when i stop the service for these tests, the node is already synced and the system is at a steady barely used state.

i reliably (every time so far) get either "context deadline exceeded" or "MQ loop recovered from runtime error: invalid memory address or nil pointer dereference" messages:

example 1:

root@tltc-blockbook-node-1:/opt/coins/blockbook/litecoin_testnet/logs# systemctl stop blockbook-litecoin-testnet

root@tltc-blockbook-node-1:/opt/coins/blockbook/litecoin_testnet/logs# systemctl status blockbook-litecoin-testnet
● blockbook-litecoin-testnet.service - Blockbook daemon (Litecoin Testnet)
   Loaded: loaded (/lib/systemd/system/blockbook-litecoin-testnet.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Mon 2021-03-29 08:35:31 UTC; 1s ago
  Process: 1580 ExecStart=/opt/coins/blockbook/litecoin_testnet/bin/blockbook -blockchaincfg=/opt/coins/blockbook/litecoin_testnet/config/blockchaincfg.json -datadir=/opt/coins/data/litecoin_testnet/bloc
kbook/db -sync -internal=:19034 -public=:19134 -certfile=/opt/coins/blockbook/litecoin_testnet/cert/blockbook -explorer= -log_dir=/opt/coins/blockbook/litecoin_testnet/logs (code=exited, status=0/SUCCESS
)
 Main PID: 1580 (code=exited, status=0/SUCCESS)

Mar 29 08:35:02 tltc-blockbook-node-1 systemd[1]: Started Blockbook daemon (Litecoin Testnet).
Mar 29 08:35:21 tltc-blockbook-node-1 systemd[1]: Stopping Blockbook daemon (Litecoin Testnet)...
Mar 29 08:35:31 tltc-blockbook-node-1 blockbook[1580]: E0329 08:35:31.510805    1580 bitcoinrpc.go:180] MQ.Shutdown error: context deadline exceeded
Mar 29 08:35:31 tltc-blockbook-node-1 blockbook[1580]: E0329 08:35:31.511484    1580 blockbook.go:689] rpc: shutdown error: context deadline exceeded
Mar 29 08:35:31 tltc-blockbook-node-1 systemd[1]: Stopped Blockbook daemon (Litecoin Testnet).

root@tltc-blockbook-node-1:/opt/coins/blockbook/litecoin_testnet/logs# cat blockbook.ERROR 
Log file created at: 2021/03/29 08:35:31
Running on machine: tltc-blockbook-node-1
Binary: Built with gc go1.15.5 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E0329 08:35:31.510805    1580 bitcoinrpc.go:180] MQ.Shutdown error: context deadline exceeded
E0329 08:35:31.511484    1580 blockbook.go:689] rpc: shutdown error: context deadline exceeded

root@tltc-blockbook-node-1:~# cat /opt/coins/blockbook/litecoin_testnet/logs/blockbook.tltc-blockbook-node-1.blockbook-litecoin.log.INFO.20210329-083502.1580
Log file created at: 2021/03/29 08:35:02
Running on machine: tltc-blockbook-node-1
Binary: Built with gc go1.15.5 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0329 08:35:02.960371    1580 blockbook.go:138] Blockbook: {Version:0.3.4 GitCommit:1f6cddd-dirty BuildTime:2021-03-28T21:14:06+00:00 GoVersion:go1.15.5 OSArch:linux/amd64}, debug mode false
I0329 08:35:02.969800    1580 litecoinrpc.go:40] Chain name test
I0329 08:35:02.969819    1580 litecoinrpc.go:55] rpc: block chain testnet3
I0329 08:35:02.969898    1580 mempool_bitcoin_type.go:56] mempool: starting with 8*2 sync workers
I0329 08:35:02.969912    1580 rocksdb.go:148] rocksdb: opening /opt/coins/data/litecoin_testnet/blockbook/db, required data version 5, cache size 536870912, max open files 16384
I0329 08:35:06.151393    1580 rocksdb.go:1696] loaded 1846347 block times
I0329 08:35:06.277725    1580 worker.go:1793] GetSystemInfo finished in 9.400712ms
I0329 08:35:06.277904    1580 internal.go:68] internal server: starting to listen on https://:19034
I0329 08:35:06.291130    1580 public.go:122] public server starting to listen on https://:19134
I0329 08:35:06.291288    1580 sync.go:126] resync: synced at 1846346 edfd403e3e12310e8d2e6e9172d20055d19b72279b594a8299fb839aec3de2d5
I0329 08:35:06.304445    1580 sync.go:105] resync: finished in 13.75342ms
I0329 08:35:06.304769    1580 mq.go:60] MQ listening to tcp://127.0.0.1:48334
I0329 08:35:06.311001    1580 mempool_bitcoin_type.go:203] mempool: resync finished in 6.199945ms, 3 transactions in mempool
I0329 08:35:06.311249    1580 blockbook.go:737] FiatRates config (/opt/coins/blockbook/litecoin_testnet/config/blockchaincfg.json) is empty, so the functionality is disabled.
I0329 08:35:06.311266    1580 blockbook.go:601] storeInternalStateLoop starting with db stats recompute period 24h56m18.216401052s
I0329 08:35:06.311290    1580 blockbook.go:534] syncIndexLoop starting
I0329 08:35:06.311341    1580 blockbook.go:573] syncMempoolLoop starting
I0329 08:35:15.213093    1580 worker.go:1793] GetSystemInfo finished in 9.308973ms
I0329 08:35:21.510416    1580 blockbook.go:670] shutdown: terminated
I0329 08:35:21.510445    1580 internal.go:80] internal server: shutdown
I0329 08:35:21.510603    1580 blockbook.go:398] internal server: closed
I0329 08:35:22.010866    1580 public.go:207] public server: shutdown
I0329 08:35:22.011394    1580 blockbook.go:418] public server: closed
I0329 08:35:22.511116    1580 mq.go:122] MQ server shutdown
E0329 08:35:31.510805    1580 bitcoinrpc.go:180] MQ.Shutdown error: context deadline exceeded
E0329 08:35:31.511484    1580 blockbook.go:689] rpc: shutdown error: context deadline exceeded
I0329 08:35:31.511518    1580 blockbook.go:628] storeInternalStateLoop stopped
I0329 08:35:31.511526    1580 blockbook.go:546] syncIndexLoop stopped
I0329 08:35:31.511532    1580 blockbook.go:584] syncMempoolLoop stopped
I0329 08:35:31.511705    1580 rocksdb.go:287] rocksdb: close
root@tltc-blockbook-node-1:~# time /opt/coins/nodes/litecoin_testnet/bin/litecoin-cli -testnet -datadir=/opt/coins/data/litecoin_testnet/backend -conf=/opt/coins/nodes/litecoin_testnet/litecoin_testnet.conf getblockcount
1846348

real    0m0.003s
user    0m0.000s
sys 0m0.004s

root@tltc-blockbook-node-1:~# systemctl status blockbook-litecoin-testnet
● blockbook-litecoin-testnet.service - Blockbook daemon (Litecoin Testnet)
   Loaded: loaded (/lib/systemd/system/blockbook-litecoin-testnet.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2021-03-29 08:44:21 UTC; 1min 5s ago
 Main PID: 1726 (blockbook)
    Tasks: 24 (limit: 4915)
   CGroup: /system.slice/blockbook-litecoin-testnet.service
           └─1726 /opt/coins/blockbook/litecoin_testnet/bin/blockbook -blockchaincfg=/opt/coins/blockbook/litecoin_testnet/config/blockchaincfg.json -datadir=/opt/coins/data/litecoin_testnet/blockbook/db
 -sync -internal=:19034 -public=:19134 -certfile=/opt/coins/blockbook/litecoin_testnet/cert/blockbook -explorer= -log_dir=/opt/coins/blockbook/litecoin_testnet/logs

Mar 29 08:44:21 tltc-blockbook-node-1 systemd[1]: Started Blockbook daemon (Litecoin Testnet).
root@tltc-blockbook-node-1:~# systemctl stop blockbook-litecoin-testnet
root@tltc-blockbook-node-1:~# systemctl status blockbook-litecoin-testnet
● blockbook-litecoin-testnet.service - Blockbook daemon (Litecoin Testnet)
   Loaded: loaded (/lib/systemd/system/blockbook-litecoin-testnet.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Mon 2021-03-29 08:45:34 UTC; 2s ago
  Process: 1726 ExecStart=/opt/coins/blockbook/litecoin_testnet/bin/blockbook -blockchaincfg=/opt/coins/blockbook/litecoin_testnet/config/blockchaincfg.json -datadir=/opt/coins/data/litecoin_testnet/bloc
kbook/db -sync -internal=:19034 -public=:19134 -certfile=/opt/coins/blockbook/litecoin_testnet/cert/blockbook -explorer= -log_dir=/opt/coins/blockbook/litecoin_testnet/logs (code=exited, status=0/SUCCESS
)
 Main PID: 1726 (code=exited, status=0/SUCCESS)

Mar 29 08:44:21 tltc-blockbook-node-1 systemd[1]: Started Blockbook daemon (Litecoin Testnet).
Mar 29 08:45:33 tltc-blockbook-node-1 systemd[1]: Stopping Blockbook daemon (Litecoin Testnet)...
Mar 29 08:45:34 tltc-blockbook-node-1 blockbook[1726]: E0329 08:45:34.382810    1726 mq.go:69] MQ loop recovered from runtime error: invalid memory address or nil pointer dereference
Mar 29 08:45:34 tltc-blockbook-node-1 systemd[1]: Stopped Blockbook daemon (Litecoin Testnet).

root@tltc-blockbook-node-1:~# cat /opt/coins/blockbook/litecoin_testnet/logs/blockbook.ERROR
Log file created at: 2021/03/29 08:45:34
Running on machine: tltc-blockbook-node-1
Binary: Built with gc go1.15.5 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E0329 08:45:34.382810    1726 mq.go:69] MQ loop recovered from runtime error: invalid memory address or nil pointer dereference

root@tltc-blockbook-node-1:~# cat /opt/coins/blockbook/litecoin_testnet/logs/blockbook.INFO
Log file created at: 2021/03/29 08:44:21
Running on machine: tltc-blockbook-node-1
Binary: Built with gc go1.15.5 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0329 08:44:21.718848    1726 blockbook.go:138] Blockbook: {Version:0.3.4 GitCommit:1f6cddd-dirty BuildTime:2021-03-28T21:14:06+00:00 GoVersion:go1.15.5 OSArch:linux/amd64}, debug mode false
I0329 08:44:21.732208    1726 litecoinrpc.go:40] Chain name test
I0329 08:44:21.732223    1726 litecoinrpc.go:55] rpc: block chain testnet3
I0329 08:44:21.732297    1726 mempool_bitcoin_type.go:56] mempool: starting with 8*2 sync workers
I0329 08:44:21.732311    1726 rocksdb.go:148] rocksdb: opening /opt/coins/data/litecoin_testnet/blockbook/db, required data version 5, cache size 536870912, max open files 16384
I0329 08:44:24.576976    1726 rocksdb.go:1696] loaded 1846347 block times
I0329 08:44:24.586080    1726 worker.go:1793] GetSystemInfo finished in 8.721198ms
I0329 08:44:24.586372    1726 internal.go:68] internal server: starting to listen on https://:19034
I0329 08:44:24.599574    1726 public.go:122] public server starting to listen on https://:19134
I0329 08:44:24.601356    1726 sync.go:140] resync: local at 1846346 is behind
I0329 08:44:24.892917    1726 sync.go:264] resync: synced at 1846348 cca3a42bcd91d5cba99af233158f274851a8ad419f7dd49bcd5175fa562214e7
I0329 08:44:24.901833    1726 sync.go:91] resync: finished in 302.691407ms
I0329 08:44:24.902619    1726 mq.go:60] MQ listening to tcp://127.0.0.1:48334
I0329 08:44:24.907192    1726 mempool_bitcoin_type.go:203] mempool: resync finished in 4.53675ms, 4 transactions in mempool
I0329 08:44:24.907356    1726 blockbook.go:737] FiatRates config (/opt/coins/blockbook/litecoin_testnet/config/blockchaincfg.json) is empty, so the functionality is disabled.
I0329 08:44:24.907373    1726 blockbook.go:601] storeInternalStateLoop starting with db stats recompute period 27h21m14.189243169s
I0329 08:44:24.907388    1726 blockbook.go:534] syncIndexLoop starting
I0329 08:44:24.907396    1726 blockbook.go:573] syncMempoolLoop starting
I0329 08:44:51.799810    1726 mempool_bitcoin_type.go:203] mempool: resync finished in 3.95708ms, 5 transactions in mempool
I0329 08:45:00.336385    1726 mempool_bitcoin_type.go:203] mempool: resync finished in 3.774999ms, 6 transactions in mempool
I0329 08:45:09.884631    1726 worker.go:1793] GetSystemInfo finished in 10.10174ms
I0329 08:45:24.900384    1726 mempool_bitcoin_type.go:203] mempool: resync finished in 2.310709ms, 7 transactions in mempool
I0329 08:45:33.381720    1726 blockbook.go:670] shutdown: terminated
I0329 08:45:33.381756    1726 internal.go:80] internal server: shutdown
I0329 08:45:33.381837    1726 blockbook.go:398] internal server: closed
I0329 08:45:33.881922    1726 public.go:207] public server: shutdown
I0329 08:45:33.882233    1726 blockbook.go:418] public server: closed
I0329 08:45:34.382422    1726 mq.go:122] MQ server shutdown
E0329 08:45:34.382810    1726 mq.go:69] MQ loop recovered from runtime error: invalid memory address or nil pointer dereference
I0329 08:45:34.383278    1726 mq.go:72] MQ loop terminated
I0329 08:45:34.383289    1726 mq.go:157] MQ server shutdown finished
I0329 08:45:34.383302    1726 blockbook.go:628] storeInternalStateLoop stopped
I0329 08:45:34.383311    1726 blockbook.go:546] syncIndexLoop stopped
I0329 08:45:34.383317    1726 blockbook.go:584] syncMempoolLoop stopped
I0329 08:45:34.383447    1726 rocksdb.go:287] rocksdb: close
martinboehm commented 3 years ago

The MQ shutdown sometimes takes too long time or maybe even hangs waiting for something. To be able to close Blockbook gracefully, we give it only a limited time to complete it. If this deadline is exceeded, you get this error message. However, as it happens in the closing process, it does not cause any harm.