0.14.0 long shutdown delay, due to onion listening (but not running tor) #10025

issue mmortal03 opened this issue on March 18, 2017
  1. mmortal03 commented at 1:03 AM on March 18, 2017: none

    After having run bitcoin-qt 0.14.0 for a while on Windows 10 64-bit (it needs to have run the node for a number of hours to reproduce) I closed bitcoin-qt. The "do not shutdown computer" message stayed up for almost two hours before it finally closed.

    I have been experiencing this issue consistently, and this delay has lasted even longer in prior instances (i.e. lasting for many more hours). The delay seems to be proportional to how long bitcoin-qt has been running. See below an example debug.log after closing bitcoin-qt this particular time.

    2017-03-16 22:03:23 tor: Thread interrupt 2017-03-16 22:03:23 addcon thread exit 2017-03-16 22:03:23 opencon thread exit 2017-03-16 22:03:23 scheduler thread interrupt 2017-03-16 22:03:23 Shutdown: In progress... 2017-03-16 22:03:23 msghand thread exit 2017-03-16 22:03:23 net thread exit 2017-03-16 23:56:07 torcontrol thread exit 2017-03-16 23:56:14 Dumped mempool: 0.031193s to copy, 6.97686s to dump 2017-03-16 23:56:23 Shutdown: done

    Take note of the torcontrol thread not closing until almost 2 hours later. I'm not sure if this is just a coincidence or actually caused by the torcontrol thread taking forever to close, but at least it's a start. I am not running tor, but I realize that, by default, Bitcoin Core now listens for onion routing. I suspect that turning off onion listening would work around this bug (listenonion=0), but I haven't confirmed this yet (would take a while to test). In the meantime, I will let bitcoin-qt run again for a number of hours with listenonion=1 and debug=tor to see if anything more interesting appears in the log after an extended period of time.

    For reference, all default settings are being used for this node, except I have maxuploadtarget set to 144.

    Other possibly unique variables to consider with this node are:

    1.) I happen to have purposely banned a good number of non-Bitcoin Core peers, one by one, manually for a year over the past year. Not sure if this could interfere in any way.

    2.) While datadir is set to the default, the actual default directory in Windows is set up as a symbolic link, pointing to a directory on a USB 3.0 external drive. I don't know how this would interfere with closing a torcontrol thread, but I just thought I'd mention it to cover all bases.

  2. sipa commented at 1:11 AM on March 18, 2017: member

    Can you run with -debug and try again? More things should be written to debug.log. I suspect that the tor control thread doesn't actually have anything to do with it, but it is the first thing that is reported.

  3. laanwj commented at 8:16 AM on March 18, 2017: member

    I suspect that turning off onion listening would work around this bug (listenonion=0), but I haven't confirmed this yet (would take a while to test)

    This would be a good next thing to test, to either rule it out or narrow down the issue.

    I find it really strange that the torcontrol thread would hang if there is no Tor running. Do you perhaps have anything else listening on Tor's default control port 9051?

    (even then I'd find it unlikely because torcontrol is supposed to just slam the control connection shut when terminating, it shouldn't try to wait for anything)

  4. mmortal03 commented at 10:05 AM on March 18, 2017: none

    Can you run with -debug and try again? More things should be written to debug.log. I suspect that the tor control thread doesn't actually have anything to do with it, but it is the first thing that is reported.

    Yep, will do. I've got to run it for a while to reproduce, so I'll post the full -debug tomorrow.

    For now, here it is with debug=tor (it took almost three hours for it to close this time):

    2017-03-18 07:09:17 tor: Thread interrupt 2017-03-18 07:09:17 GUI: QItemSelectionModel: Selecting when no model has been set will result in a no-op. 2017-03-18 07:09:17 GUI: QItemSelectionModel: Selecting when no model has been set will result in a no-op. 2017-03-18 07:09:17 GUI: QItemSelectionModel: Selecting when no model has been set will result in a no-op. 2017-03-18 07:09:17 opencon thread exit 2017-03-18 07:09:17 addcon thread exit 2017-03-18 07:09:17 scheduler thread interrupt 2017-03-18 07:09:17 Shutdown: In progress... 2017-03-18 07:09:17 msghand thread exit 2017-03-18 07:09:17 net thread exit 2017-03-18 09:52:18 torcontrol thread exit 2017-03-18 09:52:20 Dumped mempool: 0.015521s to copy, 1.46903s to dump 2017-03-18 09:52:27 Shutdown: done

  5. mmortal03 commented at 10:25 AM on March 18, 2017: none

    This would be a good next thing to test, to either rule it out or narrow down the issue.

    Yeah, tomorrow I will run it with listenonion=0 for an extended period of time to see. Before I do that, let me first produce the full debug log for sipa with listenonion=1.

    I find it really strange that the torcontrol thread would hang if there is no Tor running. Do you perhaps have anything else listening on Tor's default control port 9051?

    Nope, not that I know of. I just ran an nmap scan of ports 1-10000, and that port is not open.

  6. laanwj commented at 10:35 AM on March 18, 2017: member

    Nope, not that I know of. I just ran an nmap scan of ports 1-10000, and that port is not open.

    Is the port perhaps firewalled? If you connect to 127.0.0.1:9051 (say, with telnet), do you get connection refused or does it hang?

  7. mmortal03 commented at 10:55 AM on March 18, 2017: none

    Is the port perhaps firewalled?

    Yeah, Windows Firewall should be blocking it by default. I just checked, and there are no rules specific to 9051 inbound or outbound.

    If you connect to 127.0.0.1:9051 (say, with telnet), do you get connection refused or does it hang?

    On the local machine, telnet gives me: "Could not open connection to the host, on port 9051: Connect failed"

    I also tried to telnet into that port from another machine on the network to the machine's IP address, and got the same thing: "Could not open connection to the host, on port 9051: Connect failed"

  8. laanwj commented at 11:14 AM on March 18, 2017: member

    OK it's not timing out on that at least, then.

  9. mmortal03 commented at 11:19 AM on March 18, 2017: none

    Correct.

  10. mmortal03 commented at 4:54 PM on March 18, 2017: none

    @sipa , here is the requested portion of the debug.log with listenonion=1 and debug=1. Not much more to go on, it seems. This time it took an hour and 20 minutes to shutdown. Next up, I will run it again for an extended period of time with listenonion=0 and debug=1, and see how long it takes to shutdown.

    2017-03-18 15:09:39 GUI: requestShutdown : Requesting shutdown 2017-03-18 15:09:39 GUI: shutdown : Running Shutdown in thread 2017-03-18 15:09:39 Interrupting HTTP server 2017-03-18 15:09:39 Interrupting HTTP RPC server 2017-03-18 15:09:39 Interrupting RPC 2017-03-18 15:09:39 tor: Thread interrupt 2017-03-18 15:09:39 opencon thread exit 2017-03-18 15:09:39 addcon thread exit 2017-03-18 15:09:39 scheduler thread interrupt 2017-03-18 15:09:39 Shutdown: In progress... 2017-03-18 15:09:39 Stopping HTTP RPC server 2017-03-18 15:09:39 Stopping RPC 2017-03-18 15:09:39 Stopping HTTP server 2017-03-18 15:09:39 Stopped HTTP server 2017-03-18 15:09:39 net thread exit 2017-03-18 15:09:39 msghand thread exit 2017-03-18 15:09:40 Flushed 70649 addresses to peers.dat 453ms 2017-03-18 15:09:40 disconnecting peer=1 2017-03-18 15:09:40 disconnecting peer=2 2017-03-18 15:09:40 disconnecting peer=3 2017-03-18 15:09:40 disconnecting peer=4 2017-03-18 15:09:40 disconnecting peer=12 2017-03-18 15:09:40 disconnecting peer=13 2017-03-18 15:09:40 disconnecting peer=36 2017-03-18 15:09:40 disconnecting peer=44 2017-03-18 16:29:06 torcontrol thread exit 2017-03-18 16:29:11 Dumped mempool: 0.046704s to copy, 5.39117s to dump 2017-03-18 16:29:14 Committing 87908 changed transactions (out of 111146) to coin database... 2017-03-18 16:29:18 Shutdown: done 2017-03-18 16:29:18 GUI: shutdown : Shutdown finished 2017-03-18 16:29:18 GUI: ~BitcoinApplication : Stopping thread 2017-03-18 16:29:18 GUI: ~BitcoinApplication : Stopped thread

  11. mmortal03 commented at 4:31 AM on March 19, 2017: none

    I just finished testing it with listenonion=0, ran the node for 12 hours, requested shutdown, and shutdown happened almost immediately -- so disabling listenonion does seem to solve the problem. Here's the log:

    2017-03-19 04:22:08 GUI: requestShutdown : Requesting shutdown 2017-03-19 04:22:08 GUI: shutdown : Running Shutdown in thread 2017-03-19 04:22:08 Interrupting HTTP server 2017-03-19 04:22:08 Interrupting HTTP RPC server 2017-03-19 04:22:08 Interrupting RPC 2017-03-19 04:22:08 opencon thread exit 2017-03-19 04:22:08 addcon thread exit 2017-03-19 04:22:08 scheduler thread interrupt 2017-03-19 04:22:08 Shutdown: In progress... 2017-03-19 04:22:08 Stopping HTTP RPC server 2017-03-19 04:22:08 Stopping RPC 2017-03-19 04:22:08 Stopping HTTP server 2017-03-19 04:22:08 Stopped HTTP server 2017-03-19 04:22:08 net thread exit 2017-03-19 04:22:08 msghand thread exit 2017-03-19 04:22:09 Flushed 70698 addresses to peers.dat 437ms 2017-03-19 04:22:09 disconnecting peer=4 2017-03-19 04:22:09 disconnecting peer=5 2017-03-19 04:22:09 disconnecting peer=6 2017-03-19 04:22:09 disconnecting peer=7 2017-03-19 04:22:09 disconnecting peer=9 2017-03-19 04:22:09 disconnecting peer=10 2017-03-19 04:22:09 disconnecting peer=11 2017-03-19 04:22:09 disconnecting peer=13 2017-03-19 04:22:09 Erased 1 orphan tx from peer=5 2017-03-19 04:22:09 Erased 3 orphan tx from peer=6 2017-03-19 04:22:09 Erased 1 orphan tx from peer=7 2017-03-19 04:22:09 Erased 1 orphan tx from peer=13 2017-03-19 04:22:10 Dumped mempool: 0.015595s to copy, 0.859461s to dump 2017-03-19 04:22:13 Committing 176691 changed transactions (out of 183909) to coin database... 2017-03-19 04:22:16 Shutdown: done 2017-03-19 04:22:16 GUI: shutdown : Shutdown finished 2017-03-19 04:22:16 GUI: ~BitcoinApplication : Stopping thread 2017-03-19 04:22:16 GUI: ~BitcoinApplication : Stopped thread

  12. laanwj added the label P2P on Mar 24, 2017
  13. laanwj renamed this:
    0.14.0 long shutdown delay, possibly due to onion listening (but not running tor)
    0.14.0 long shutdown delay, due to onion listening (but not running tor)
    on Mar 25, 2017
  14. laanwj commented at 8:38 AM on March 25, 2017: member

    That narrows it down to the onion control. Removed the 'possibly' from the PR title.

  15. MarcoFalke commented at 12:30 AM on April 27, 2020: member

    Is this still an issue with a recent version of Bitcoin Core? If yes, what are the steps to reproduce?

  16. MarcoFalke closed this on Apr 27, 2020
  17. bilthon commented at 12:23 AM on August 10, 2020: none

    I just ran unto a similar issue with v0.20.1 on Ubuntu 19.10. I don't have the tor daemon active on this machine, but the problem persists even after adding listenonion=0 to the configuration file.

    I've compiled this version from source using the commit 7ff64311bee570874c4f0dfa18f518552188df08.

    And since I keep having to kill the bitcoind process, it keeps restarting from height 0. Is there any other reason why this could be happening?

    These are the last lines of my debug.log file after a bitcoin-cli stop

    2020-08-10T00:26:28Z BlockConnected: block hash=000000002e9333b3570f69a706f78c430f06d1c08e38ded06c78a5d670908c9f block height=47812
