bitcoind hangs waiting for g_requests.empty() #27722

issue Crypt-iQ openend 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:

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

    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:

    0./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):

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

    Output of gcc --version:

    0Configured 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
    1Apple clang version 11.0.3 (clang-1103.0.32.62)
    2Target: x86_64-apple-darwin21.6.0
    3Thread model: posix
    4InstalledDir: /Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin
    

    Output of g++ --version:

    0Configured 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
    1Apple clang version 11.0.3 (clang-1103.0.32.62)
    2Target: x86_64-apple-darwin21.6.0
    3Thread model: posix
    4InstalledDir: /Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin
    

    My libevent version is 2.1.12

    Relevant log output

     0^C2023-05-22T20:56:10Z [http] Interrupting HTTP server
     12023-05-22T20:56:10Z [rpc] Interrupting HTTP RPC server
     22023-05-22T20:56:10Z [rpc] Interrupting RPC
     32023-05-22T20:56:10Z tor: Thread interrupt
     42023-05-22T20:56:10Z Shutdown: In progress...
     52023-05-22T20:56:10Z [rpc] Stopping HTTP RPC server
     62023-05-22T20:56:10Z torcontrol thread exit
     72023-05-22T20:56:10Z [http] Unregistering HTTP handler for / (exactmatch 1)
     82023-05-22T20:56:10Z addcon thread exit
     92023-05-22T20:56:10Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    102023-05-22T20:56:10Z [rpc] Stopping RPC
    112023-05-22T20:56:10Z net thread exit
    122023-05-22T20:56:10Z [rpc] RPC stopped.
    132023-05-22T20:56:10Z [http] Stopping HTTP server
    142023-05-22T20:56:10Z [http] Waiting for HTTP worker threads to exit
    152023-05-22T20:56:10Z [http] Exited http event loop
    162023-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:

    02023-05-23T13:58:01Z [http] Unregistering HTTP handler for / (exactmatch 1)
    12023-05-23T13:58:01Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    22023-05-23T13:58:01Z [http] Stopping HTTP server
    32023-05-23T13:58:01Z [http] Waiting for HTTP worker threads to exit
    42023-05-23T13:58:01Z [http] Waiting for 1 requests to stop HTTP server
    52023-05-23T13:58:01Z [http] Exited http event loop
    62023-05-23T13:58:01Z msghand thread exit
    72023-05-23T13:58:01Z net thread exit
    82023-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: contributor

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

    With @theStack method:

     02023-05-26T10:39:07Z [http] Received a POST request for / from 127.0.0.1:50704
     1^C2023-05-26T10:39:10Z [http] Interrupting HTTP server
     22023-05-26T10:39:10Z tor: Thread interrupt
     32023-05-26T10:39:10Z torcontrol thread exit
     42023-05-26T10:39:10Z addcon thread exit
     52023-05-26T10:39:10Z opencon thread exit
     62023-05-26T10:39:10Z Shutdown: In progress...
     72023-05-26T10:39:10Z [http] Unregistering HTTP handler for / (exactmatch 1)
     82023-05-26T10:39:10Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
     92023-05-26T10:39:10Z [http] Stopping HTTP server
    102023-05-26T10:39:10Z [http] Waiting for HTTP worker threads to exit
    112023-05-26T10:39:10Z [http] Waiting for 1 requests to stop HTTP server
    122023-05-26T10:39:10Z [http] Waiting for HTTP event thread to exit
    132023-05-26T10:39:10Z [http] Exited http event loop
    142023-05-26T10:39:10Z [http] Stopped HTTP server
    152023-05-26T10:39:10Z loadblk thread exit
    162023-05-26T10:39:10Z net thread exit
    172023-05-26T10:39:10Z msghand thread exit
    182023-05-26T10:39:10Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat started
    192023-05-26T10:39:10Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat completed (0.00s)
    202023-05-26T10:39:10Z scheduler thread exit
    212023-05-26T10:39:16Z Shutdown: done
    

    With @Crypt-iQ method:

      0... many lines like this
      12023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59546
      22023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59562
      32023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59566
      42023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59570
      52023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59574
      62023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59580
      72023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59590
      82023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59596
      92023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59606
     102023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59616
     112023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59618
     122023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59636
     132023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59638
     142023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59660
     152023-05-26T10:42:04Z [http] Received a POST request for / from 127.0.0.1:59658
     162023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59686
     172023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59684
     182023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59704
     192023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59706
     202023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59722
     212023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59734
     222023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59740
     232023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59746
     242023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59760
     252023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59774
     262023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59790
     272023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59792
     282023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59798
     292023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59802
     302023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59804
     312023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59818
     322023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59822
     332023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59828
     342023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59826
     352023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59840
     362023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59854
     372023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59864
     382023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59866
     392023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59870
     402023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59868
     412023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59886
     422023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59900
     432023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59914
     442023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59928
     452023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59944
     462023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59960
     472023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59964
     482023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59968
     492023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59980
     502023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:59982
     512023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60002
     522023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60004
     532023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60010
     542023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60008
     552023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60018
     562023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60016
     572023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60038
     582023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60044
     592023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60048
     602023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60054
     612023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60066
     622023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60064
     632023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60080
     642023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60082
     652023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60108
     662023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60110
     672023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60124
     682023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60128
     692023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60130
     702023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60142
     712023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60154
     722023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60158
     732023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60170
     742023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60168
     752023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60186
     762023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60184
     772023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60196
     782023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60198
     792023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60224
     802023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60226
     812023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60242
     822023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60244
     832023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60258
     842023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60256
     852023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60284
     862023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60296
     872023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60298
     882023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60310
     892023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60320
     902023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60336
     912023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60344
     922023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60342
     932023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60362
     942023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60370
     952023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60378
     962023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60382
     972023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60386
     982023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60388
     992023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60400
    1002023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60402
    1012023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60422
    1022023-05-26T10:42:05Z [http] Received a POST request for / from 127.0.0.1:60430
    1032023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60436
    1042023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60450
    1052023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60462
    1062023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60468
    1072023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60472
    1082023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60470
    1092023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60494
    1102023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60496
    1112023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60508
    1122023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60510
    1132023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60514
    1142023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60522
    1152023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60524
    1162023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60532
    1172023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60544
    1182023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60552
    1192023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60556
    1202023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60560
    1212023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60570
    1222023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60582
    1232023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60592
    1242023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60598
    1252023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60612
    1262023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60614
    1272023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60620
    1282023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60626
    1292023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60628
    1302023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60646
    1312023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60654
    1322023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60652
    1332023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60676
    1342023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60678
    1352023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60680
    1362023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60688
    1372023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60700
    1382023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60706
    1392023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60710
    1402023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60712
    1412023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60724
    1422023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60736
    1432023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60750
    1442023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60756
    1452023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60760
    1462023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60772
    1472023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60776
    1482023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60788
    1492023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60802
    1502023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60814
    1512023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60816
    1522023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60828
    1532023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60830
    1542023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60846
    1552023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60848
    1562023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60854
    1572023-05-26T10:42:06Z [http] Received a POST request for / from 127.0.0.1:60866
    1582023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60880
    1592023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60892
    1602023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60896
    1612023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60906
    1622023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60918
    1632023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60934
    1642023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60940
    1652023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60950
    1662023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60960
    1672023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60972
    1682023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60988
    1692023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:60994
    1702023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32772
    1712023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32774
    1722023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32776
    1732023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32778
    1742023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32788
    1752023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32802
    1762023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32812
    1772023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32828
    1782023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32830
    1792023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32832
    1802023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32846
    1812023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32854
    1822023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32870
    1832023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32872
    1842023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32876
    1852023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32890
    1862023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32892
    1872023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32904
    1882023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32906
    1892023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32912
    1902023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32928
    1912023-05-26T10:42:07Z [http] Received a POST request for / from 127.0.0.1:32934
    192^C2023-05-26T10:42:14Z [http] Interrupting HTTP server
    1932023-05-26T10:42:14Z tor: Thread interrupt
    1942023-05-26T10:42:14Z torcontrol thread exit
    1952023-05-26T10:42:14Z opencon thread exit
    1962023-05-26T10:42:14Z addcon thread exit
    1972023-05-26T10:42:14Z Shutdown: In progress...
    1982023-05-26T10:42:14Z [http] Unregistering HTTP handler for / (exactmatch 1)
    1992023-05-26T10:42:14Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    2002023-05-26T10:42:14Z [http] Stopping HTTP server
    2012023-05-26T10:42:14Z [http] Waiting for HTTP worker threads to exit
    2022023-05-26T10:42:14Z [http] Exited http event loop
    2032023-05-26T10:42:14Z [http] Waiting for HTTP event thread to exit
    2042023-05-26T10:42:14Z [http] Stopped HTTP server
    2052023-05-26T10:42:14Z net thread exit
    2062023-05-26T10:42:14Z loadblk thread exit
    2072023-05-26T10:42:14Z msghand thread exit
    2082023-05-26T10:42:14Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat started
    2092023-05-26T10:42:14Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat completed (0.00s)
    2102023-05-26T10:42:14Z scheduler thread exit
    2112023-05-26T10:42:15Z Shutdown: done
    
  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.

    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.

  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: contributor

    @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: 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?

    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…

      02023-06-28T08:47:52Z [libevent:debug] event_active: 0x55c039f36038 (fd 12), res 2, callback 0x7ff7a7371270
      12023-06-28T08:47:52Z [libevent:debug] event_process_active: event: 0x55c039f36038, EV_READ   call 0x7ff7a7371270
      22023-06-28T08:47:52Z [libevent:debug] evhttp_get_request_connection: new request from 127.0.0.1:46142 on 44
      3
      42023-06-28T08:47:52Z [libevent:debug] Attempting connection to 127.0.0.1:46142
      5
      62023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff7500053f0 (fd -1), callback 0x7ff7a7361f90
      72023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff750005470 (fd -1), callback 0x7ff7a7362740
      82023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff750005470 (fd 44),  EV_WRITE   call 0x7ff7a7362740
      92023-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)
     102023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ    call 0x7ff7a7361f90
     112023-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)
     122023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff750005470 (fd 44), callback 0x7ff7a7362740
     132023-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)
     142023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
     152023-06-28T08:47:52Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 30 seconds 0 useconds, call 0x7ff7a7361f90
     162023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff750005470 (fd 44), callback 0x7ff7a7362740
     172023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
     182023-06-28T08:47:52Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 30 seconds 0 useconds, call 0x7ff7a7361f90
     192023-06-28T08:47:52Z [libevent:debug] timeout_next: event: 0x7ff7500053f0, in 30 seconds, 0 useconds
     202023-06-28T08:47:52Z [libevent:debug] epoll_dispatch: epoll_wait reports 1
     212023-06-28T08:47:52Z [libevent:debug] event_active: 0x7ff7500053f0 (fd 44), res 2, callback 0x7ff7a7361f90
     222023-06-28T08:47:52Z [libevent:debug] event_process_active: event: 0x7ff7500053f0, EV_READ   call 0x7ff7a7361f90
     232023-06-28T08:47:52Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
     242023-06-28T08:47:52Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 70594 seconds 199020 useconds, call 0x7ff7a7361f90
     252023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Host val: 127.0.0.1
     26
     272023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Connection val: close
     28
     292023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Content-Type val: application/json
     30
     312023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Authorization val: Basic xxxxxxx
     32
     332023-06-28T08:47:52Z [libevent:debug] evhttp_add_header: key: Content-Length val: 58
     34
     352023-06-28T08:47:52Z [libevent:debug] evhttp_read_header: checking for post data on 44
     36
     372023-06-28T08:47:52Z [libevent:debug] evhttp_get_body_length: bytes to read: 58 (in buffer 58)
     38
     392023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff7500053f0 (fd 44), callback 0x7ff7a7361f90
     402023-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)
     412023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff7500053f0 (fd 44), callback 0x7ff7a7361f90
     422023-06-28T08:47:52Z [libevent:debug] event_del: 0x7ff7500053f0 (fd 44), callback 0x7ff7a7361f90
     432023-06-28T08:47:52Z [http] Received a POST request for / from 127.0.0.1:46142
     44^C2023-06-28T08:47:57Z [http] Interrupting HTTP server
     452023-06-28T08:47:57Z tor: Thread interrupt
     462023-06-28T08:47:57Z [libevent:debug] event_active: 0x55c0458e3250 (fd -1), res 1, callback 0x7ff7a7366100
     472023-06-28T08:47:57Z [libevent:debug] epoll_dispatch: epoll_wait reports 1
     482023-06-28T08:47:57Z [libevent:debug] event_active: 0x55c0458e51f0 (fd 30), res 2, callback 0x7ff7a736c690
     492023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c0458e3250 (fd -1), callback 0x7ff7a7366100
     502023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x55c0458e3250,    call 0x7ff7a7366100
     512023-06-28T08:47:57Z [libevent:debug] event_base_loop: asked to terminate loop.
     522023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff640001080 (fd -1), callback 0x55c03736e022
     532023-06-28T08:47:57Z torcontrol thread exit
     542023-06-28T08:47:57Z Shutdown: In progress...
     552023-06-28T08:47:57Z addcon thread exit
     562023-06-28T08:47:57Z opencon thread exit
     572023-06-28T08:47:57Z [http] Unregistering HTTP handler for / (exactmatch 1)
     582023-06-28T08:47:57Z [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
     592023-06-28T08:47:57Z [http] Stopping HTTP server
     602023-06-28T08:47:57Z [http] Waiting for HTTP worker threads to exit
     612023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Content-Type val: application/json
     62
     632023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Connection val: close
     64
     652023-06-28T08:47:57Z [libevent:debug] event_active: 0x7ff730001240 (fd -1), res 0, callback 0x55c03750235f
     662023-06-28T08:47:57Z [libevent:debug] epoll_dispatch: epoll_wait reports 1
     672023-06-28T08:47:57Z [libevent:debug] event_active: 0x55c039f35bc0 (fd 10), res 2, callback 0x7ff7a736c690
     682023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff730001240 (fd -1), callback 0x55c03750235f
     692023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x7ff730001240,    call 0x55c03750235f
     702023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Date val: Wed, 28 Jun 2023 08:47:57 GMT
     71
     722023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Content-Length val: 123
     73
     742023-06-28T08:47:57Z [libevent:debug] evhttp_add_header: key: Connection val: close
     75
     762023-06-28T08:47:57Z [libevent:debug] evhttp_write_buffer: preparing to write buffer
     77
     782023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
     792023-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)
     802023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 30 seconds 0 useconds, call 0x7ff7a7361f90
     812023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff750005470 (fd 44),  EV_WRITE  EV_TIMEOUT call 0x7ff7a7362740
     822023-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)
     832023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff750005470, timeout in 30 seconds 0 useconds, call 0x7ff7a7362740
     842023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff7500053f0 (fd 44), EV_READ   EV_TIMEOUT call 0x7ff7a7361f90
     852023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff7500053f0, timeout in 30 seconds 0 useconds, call 0x7ff7a7361f90
     862023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff750005470 (fd 44),  EV_WRITE  EV_TIMEOUT call 0x7ff7a7362740
     872023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff750005470, timeout in 30 seconds 0 useconds, call 0x7ff7a7362740
     882023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff730001240 (fd -1), callback 0x55c03750235f
     892023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x55c039f35bc0, EV_READ   call 0x7ff7a736c690
     902023-06-28T08:47:57Z [libevent:debug] timeout_next: event: 0x7ff7500053f0, in 30 seconds, 0 useconds
     912023-06-28T08:47:57Z [libevent:debug] epoll_dispatch: epoll_wait reports 1
     922023-06-28T08:47:57Z [libevent:debug] event_active: 0x7ff750005470 (fd 44), res 4, callback 0x7ff7a7362740
     932023-06-28T08:47:57Z [libevent:debug] event_active: 0x7ff7500053f0 (fd 44), res 2, callback 0x7ff7a7361f90
     942023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x7ff750005470,  EV_WRITE  call 0x7ff7a7362740
     952023-06-28T08:47:57Z [libevent:debug] event_add: event: 0x7ff750005470 (fd 44),  EV_WRITE  EV_TIMEOUT call 0x7ff7a7362740
     962023-06-28T08:47:57Z [libevent:debug] event_add: event 0x7ff750005470, timeout in 70599 seconds 923008 useconds, call 0x7ff7a7362740
     972023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c039f36658 (fd 11), callback 0x7ff7a7371270
     982023-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)
     992023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff750005470 (fd 44), callback 0x7ff7a7362740
    1002023-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)
    1012023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c039f36038 (fd 12), callback 0x7ff7a7371270
    1022023-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)
    1032023-06-28T08:47:57Z [libevent:debug] event_active: 0x55c04518ec30 (fd -1), res 1, callback 0x7ff7a7366100
    1042023-06-28T08:47:57Z [http] Waiting for HTTP event thread to exit
    1052023-06-28T08:47:57Z [libevent:debug] event_callback_finalize_many_: 3 events finalizing
    1062023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff7500053f0 (fd 44), callback 0x7ff7a7361f90
    1072023-06-28T08:47:57Z [libevent:debug] Epoll DEL(1) on fd 44 gave Bad file descriptor: DEL was unnecessary.
    1082023-06-28T08:47:57Z [libevent:debug] event_del: 0x7ff750005470 (fd 44), callback 0x7ff7a7362740
    1092023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c04518ec30 (fd -1), callback 0x7ff7a7366100
    1102023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x55c04518ec30,    call 0x7ff7a7366100
    1112023-06-28T08:47:57Z [libevent:debug] event_process_active: event: 0x7ff750005470,  EV_WRITE  call 0x7ff7a735f910
    1122023-06-28T08:47:57Z [libevent:debug] event_base_loop: no events registered.
    1132023-06-28T08:47:57Z [http] Exited http event loop
    1142023-06-28T08:47:57Z [libevent:debug] event_del: 0x55c039f35bc0 (fd 10), callback 0x7ff7a736c690
    1152023-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)
    1162023-06-28T08:47:57Z [libevent:debug] event_base_free_: 0 events freed
    1172023-06-28T08:47:57Z [http] Stopped HTTP server
    1182023-06-28T08:47:57Z loadblk thread exit
    1192023-06-28T08:47:57Z msghand thread exit
    1202023-06-28T08:47:57Z net thread exit
    1212023-06-28T08:47:58Z i2paccept thread exit
    1222023-06-28T08:47:58Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat started
    1232023-06-28T08:47:58Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat completed (0.01s)
    1242023-06-28T08:47:58Z [libevent:debug] event_del: 0x55c0458e51f0 (fd 30), callback 0x7ff7a736c690
    1252023-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)
    1262023-06-28T08:47:58Z [libevent:debug] event_base_free_: 0 events freed
    1272023-06-28T08:47:58Z scheduler thread exit
    1282023-06-28T08:47:58Z Flushed fee estimates to fee_estimates.dat.
    1292023-06-28T08:47:59Z Shutdown: done
    

    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?

    02023-06-28T08:47:57Z [libevent:debug] Epoll DEL(1) on fd 44 gave Bad file descriptor: DEL was unnecessary.
    1# continues with shutdown
    2...
    
  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 0: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.

     0$ dpkg -l | grep libevent
     1ii  libev4:amd64                                                1:4.33-1                           amd64        high-performance event loop library modelled after libevent
     2ii  libevent-2.1-7:amd64                                        2.1.12-stable-1                    amd64        Asynchronous event notification library
     3ii  libevent-core-2.1-7:amd64                                   2.1.12-stable-1                    amd64        Asynchronous event notification library (core)
     4ii  libevent-dev                                                2.1.12-stable-1                    amd64        Asynchronous event notification library (development files)
     5ii  libevent-extra-2.1-7:amd64                                  2.1.12-stable-1                    amd64        Asynchronous event notification library (extra)
     6ii  libevent-openssl-2.1-7:amd64                                2.1.12-stable-1                    amd64        Asynchronous event notification library (openssl)
     7ii  libevent-pthreads-2.1-7:amd64                               2.1.12-stable-1                    amd64        Asynchronous event notification library (pthreads)
     8$ apt policy libevent-dev
     9libevent-dev:
    10  Installed: 2.1.12-stable-1
    11  Candidate: 2.1.12-stable-1
    12  Version table:
    13 *** 2.1.12-stable-1 500
    14        500 http://deb.debian.org/debian bullseye/main amd64 Packages
    15        100 /var/lib/dpkg/status
    16$ ldd bitcoin-qt | grep event
    17	libevent_pthreads-2.1.so.7 => /usr/lib/x86_64-linux-gnu/libevent_pthreads-2.1.so.7 (0x00007f3ceafca000)
    18	libevent-2.1.so.7 => /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7 (0x00007f3ceaf71000)
    19	libevent_core-2.1.so.7 => /usr/lib/x86_64-linux-gnu/libevent_core-2.1.so.7 (0x00007f3ce9eaa000)
    20
    21$ apt-file search libevent-2.1.so.7
    22libevent-2.1-7: /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7
    23libevent-2.1-7: /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.1
    24$ dpkg -l libevent-2.1-7
    25Desired=Unknown/Install/Remove/Purge/Hold
    26| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
    27|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
    28||/ Name                 Version         Architecture Description
    29+++-====================-===============-============-=======================================
    30ii  libevent-2.1-7:amd64 2.1.12-stable-1 amd64        Asynchronous event notification library
    31$ 
    
  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”


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: 2024-09-28 22:12 UTC

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