shutdown took 8 minutes in v0.15.0.1 #12279

issue dooglus opened this issue on January 27, 2018

dooglus commented at 9:59 AM on January 27, 2018: contributor

I tried stopping a v0.15.0.1 node about a minute after starting it. I had started it with an empty .bitcoin directory, and it hadn't synced any blocks at all, so I was intended to shut it down and give it a copy of a good peers.dat file so it could find a peer to sync from - but when I asked it to stop, it didn't.

gdb shows only 2 threads running:

Thread 2 (Thread 0x7f64a97fa700 (LWP 16304)):
[#0](/bitcoin-bitcoin/0/)  0x00007f64d414473d in connect () at ../sysdeps/unix/syscall-template.S:81
[#1](/bitcoin-bitcoin/1/)  0x00007f64cc10a306 in send_vc (statp=statp@entry=0x7f64a97fadb8, buf=buf@entry=0x7f64a97f7b60 "\367A\001", buflen=buflen@entry=42, buf2=buf2@entry=0x7f64a97f7b8c "\341+\001", buflen2=buflen2@entry=42, ansp=ansp@entry=0x7f64a97f79e8, anssizp=anssizp@entry=0x7f64a97f7b30, terrno=terrno@entry=0x7f64a97f79f0, ns=ns@entry=0, anscp=anscp@entry=0x7f64a97f8fe0, ansp2=ansp2@entry=0x7f64a97f8ff0, anssizp2=anssizp2@entry=0x7f64a97f8fa0, resplen2=resplen2@entry=0x7f64a97f8fb0, ansp2_malloced=ansp2_malloced@entry=0x7f64a97f8fc0) at res_send.c:793
[#2](/bitcoin-bitcoin/2/)  0x00007f64cc10b7a7 in __libc_res_nsend (statp=statp@entry=0x7f64a97fadb8, buf=buf@entry=0x7f64a97f7b60 "\367A\001", buflen=42, buf2=buf2@entry=0x7f64a97f7b8c "\341+\001", buflen2=buflen2@entry=42, ans=ans@entry=0x7f64a97f8770 "\341+\203\200", anssiz=anssiz@entry=2048, ansp=ansp@entry=0x7f64a97f8fe0, ansp2=ansp2@entry=0x7f64a97f8ff0, nansp2=nansp2@entry=0x7f64a97f8fa0, resplen2=resplen2@entry=0x7f64a97f8fb0, ansp2_malloced=ansp2_malloced@entry=0x7f64a97f8fc0) at res_send.c:566
[#3](/bitcoin-bitcoin/3/)  0x00007f64cc108e2c in __GI___libc_res_nquery (statp=statp@entry=0x7f64a97fadb8, name=name@entry=0x7f64a97f82f0 "x9.seed.bitcoinstats.com.", class=class@entry=1, type=type@entry=62321, answer=answer@entry=0x7f64a97f8770 "\341+\203\200", anslen=anslen@entry=2048, answerp=answerp@entry=0x7f64a97f8fe0, answerp2=answerp2@entry=0x7f64a97f8ff0, nanswerp2=nanswerp2@entry=0x7f64a97f8fa0, resplen2=resplen2@entry=0x7f64a97f8fb0, answerp2_malloced=answerp2_malloced@entry=0x7f64a97f8fc0) at res_query.c:227
[#4](/bitcoin-bitcoin/4/)  0x00007f64cc1099c5 in __libc_res_nquerydomain (answerp2_malloced=0x7f64a97f8fc0, resplen2=0x7f64a97f8fb0, nanswerp2=0x7f64a97f8fa0, answerp2=0x7f64a97f8ff0, answerp=0x7f64a97f8fe0, anslen=2048, answer=0x7f64a97f8770 "\341+\203\200", type=62321, class=1, domain=<optimized out>, name=0x7f6494007a88 "x9.seed.bitcoinstats.com", statp=0x7f64a97fadb8) at res_query.c:591
[#5](/bitcoin-bitcoin/5/)  __GI___libc_res_nsearch (statp=0x7f64a97fadb8, name=name@entry=0x7f6494007a88 "x9.seed.bitcoinstats.com", class=class@entry=1, type=type@entry=62321, answer=answer@entry=0x7f64a97f8770 "\341+\203\200", anslen=anslen@entry=2048, answerp=answerp@entry=0x7f64a97f8fe0, answerp2=answerp2@entry=0x7f64a97f8ff0, nanswerp2=nanswerp2@entry=0x7f64a97f8fa0, resplen2=resplen2@entry=0x7f64a97f8fb0, answerp2_malloced=answerp2_malloced@entry=0x7f64a97f8fc0) at res_query.c:421
[#6](/bitcoin-bitcoin/6/)  0x00007f64cc31dc73 in _nss_dns_gethostbyname4_r (name=name@entry=0x7f6494007a88 "x9.seed.bitcoinstats.com", pat=pat@entry=0x7f64a97f9600, buffer=buffer@entry=0x7f64a97f9090 "_\267\060u", buflen=buflen@entry=1064, errnop=errnop@entry=0x7f64a97f95d0, herrnop=herrnop@entry=0x7f64a97f9630, ttlp=ttlp@entry=0x0) at nss_dns/dns-host.c:315
[#7](/bitcoin-bitcoin/7/)  0x00007f64d3e3d226 in gaih_inet (name=<optimized out>, name@entry=0x7f6494007a88 "x9.seed.bitcoinstats.com", service=<optimized out>, req=req@entry=0x7f64a97f98b0, pai=pai@entry=0x7f64a97f9740, naddrs=naddrs@entry=0x7f64a97f9730) at ../sysdeps/posix/getaddrinfo.c:858
[#8](/bitcoin-bitcoin/8/)  0x00007f64d3e4052d in __GI_getaddrinfo (name=0x7f6494007a88 "x9.seed.bitcoinstats.com", service=0x0, hints=0x7f64a97f98b0, pai=0x7f64a97f98a8) at ../sysdeps/posix/getaddrinfo.c:2414
[#9](/bitcoin-bitcoin/9/)  0x000055e5fd430206 in LookupIntern (pszName=0x7f6494007a88 "x9.seed.bitcoinstats.com", vIP=std::vector of length 0, capacity 0, nMaxSolutions=0, fAllowLookup=<optimized out>) at netbase.cpp:85
[#10](/bitcoin-bitcoin/10/) 0x000055e5fd430578 in LookupHost (pszName=<optimized out>, vIP=std::vector of length 0, capacity 0, nMaxSolutions=nMaxSolutions@entry=0, fAllowLookup=fAllowLookup@entry=true) at netbase.cpp:128
[#11](/bitcoin-bitcoin/11/) 0x000055e5fd26e899 in CConnman::ThreadDNSAddressSeed (this=0x55e5ffa47f70) at net.cpp:1613
[#12](/bitcoin-bitcoin/12/) 0x000055e5fd2537bb in operator() (this=0x7f64a97f9e70) at /usr/include/c++/4.8/functional:2471
[#13](/bitcoin-bitcoin/13/) TraceThread<std::function<void ()> >(char const*, std::function<void ()>) (name=0x55e5fd582f7e "dnsseed", func=...) at util.h:302
[#14](/bitcoin-bitcoin/14/) 0x000055e5fd285c3f in _M_invoke<0ul, 1ul> (this=<optimized out>) at /usr/include/c++/4.8/functional:1732
[#15](/bitcoin-bitcoin/15/) operator() (this=<optimized out>) at /usr/include/c++/4.8/functional:1720
[#16](/bitcoin-bitcoin/16/) std::thread::_Impl<std::_Bind_simple<void (*(char const*, std::function<void ()>))(char const*, std::function<void ()>)> >::_M_run() (this=<optimized out>) at /usr/include/c++/4.8/thread:115
[#17](/bitcoin-bitcoin/17/) 0x00007f64d4920a60 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
[#18](/bitcoin-bitcoin/18/) 0x00007f64d413d184 in start_thread (arg=0x7f64a97fa700) at pthread_create.c:312
[#19](/bitcoin-bitcoin/19/) 0x00007f64d3e6abed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 1 (Thread 0x7f64d640b780 (LWP 16288)):
[#0](/bitcoin-bitcoin/0/)  0x00007f64d413e65b in pthread_join (threadid=140070317172480, thread_return=0x0) at pthread_join.c:92
[#1](/bitcoin-bitcoin/1/)  0x00007f64d4920857 in std::thread::join() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
[#2](/bitcoin-bitcoin/2/)  0x000055e5fd2840dd in CConnman::Stop (this=this@entry=0x55e5ffa47f70) at net.cpp:2408
[#3](/bitcoin-bitcoin/3/)  0x000055e5fd284428 in CConnman::~CConnman (this=0x55e5ffa47f70, __in_chrg=<optimized out>) at net.cpp:2455
[#4](/bitcoin-bitcoin/4/)  0x000055e5fd233731 in operator() (this=<optimized out>, __ptr=0x55e5ffa47f70) at /usr/include/c++/4.8/bits/unique_ptr.h:67
[#5](/bitcoin-bitcoin/5/)  reset (__p=0x55e5ffa47f70, this=0x55e5fd96d990 <g_connman>) at /usr/include/c++/4.8/bits/unique_ptr.h:262
[#6](/bitcoin-bitcoin/6/)  Shutdown () at init.cpp:198
[#7](/bitcoin-bitcoin/7/)  0x000055e5fd2269a0 in AppInit (argc=1, argv=0x7ffecae4a298) at bitcoind.cpp:183
[#8](/bitcoin-bitcoin/8/)  0x000055e5fd21a7ef in main (argc=1, argv=0x7ffecae4a298) at bitcoind.cpp:195

dooglus commented at 10:00 AM on January 27, 2018: contributor

Oh, it wasn't deadlocked, it was just very slow:

2018-01-27 09:51:33 Shutdown: In progress...
2018-01-27 09:51:33 net thread exit
2018-01-27 09:51:33 msghand thread exit
2018-01-27 09:51:35 opencon thread exit
2018-01-27 09:59:18 dnsseed thread exit
2018-01-27 09:59:18 Dumped mempool: 5e-06s to copy, 0.02954s to dump
2018-01-27 09:59:19 Shutdown: done

It froze for almost 8 minutes before shutting down. This sounds familiar. Maybe it's a duplicate. Sorry if so.

fanquake added the label Linux/Unix on Jan 27, 2018
dooglus renamed this:
~~deadlock on shutdown in v0.15.0.1~~
shutdown took 8 minutes in v0.15.0.1
on Jan 27, 2018
Willtech commented at 12:21 PM on January 27, 2018: contributor

I know your ~/.bitcoin folder started empty but what you are seeing otherwise seems normal (not every time) from experience. The window that says Bitcoin Core is shutting down is there for a reason.
dooglus commented at 5:27 PM on January 27, 2018: contributor

I doubt it is intended that it bitcoind sits idle for 8 minutes waiting for some kind of timeout before shutting down. It may be "normal", but it's still not ideal behavior.
dooglus commented at 5:28 PM on January 27, 2018: contributor

Oh, and there was no window saying that Core is shutting down. I was running bitcoind, not bitcoin-qt.
sipa commented at 5:29 PM on January 27, 2018: member

If you have a large dbcache, and a not too fast I/O, 8 minutes doesn't sound unusual.

What was the last UpdatedTip line in your log?
dooglus commented at 5:37 PM on January 27, 2018: contributor

@sipa > I had started it with an empty .bitcoin directory, and it hadn't synced any blocks at all

So there wasn't a large dbcache, and no UpdatedTip line. It was a new data directory, with no blocks at all.
jonasschnelli commented at 5:50 AM on January 28, 2018: contributor

Is it possible that the shutdown was hold back by a blocking through LookupIntern() (ThreadDNSAddressSeed)? ping @theuni
theuni commented at 6:22 PM on January 29, 2018: member

@jonasschnelli Looks that way, yes. Though, the glibc docs say the default timeout should be 5sec, with a max of 30sec.

I'm afraid there's not much we can do about this until we switch resolvers.
randolf commented at 3:04 AM on February 1, 2018: contributor

@dooglus You mentioned that you're using v0.15.0.1. Does v0.15.1 work better for you?
fanquake closed this on Mar 6, 2018
dooglus commented at 10:31 PM on March 6, 2018: contributor

@randolf I only ever saw the problem once or twice. When it's so rare it's hard to say whether the new version "works better" or "just didn't fail yet".
MarcoFalke locked this on Sep 8, 2021

Contributors

Labels

Linked (view graph)

#1 JSON-RPC support for mobile devices ("ultra-lightweight" clients)#2 Long-term, safe, store-of-value #3 Encrypt wallet #4 Export/Import wallet in a human readable, future-proof format #5 Make the version number the protocol version and not the client version #6 Treat wallet as a generic keystore #7 Block-header-only, faster startup client #8 RPC command to sign text with wallet private key #9 Fix for GUI on Macs and latest wxWidgets #10 Add address to listtransactions output #11 Nolisten patch #12 Monitor transactions and/or blocks #13 Messages with or about transactions #14 bitcoin: URI and/or bitcoin-request MIME type for click-to-pay #15 Option to specify external IP address #16 Mac UI issues #17 listaccounts method #18 Error when trying to send very precise amount #19 bitcoin(d) --help should output version number