bitcoind hangs waiting for `g_requests.empty()` #27722

issue Crypt-iQ opened this issue on May 22, 2023
  1. Crypt-iQ commented at 11:05 PM on May 22, 2023: contributor

    Is there an existing issue for this?

    • I have searched the existing issues

    Current behaviour

    bitcoind hangs

    Expected behaviour

    bitcoind shouldn't hang

    I was able to dump the running threads and it was stuck waiting for g_requests to be empty. The issue seems to be that this callback may not actually be called in case of error: https://github.com/bitcoin/bitcoin/blob/22139f6e83a2bedd2dad9f280567d2c76c54252f/src/httpserver.cpp#L222-L227

    See this issue https://github.com/libevent/libevent/issues/589 for more details. I think what happens is that interrupting bitcoin-cli before it has received the reply calls the error callback and then the success callback is never called.

    I think this is also a memory leak since g_requests won't get cleaned up. Whether it's severe or not probably depends on the caller and what type of requests they are making. This new code was introduced here #26742

    Steps to reproduce

    I was running a simple shell script in 4 terminal windows for fun:

    #!/bin/bash
    
    for i in {1..50000}
    do
    	./src/bitcoin-cli -rpcuser=admin -rpcpassword=pass getrawtransaction 217819875434324c412d5e938f7f3c1670fb60814974cf7958f1fac90ee5afb7
    done
    

    I was messing around with this script and randomly Ctrl-C'd each terminal window in rapid succession and then when I waited up to a minute and Ctrl-C'd bitcoind, it didn't shutdown. I can reproduce it pretty reliably as well.

    Compilation commands:

    ./autogen.sh; ./configure --without-wallet --with-gui=no --disable-zmq; make -j4
    

    Run-time options (note that I was able to reproduce this with the default number of rpcthreads as well):

    ./src/bitcoind -txindex -rpcthreads=1 -debug
    

    Output of gcc --version:

    Configured with: --prefix=/Applications/Xcode.app/Contents/Developer/usr --with-gxx-include-dir=/Applications/Xcode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX.sdk/usr/include/c++/4.2.1
    Apple clang version 11.0.3 (clang-1103.0.32.62)
    Target: x86_64-apple-darwin21.6.0
    Thread model: posix
    InstalledDir: /Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin
    

    Output of g++ --version:

    Configured with: --prefix=/Applications/Xcode.app/Contents/Developer/usr --with-gxx-include-dir=/Applications/Xcode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX.sdk/usr/include/c++/4.2.1
    Apple clang version 11.0.3 (clang-1103.0.32.62)
    Target: x86_64-apple-darwin21.6.0
    Thread model: posix
    InstalledDir: /Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin
    

    My libevent version is 2.1.12

    Relevant log output

    ^C2023-05-22T20:56:10Z [http] Interrupting HTTP server
    2023-05-22T20:56:10Z [rpc] Interrupting HTTP RPC server
    2023-05-22T20:56:10Z [rpc] Interrupting RPC
    2023-05-22T20:56:10Z tor: Thread interrupt
    2023-05-22T20:56:10Z Shutdown: In progress...
    2023-05-22T20:56:10Z [rpc] Stopping HTTP RPC server
    2023-05-22T20:56:10Z torcontrol thread exit
    2023-05-22T20:56:10Z [http] Unregistering HTTP handler for / (exactmatch 1)
    2023-05-22T20:56:10Z addcon thread exit
    2023-05-22T20:56:10Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    2023-05-22T20:56:10Z [rpc] Stopping RPC
    2023-05-22T20:56:10Z net thread exit
    2023-05-22T20:56:10Z [rpc] RPC stopped.
    2023-05-22T20:56:10Z [http] Stopping HTTP server
    2023-05-22T20:56:10Z [http] Waiting for HTTP worker threads to exit
    2023-05-22T20:56:10Z [http] Exited http event loop
    2023-05-22T20:56:10Z [http] Waiting for 1 requests to stop HTTP server
    

    The important bit is the very last log line. bitcoind was still alive and periodically printed log lines about feeding dynamic environment data into the RNG.

    How did you obtain Bitcoin Core

    Compiled from source

    What version of Bitcoin Core are you using?

    17acb2782a66f033238340e4fb81009e7f79e97a

    Operating system and version

    macOS intel

    Machine specifications

    No response

  2. Crypt-iQ commented at 1:05 PM on May 23, 2023: contributor

    I think #27245 which uses evhttp_connection_set_closecb is needed to avoid this, but:

    • it doesn't seem to be slated for v25.0
    • I experience this in one of the libevent versions that #27245 doesn't address
  3. theStack commented at 2:02 PM on May 23, 2023: contributor

    Thanks for reporting! I observed this issue sporadically, but were never able to reproduce it until now. With the help of your description ("... interrupting bitcoin-cli before it has received the reply ...") I found it's actually quite trivial at least on my machine:

    1. startup bitcoind -debug=http (and any other desired flags; note that the hangup also happens without the debug flag, but this allows us to see where it's hanging)
    2. execute bitcoin-cli waitforblockheight 1234567 (or any other RPC call which doesn't terminate immediately)
    3. terminate bitcoin-cli via CTRL-C
    4. terminate bitcoind via CTRL-C

    The shutdown leads to the following messages and then hangs forever:

    2023-05-23T13:58:01Z [http] Unregistering HTTP handler for / (exactmatch 1)
    2023-05-23T13:58:01Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    2023-05-23T13:58:01Z [http] Stopping HTTP server
    2023-05-23T13:58:01Z [http] Waiting for HTTP worker threads to exit
    2023-05-23T13:58:01Z [http] Waiting for 1 requests to stop HTTP server
    2023-05-23T13:58:01Z [http] Exited http event loop
    2023-05-23T13:58:01Z msghand thread exit
    2023-05-23T13:58:01Z net thread exit
    2023-05-23T13:58:03Z opencon thread exit
    

    Tested on master branch (commit 5ef2c1ee7a7416907e0f9135dc0701a88d92a7f6) with default configuration, running OpenBSD 7.3 with libevent 2.1.12 here.

  4. maflcko added the label RPC/REST/ZMQ on May 23, 2023
  5. Crypt-iQ commented at 4:00 PM on May 23, 2023: contributor

    I was able to fix this with my branch here https://github.com/Crypt-iQ/bitcoin/commit/4fd7adb30f584664421b6431bce8ebcbf7ceef2f by adding a evhttp_connection_set_closecb callback. I didn't need to modify the logic related to EV_READ and no functional test errors are introduced on my machine

  6. theStack commented at 6:09 PM on May 24, 2023: contributor

    I was able to fix this with my branch here Crypt-iQ@4fd7adb by adding a evhttp_connection_set_closecb callback. I didn't need to modify the logic related to EV_READ and no functional test errors are introduced on my machine

    Can confirm that this patch fixes the issue on my side.

  7. willcl-ark commented at 10:44 AM on May 26, 2023: member

    Hmmm, curiously enough I was not able to reproduce using either method on master @ aa6cc5bec9

    With @theStack method:

    2023-05-26T10:39:07Z [http] Received a POST request for / from 127.0.0.1:50704
    ^C2023-05-26T10:39:10Z [http] Interrupting HTTP server
    2023-05-26T10:39:10Z tor: Thread interrupt
    2023-05-26T10:39:10Z torcontrol thread exit
    2023-05-26T10:39:10Z addcon thread exit
    2023-05-26T10:39:10Z opencon thread exit
    2023-05-26T10:39:10Z Shutdown: In progress...
    2023-05-26T10:39:10Z [http] Unregistering HTTP handler for / (exactmatch 1)
    2023-05-26T10:39:10Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    2023-05-26T10:39:10Z [http] Stopping HTTP server
    2023-05-26T10:39:10Z [http] Waiting for HTTP worker threads to exit
    2023-05-26T10:39:10Z [http] Waiting for 1 requests to stop HTTP server
    2023-05-26T10:39:10Z [http] Waiting for HTTP event thread to exit
    2023-05-26T10:39:10Z [http] Exited http event loop
    2023-05-26T10:39:10Z [http] Stopped HTTP server
    2023-05-26T10:39:10Z loadblk thread exit
    2023-05-26T10:39:10Z net thread exit
    2023-05-26T10:39:10Z msghand thread exit
    2023-05-26T10:39:10Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat started
    2023-05-26T10:39:10Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat completed (0.00s)
    2023-05-26T10:39:10Z scheduler thread exit
    2023-05-26T10:39:16Z Shutdown: done
    

    With @Crypt-iQ method:

    <details> <summary>Details</summary>

    ... many lines like this
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59546
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59562
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59566
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59570
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59574
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59580
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59590
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59596
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59606
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59616
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59618
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59636
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59638
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59660
    2023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59658
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59686
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59684
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59704
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59706
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59722
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59734
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59740
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59746
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59760
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59774
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59790
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59792
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59798
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59802
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59804
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59818
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59822
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59828
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59826
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59840
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59854
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59864
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59866
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59870
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59868
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59886
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59900
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59914
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59928
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59944
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59960
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59964
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59968
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59980
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59982
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60002
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60004
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60010
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60008
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60018
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60016
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60038
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60044
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60048
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60054
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60066
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60064
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60080
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60082
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60108
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60110
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60124
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60128
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60130
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60142
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60154
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60158
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60170
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60168
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60186
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60184
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60196
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60198
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60224
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60226
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60242
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60244
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60258
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60256
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60284
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60296
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60298
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60310
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60320
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60336
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60344
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60342
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60362
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60370
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60378
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60382
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60386
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60388
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60400
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60402
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60422
    2023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60430
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60436
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60450
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60462
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60468
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60472
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60470
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60494
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60496
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60508
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60510
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60514
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60522
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60524
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60532
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60544
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60552
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60556
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60560
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60570
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60582
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60592
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60598
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60612
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60614
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60620
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60626
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60628
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60646
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60654
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60652
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60676
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60678
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60680
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60688
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60700
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60706
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60710
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60712
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60724
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60736
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60750
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60756
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60760
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60772
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60776
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60788
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60802
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60814
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60816
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60828
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60830
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60846
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60848
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60854
    2023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60866
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60880
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60892
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60896
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60906
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60918
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60934
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60940
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60950
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60960
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60972
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60988
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60994
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32772
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32774
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32776
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32778
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32788
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32802
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32812
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32828
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32830
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32832
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32846
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32854
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32870
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32872
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32876
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32890
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32892
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32904
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32906
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32912
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32928
    2023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32934
    ^C2023-05-26T10:42:14Z [http] Interrupting HTTP server
    2023-05-26T10:42:14Z tor: Thread interrupt
    2023-05-26T10:42:14Z torcontrol thread exit
    2023-05-26T10:42:14Z opencon thread exit
    2023-05-26T10:42:14Z addcon thread exit
    2023-05-26T10:42:14Z Shutdown: In progress...
    2023-05-26T10:42:14Z [http] Unregistering HTTP handler for / (exactmatch 1)
    2023-05-26T10:42:14Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    2023-05-26T10:42:14Z [http] Stopping HTTP server
    2023-05-26T10:42:14Z [http] Waiting for HTTP worker threads to exit
    2023-05-26T10:42:14Z [http] Exited http event loop
    2023-05-26T10:42:14Z [http] Waiting for HTTP event thread to exit
    2023-05-26T10:42:14Z [http] Stopped HTTP server
    2023-05-26T10:42:14Z net thread exit
    2023-05-26T10:42:14Z loadblk thread exit
    2023-05-26T10:42:14Z msghand thread exit
    2023-05-26T10:42:14Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat started
    2023-05-26T10:42:14Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat completed (0.00s)
    2023-05-26T10:42:14Z scheduler thread exit
    2023-05-26T10:42:15Z Shutdown: done
    

    </details>

  8. Crypt-iQ commented at 1:15 PM on May 26, 2023: contributor

    @willcl-ark can you find what libevent version you're using?

  9. erikarvstedt commented at 6:31 PM on May 30, 2023: contributor

    This bug appeared in the nix-bitcoin test suite. I can confirm that it is fixed by https://github.com/Crypt-iQ/bitcoin/commit/4fd7adb30f584664421b6431bce8ebcbf7ceef2f.

    <details> <summary>Details</summary>

    The test is executed inside a QEMU VM and runs bitcoind together with a bunch of client services (like clightning, lnd, joinmarket). It then stops all services, including bitcoind. Sometimes bitcoind hangs during shutdown:

    1. First, it waits for a few minutes at httpserver.cpp#L469 ([http] Waiting for HTTP worker threads to exit)
    2. Then it hangs indefinitely at httpserver.cpp#L484 ([http] Waiting for 1 requests to stop HTTP server')

    bitcoind gets shutdown after all client services have exited, so there are never any lingering active connections.

    This bug is hard to reproduce in the context of the test suite. I once could consistently trigger it on my desktop system, but never again after rebooting the system. Currently, I can reproduce it in 80% of all test runs on our nix-bitcoin server.

    Here's the log output of the shutdown sequence, interspersed with gdb backtraces of all threads.

    </details>

  10. Crypt-iQ commented at 7:26 PM on May 30, 2023: contributor

    @erikarvstedt it seems like there's a call to importmulti that is outstanding while bitcoind is trying to shut down

  11. erikarvstedt commented at 8:43 PM on May 30, 2023: contributor

    @Crypt-iQ, the slow progress of importmulti is indeed a separate issue. Maybe it has existed before and was just uncovered by #26742. I'll check this later. I've updated my previous post.

  12. willcl-ark commented at 10:23 AM on May 31, 2023: member

    @willcl-ark can you find what libevent version you're using?

    I am using libevent 2.1.12 (like TheStack)

  13. Crypt-iQ commented at 5:56 PM on May 31, 2023: contributor

    I get this when compiling with both gcc and clang-16. I am also using libevent 2.1.12. Is there anything unique about your setup @willcl-ark ? Also, did you Ctrl-C the waitforblockheight command before trying to stop bitcoind?

  14. fanquake added this to the milestone 25.1 on Jun 1, 2023
  15. pablomartin4btc commented at 2:11 PM on June 25, 2023: member

    As @willcl-ark, tried @theStack's method with no sucess, my libevent version is 2.1.7, I'll try to update it and retry again. Thanks. @Crypt-iQ I did: Ctrl-C the waitforblockheight command before trying to stop bitcoind.

  16. bitcoin deleted a comment on Jun 25, 2023
  17. Crypt-iQ commented at 11:04 AM on June 26, 2023: contributor

    As @willcl-ark, tried @theStack's method with no sucess, my libevent version is 2.1.7, I'll try to update it and retry again. Thanks.

    @Crypt-iQ I did: Ctrl-C the waitforblockheight command before trying to stop bitcoind.

    Good to know, I'll have to test out that version

  18. maflcko added the label Bug on Jun 26, 2023
  19. willcl-ark commented at 9:00 AM on June 28, 2023: member

    I get this when compiling with both gcc and clang-16. I am also using libevent 2.1.12. Is there anything unique about your setup @willcl-ark ? Also, did you Ctrl-C the waitforblockheight command before trying to stop bitcoind?

    I've had more reports of this deadlock so come back to try and repro it again, but don't seem to be able to no matter what I try 🤷🏼‍♂️

    I am on Ubuntu 23.04, also using Clang 16 and libevent 2.1.12-stable-8ubuntu3. It doesn't look like there are any debian patches applied which could affect this...

    <details> <summary>debug log with http and libevent looks normal</summary>

    2023-06-28T08:47:52Z [libevent:debug] event_active: 0x55c039f36038 (fd 12), res 2, callback 0x7ff7a7371270
    2023-06-28T08:47:52Z [libevent:debug] event_process_active: event: 0x55c039f36038, EV_READ   call 0x7ff7a7371270
    2023-06-28T08:47:52Z [libevent:debug] evhttp_get_request_connection: new request from 127.0.0.1:46142 on 44
    
    2023-06-28T08:47:52Z [libevent:debug] Attempting connection to 127.0.0.1:46142
    
    2023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff7500053f0 (fd -1), callback 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff750005470 (fd -1), callback 0x7ff7a7362740
    2023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff750005470 (fd 44),  EV_WRITE   call 0x7ff7a7362740
    2023-06-28T08:47:52Z [libevent:debug] Epoll ADD(4) on fd 44 okay. Old events were 0; read change was 0 (none); write change was 1 (add); close change was 0 (none)
    2023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ    call 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] Epoll MOD(5) on fd 44 okay. Old events were 4; read change was 1 (add); write change was 0 (none); close change was 0 (none)
    2023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff750005470 (fd 44), callback 0x7ff7a7362740
    2023-06-28T08:47:52Z [libevent:debug] Epoll MOD(1) on fd 44 okay. Old events were 6; read change was 0 (none); write change was 2 (del); close change was 0 (none)
    2023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 30 seconds 0 useconds, call 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff750005470 (fd 44), callback 0x7ff7a7362740
    2023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 30 seconds 0 useconds, call 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] timeout_next: event: 0x7ff7500053f0, in 30 seconds, 0 useconds
    2023-06-28T08:47:52Z [libevent:debug] epoll_dispatch: epoll_wait reports 1
    2023-06-28T08:47:52Z [libevent:debug] event_active: 0x7ff7500053f0 (fd 44), res 2, callback 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] event_process_active: event: 0x7ff7500053f0, EV_READ   call 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 70594 seconds 199020 useconds, call 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Host val: 127.0.0.1
    
    2023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Connection val: close
    
    2023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Content-Type val: application/json
    
    2023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Authorization val: Basic xxxxxxx
    
    2023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Content-Length val: 58
    
    2023-06-28T08:47:52Z [libevent:debug] evhttp_read_header: checking for post data on 44
    
    2023-06-28T08:47:52Z [libevent:debug] evhttp_get_body_length: bytes to read: 58 (in buffer 58)
    
    2023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff7500053f0 (fd 44), callback 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] Epoll DEL(1) on fd 44 okay. Old events were 2; read change was 2 (del); write change was 0 (none); close change was 0 (none)
    2023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff7500053f0 (fd 44), callback 0x7ff7a7361f90
    2023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff7500053f0 (fd 44), callback 0x7ff7a7361f90
    2023-06-28T08:47:52Z [http] Received a POST request for / from 127.0.0.1:46142
    ^C2023-06-28T08:47:57Z [http] Interrupting HTTP server
    2023-06-28T08:47:57Z tor: Thread interrupt
    2023-06-28T08:47:57Z [libevent:debug] event_active: 0x55c0458e3250 (fd -1), res 1, callback 0x7ff7a7366100
    2023-06-28T08:47:57Z [libevent:debug] epoll_dispatch: epoll_wait reports 1
    2023-06-28T08:47:57Z [libevent:debug] event_active: 0x55c0458e51f0 (fd 30), res 2, callback 0x7ff7a736c690
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c0458e3250 (fd -1), callback 0x7ff7a7366100
    2023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x55c0458e3250,    call 0x7ff7a7366100
    2023-06-28T08:47:57Z [libevent:debug] event_base_loop: asked to terminate loop.
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff640001080 (fd -1), callback 0x55c03736e022
    2023-06-28T08:47:57Z torcontrol thread exit
    2023-06-28T08:47:57Z Shutdown: In progress...
    2023-06-28T08:47:57Z addcon thread exit
    2023-06-28T08:47:57Z opencon thread exit
    2023-06-28T08:47:57Z [http] Unregistering HTTP handler for / (exactmatch 1)
    2023-06-28T08:47:57Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    2023-06-28T08:47:57Z [http] Stopping HTTP server
    2023-06-28T08:47:57Z [http] Waiting for HTTP worker threads to exit
    2023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Content-Type val: application/json
    
    2023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Connection val: close
    
    2023-06-28T08:47:57Z [libevent:debug] event_active: 0x7ff730001240 (fd -1), res 0, callback 0x55c03750235f
    2023-06-28T08:47:57Z [libevent:debug] epoll_dispatch: epoll_wait reports 1
    2023-06-28T08:47:57Z [libevent:debug] event_active: 0x55c039f35bc0 (fd 10), res 2, callback 0x7ff7a736c690
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff730001240 (fd -1), callback 0x55c03750235f
    2023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x7ff730001240,    call 0x55c03750235f
    2023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Date val: Wed, 28 Jun 2023 08:47:57 GMT
    
    2023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Content-Length val: 123
    
    2023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Connection val: close
    
    2023-06-28T08:47:57Z [libevent:debug] evhttp_write_buffer: preparing to write buffer
    
    2023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
    2023-06-28T08:47:57Z [libevent:debug] Epoll ADD(1) on fd 44 okay. Old events were 0; read change was 1 (add); write change was 0 (none); close change was 0 (none)
    2023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 30 seconds 0 useconds, call 0x7ff7a7361f90
    2023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff750005470 (fd 44),  EV_WRITE  EV_TIMEOUT call 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] Epoll MOD(5) on fd 44 okay. Old events were 2; read change was 0 (none); write change was 1 (add); close change was 0 (none)
    2023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff750005470, timeout in 30 seconds 0 useconds, call 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
    2023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 30 seconds 0 useconds, call 0x7ff7a7361f90
    2023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff750005470 (fd 44),  EV_WRITE  EV_TIMEOUT call 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff750005470, timeout in 30 seconds 0 useconds, call 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff730001240 (fd -1), callback 0x55c03750235f
    2023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x55c039f35bc0, EV_READ   call 0x7ff7a736c690
    2023-06-28T08:47:57Z [libevent:debug] timeout_next: event: 0x7ff7500053f0, in 30 seconds, 0 useconds
    2023-06-28T08:47:57Z [libevent:debug] epoll_dispatch: epoll_wait reports 1
    2023-06-28T08:47:57Z [libevent:debug] event_active: 0x7ff750005470 (fd 44), res 4, callback 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] event_active: 0x7ff7500053f0 (fd 44), res 2, callback 0x7ff7a7361f90
    2023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x7ff750005470,  EV_WRITE  call 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff750005470 (fd 44),  EV_WRITE  EV_TIMEOUT call 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff750005470, timeout in 70599 seconds 923008 useconds, call 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c039f36658 (fd 11), callback 0x7ff7a7371270
    2023-06-28T08:47:57Z [libevent:debug] Epoll DEL(1) on fd 11 okay. Old events were 2; read change was 2 (del); write change was 0 (none); close change was 0 (none)
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff750005470 (fd 44), callback 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] Epoll MOD(1) on fd 44 okay. Old events were 6; read change was 0 (none); write change was 2 (del); close change was 0 (none)
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c039f36038 (fd 12), callback 0x7ff7a7371270
    2023-06-28T08:47:57Z [libevent:debug] Epoll DEL(1) on fd 12 okay. Old events were 2; read change was 2 (del); write change was 0 (none); close change was 0 (none)
    2023-06-28T08:47:57Z [libevent:debug] event_active: 0x55c04518ec30 (fd -1), res 1, callback 0x7ff7a7366100
    2023-06-28T08:47:57Z [http] Waiting for HTTP event thread to exit
    2023-06-28T08:47:57Z [libevent:debug] event_callback_finalize_many_: 3 events finalizing
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff7500053f0 (fd 44), callback 0x7ff7a7361f90
    2023-06-28T08:47:57Z [libevent:debug] Epoll DEL(1) on fd 44 gave Bad file descriptor: DEL was unnecessary.
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff750005470 (fd 44), callback 0x7ff7a7362740
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c04518ec30 (fd -1), callback 0x7ff7a7366100
    2023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x55c04518ec30,    call 0x7ff7a7366100
    2023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x7ff750005470,  EV_WRITE  call 0x7ff7a735f910
    2023-06-28T08:47:57Z [libevent:debug] event_base_loop: no events registered.
    2023-06-28T08:47:57Z [http] Exited http event loop
    2023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c039f35bc0 (fd 10), callback 0x7ff7a736c690
    2023-06-28T08:47:57Z [libevent:debug] 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)
    2023-06-28T08:47:57Z [libevent:debug] event_base_free_: 0 events freed
    2023-06-28T08:47:57Z [http] Stopped HTTP server
    2023-06-28T08:47:57Z loadblk thread exit
    2023-06-28T08:47:57Z msghand thread exit
    2023-06-28T08:47:57Z net thread exit
    2023-06-28T08:47:58Z i2paccept thread exit
    2023-06-28T08:47:58Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat started
    2023-06-28T08:47:58Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat completed (0.01s)
    2023-06-28T08:47:58Z [libevent:debug] event_del: 0x55c0458e51f0 (fd 30), callback 0x7ff7a736c690
    2023-06-28T08:47:58Z [libevent:debug] Epoll DEL(1) on fd 30 okay. Old events were 2; read change was 2 (del); write change was 0 (none); close change was 0 (none)
    2023-06-28T08:47:58Z [libevent:debug] event_base_free_: 0 events freed
    2023-06-28T08:47:58Z scheduler thread exit
    2023-06-28T08:47:58Z Flushed fee estimates to fee_estimates.dat.
    2023-06-28T08:47:59Z Shutdown: done
    

    </details>

    I wonder libevent on my system using Epoll might be the reason I can't reproduce (and that I've seen mainly reports of this on MacOS)? AFAIK MacOS uses kqueue, and not sure what BSD is using but I might guess also kqueue... Perhaps kqueue blocks if it can't delete a closed fd or something?

    2023-06-28T08:47:57Z [libevent:debug] Epoll DEL(1) on fd 44 gave Bad file descriptor: DEL was unnecessary.
    # continues with shutdown
    ...
    
  20. dooglus commented at 7:27 PM on June 28, 2023: contributor

    I was able to fix this with my branch here Crypt-iQ@4fd7adb by adding a evhttp_connection_set_closecb callback.

    This fixed the issue for me too, but I just saw a crash caused by an assert() just 4 lines before the modified code:

    [Thread 0x7ffec0f4b700 (LWP 1828755) exited]
    bitcoin-qt: httpserver.cpp:223: http_request_cb(evhttp_request*, void*)::<lambda(evhttp_request*, void*)>: Assertion `n == 1' failed.
    
    Thread 35 "b-http" received signal SIGABRT, Aborted.
    [Switching to Thread 0x7fff577fe700 (LWP 1762429)]
    __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
    50      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
    (gdb) where
    [#0](/bitcoin-bitcoin/0/)  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
    [#1](/bitcoin-bitcoin/1/)  0x00007ffff6261537 in __GI_abort () at abort.c:79
    [#2](/bitcoin-bitcoin/2/)  0x00007ffff626140f in __assert_fail_base (fmt=0x7ffff63d8688 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x555556ae7ae2 "n == 1", file=0x555556ae79c2 "httpserver.cpp", line=223, function=<optimized out>) at assert.c:92
    [#3](/bitcoin-bitcoin/3/)  0x00007ffff6270662 in __GI___assert_fail (assertion=0x555556ae7ae2 "n == 1", file=0x555556ae79c2 "httpserver.cpp", line=223, function=0x555556ae7a98 "http_request_cb(evhttp_request*, void*)::<lambda(evhttp_request*, void*)>") at assert.c:101
    [#4](/bitcoin-bitcoin/4/)  0x0000555555dab98b in http_request_cb(evhttp_request*, void*)::{lambda(evhttp_request*, void*)#2}::operator()(evhttp_request*, void*) const ()
    [#5](/bitcoin-bitcoin/5/)  0x0000555555dab9e6 in http_request_cb(evhttp_request*, void*)::{lambda(evhttp_request*, void*)#2}::_FUN(evhttp_request*, void*) ()
    [#6](/bitcoin-bitcoin/6/)  0x00007ffff68e4da9 in  () at /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7
    [#7](/bitcoin-bitcoin/7/)  0x00007ffff68c3233 in  () at /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7
    [#8](/bitcoin-bitcoin/8/)  0x00007ffff68c8b4f in  () at /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7
    [#9](/bitcoin-bitcoin/9/)  0x00007ffff68c928f in event_base_loop () at /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7
    [#10](/bitcoin-bitcoin/10/) 0x0000555555dacf1a in ThreadHTTP(event_base*) ()
    [#11](/bitcoin-bitcoin/11/) 0x0000555555dc4f11 in void std::__invoke_impl<void, void (*)(event_base*), event_base*>(std::__invoke_other, void (*&&)(event_base*), event_base*&&) ()
    [#12](/bitcoin-bitcoin/12/) 0x0000555555dc4b98 in std::__invoke_result<void (*)(event_base*), event_base*>::type std::__invoke<void (*)(event_base*), event_base*>(void (*&&)(event_base*), event_base*&&) ()
    [#13](/bitcoin-bitcoin/13/) 0x0000555555dc48d4 in void std::thread::_Invoker<std::tuple<void (*)(event_base*), event_base*> >::_M_invoke<0ul, 1ul>(std::_Index_tuple<0ul, 1ul>) ()
    [#14](/bitcoin-bitcoin/14/) 0x0000555555dc47d7 in std::thread::_Invoker<std::tuple<void (*)(event_base*), event_base*> >::operator()() ()
    [#15](/bitcoin-bitcoin/15/) 0x0000555555dc460f in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(event_base*), event_base*> > >::_M_run() ()
    [#16](/bitcoin-bitcoin/16/) 0x00007ffff6663ed0 in  () at /usr/lib/x86_64-linux-gnu/libstdc++.so.6
    [#17](/bitcoin-bitcoin/17/) 0x00007ffff641aea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
    [#18](/bitcoin-bitcoin/18/) 0x00007ffff633aa2f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
    (gdb) 

    I can't tell what the value of n is, because I don't compile with debug enabled any more. But I guess it isn't 1!

  21. Crypt-iQ commented at 12:53 AM on July 2, 2023: contributor

    [Thread 0x7ffec0f4b700 (LWP 1828755) exited] bitcoin-qt: httpserver.cpp:223: http_request_cb(evhttp_request*

    Do you happen to know what libevent version you were on?

  22. dooglus commented at 4:36 PM on July 4, 2023: contributor

    Do you happen to know what libevent version you were on?

    It looks like version 2.1.12.

    $ dpkg -l | grep libevent
    ii  libev4:amd64                                                1:4.33-1                           amd64        high-performance event loop library modelled after libevent
    ii  libevent-2.1-7:amd64                                        2.1.12-stable-1                    amd64        Asynchronous event notification library
    ii  libevent-core-2.1-7:amd64                                   2.1.12-stable-1                    amd64        Asynchronous event notification library (core)
    ii  libevent-dev                                                2.1.12-stable-1                    amd64        Asynchronous event notification library (development files)
    ii  libevent-extra-2.1-7:amd64                                  2.1.12-stable-1                    amd64        Asynchronous event notification library (extra)
    ii  libevent-openssl-2.1-7:amd64                                2.1.12-stable-1                    amd64        Asynchronous event notification library (openssl)
    ii  libevent-pthreads-2.1-7:amd64                               2.1.12-stable-1                    amd64        Asynchronous event notification library (pthreads)
    $ apt policy libevent-dev
    libevent-dev:
      Installed: 2.1.12-stable-1
      Candidate: 2.1.12-stable-1
      Version table:
     *** 2.1.12-stable-1 500
            500 http://deb.debian.org/debian bullseye/main amd64 Packages
            100 /var/lib/dpkg/status
    $ ldd bitcoin-qt | grep event
    	libevent_pthreads-2.1.so.7 => /usr/lib/x86_64-linux-gnu/libevent_pthreads-2.1.so.7 (0x00007f3ceafca000)
    	libevent-2.1.so.7 => /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7 (0x00007f3ceaf71000)
    	libevent_core-2.1.so.7 => /usr/lib/x86_64-linux-gnu/libevent_core-2.1.so.7 (0x00007f3ce9eaa000)
    
    $ apt-file search libevent-2.1.so.7
    libevent-2.1-7: /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7
    libevent-2.1-7: /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.1
    $ dpkg -l libevent-2.1-7
    Desired=Unknown/Install/Remove/Purge/Hold
    | Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
    |/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
    ||/ Name                 Version         Architecture Description
    +++-====================-===============-============-=======================================
    ii  libevent-2.1-7:amd64 2.1.12-stable-1 amd64        Asynchronous event notification library
    $ 
    
  23. fanquake referenced this in commit db7b5dfcc5 on Oct 4, 2023
  24. fanquake closed this on Oct 4, 2023

  25. Frank-GER referenced this in commit b0fea09705 on Oct 13, 2023
  26. anarchymachines commented at 8:51 PM on October 25, 2023: none

    I am experiencing this shutdown hang as well. Just upgraded to v25 on my iMac (running Catalina 10.15.7). Has been hung for over an hour. Last entry in debug.log is "opencon thread exit."

    my question is, is it safe to force quit the application in this state? I have been resynchronizing the blockchain for weeks now and it's about 97% complete so I'm a little paranoid about killing the process. Any info would be appreciated. Thanks

    edit: should also add that prior to trying to quit the application (Bitcoin-QT, btw) it had not processed any new blocks for a few hours. Peers were still connected and data was being transferred in and out but for some reason it wasn't making any progress.

  27. fanquake commented at 8:54 PM on October 25, 2023: member

    Just upgraded to v25 on my iMac

    I would suggest upgrading to 25.1, which has fixed this issue.

  28. anarchymachines commented at 8:59 PM on October 25, 2023: none

    Silly me...I downloaded it from bitcoin.org and didn't even think to look here. Will download right away...but...do you think killing the existing hanging process will most likely be ok?

  29. anarchymachines commented at 5:19 AM on October 26, 2023: none

    I tried to kill the process but it had no effect. Then I tried again with "kill -9 (PID)" and that of course did the trick. Didnt seem to do any harm. However, I installed 25.1 and it seemed to hang on block 813831 while synchronizing headers. Debug.log is full of "New outbound peer connected" (with blocks=813831) and after trying to quit via command + q it has been hung for about 15 minutes on "Bitcoin Core is shutting down..."

    Last message in debug.log is "msghand thread exit"

  30. bitcoin locked this on Oct 25, 2024

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-29 06:13 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me