2020-08-10T00:26:28Z WriteBatch memory usage: db=txindex, before=3.4MiB, after=3.4MiB
2020-08-10T00:26:28Z Requesting block 0000000008d6bce54a007efd7adaec784713dd06de5b8d4d46fec70dbaeae243 (48309) peer=10
2020-08-10T00:26:28Z sending getdata (37 bytes) peer=10
2020-08-10T00:26:28Z WriteBatch memory usage: db=db, before=6.4MiB, after=6.4MiB
2020-08-10T00:26:28Z UpdatedBlockTip: new block hash=000000002e9333b3570f69a706f78c430f06d1c08e38ded06c78a5d670908c9f fork block hash=000000003665e4b5eb01832cf6b2aaa359b284b08cd5e10e079d5474a9ba28ad (in IBD=true)
2020-08-10T00:26:28Z Interrupting HTTP server
2020-08-10T00:26:28Z Interrupting HTTP RPC server
2020-08-10T00:26:28Z Interrupting RPC
2020-08-10T00:26:28Z Shutdown: In progress...
2020-08-10T00:26:28Z addcon thread exit
2020-08-10T00:26:28Z Stopping HTTP RPC server
2020-08-10T00:26:28Z Unregistering HTTP handler for / (exactmatch 1)
2020-08-10T00:26:28Z Unregistering HTTP handler for /wallet/ (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/tx/ (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/block/notxdetails/ (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/block/ (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/chaininfo (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/mempool/info (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/mempool/contents (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/headers/ (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/getutxos (exactmatch 0)
2020-08-10T00:26:28Z Unregistering HTTP handler for /rest/blockhashbyheight/ (exactmatch 0)
2020-08-10T00:26:28Z Stopping RPC
2020-08-10T00:26:28Z RPC stopped.
2020-08-10T00:26:28Z Stopping HTTP server
2020-08-10T00:26:28Z Waiting for HTTP worker threads to exit
2020-08-10T00:26:28Z libevent: event_del: 0x557149dcbf18 (fd 9), callback 0x7f2bd359b0d0
2020-08-10T00:26:28Z libevent: Epoll DEL(1) on fd 9 okay. Old events were 2; read change was 2 (del); write change was 0 (none); close change was 0 (none)
2020-08-10T00:26:28Z libevent: epoll_dispatch: epoll_wait reports 1
2020-08-10T00:26:28Z libevent: event_active: 0x557149dcb010 (fd 8), res 2, callback 0x7f2bd358d980
2020-08-10T00:26:28Z net thread exit
2020-08-10T00:26:28Z libevent: event_process_active: event: 0x557149dcb010, EV_READ   call 0x7f2bd358d980
2020-08-10T00:26:28Z libevent: event_del: 0x557149dcb8f8 (fd 10), callback 0x7f2bd359b0d0
2020-08-10T00:26:28Z libevent: Epoll DEL(1) on fd 10 okay. Old events were 2; read change was 2 (del); write change was 0 (none); close change was 0 (none)
2020-08-10T00:26:28Z Waiting for HTTP event thread to exit
2020-08-10T00:26:28Z libevent: epoll_dispatch: epoll_wait reports 1
2020-08-10T00:26:28Z libevent: event_active: 0x557149dcb010 (fd 8), res 2, callback 0x7f2bd358d980
2020-08-10T00:26:28Z libevent: event_process_active: event: 0x557149dcb010, EV_READ   call 0x7f2bd358d980
2020-08-10T00:26:28Z libevent: event_base_loop: no events registered.
2020-08-10T00:26:28Z Exited http event loop
2020-08-10T00:26:28Z libevent: event_del: 0x557149dcb010 (fd 8), callback 0x7f2bd358d980
2020-08-10T00:26:28Z libevent: Epoll DEL(1) on fd 8 okay. Old events were 2; read change was 2 (del); write change was 0 (none); close change was 0 (none)
2020-08-10T00:26:28Z Stopped HTTP server
2020-08-10T00:26:28Z BerkeleyEnvironment::Flush: [/home/bilthon/.bitcoin] Flush(false)
2020-08-10T00:26:28Z BerkeleyEnvironment::Flush: Flushing wallet.dat (refcount = 0)...
2020-08-10T00:26:28Z BerkeleyEnvironment::Flush: wallet.dat checkpoint
2020-08-10T00:26:28Z BerkeleyEnvironment::Flush: wallet.dat detach
2020-08-10T00:26:29Z msghand thread exit
2020-08-10T00:26:29Z BerkeleyEnvironment::Flush: wallet.dat closed
2020-08-10T00:26:29Z BerkeleyEnvironment::Flush: Flush(false) took             131ms
2020-08-10T00:26:30Z connection to 71.178.203.185:8333 timeout
2020-08-10T00:26:30Z opencon thread exit
2020-08-10T00:26:30Z Flushed 27030 addresses to peers.dat  70ms
2020-08-10T00:26:30Z disconnecting peer=0
2020-08-10T00:26:30Z disconnecting peer=2
2020-08-10T00:26:30Z disconnecting peer=3
2020-08-10T00:26:30Z disconnecting peer=4
2020-08-10T00:26:30Z disconnecting peer=5
2020-08-10T00:26:30Z disconnecting peer=6
2020-08-10T00:26:30Z disconnecting peer=7
2020-08-10T00:26:30Z disconnecting peer=8
2020-08-10T00:26:30Z disconnecting peer=9
2020-08-10T00:26:30Z disconnecting peer=10
2020-08-10T00:26:30Z Cleared nodestate for peer=0
2020-08-10T00:26:30Z Cleared nodestate for peer=2
2020-08-10T00:26:30Z Cleared nodestate for peer=3
2020-08-10T00:26:30Z Cleared nodestate for peer=4
2020-08-10T00:26:30Z Cleared nodestate for peer=5
2020-08-10T00:26:30Z Cleared nodestate for peer=6
2020-08-10T00:26:30Z Cleared nodestate for peer=7
2020-08-10T00:26:30Z Cleared nodestate for peer=8
2020-08-10T00:26:30Z Cleared nodestate for peer=9
2020-08-10T00:26:30Z Cleared nodestate for peer=10
2020-08-10T00:26:30Z scheduler thread exit
  18. DrahtBot locked this on Feb 15, 2022
Contributors
mmortal03sipalaanwjMarcoFalkebilthon
Labels
P2P
github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-04-17 12:15 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me