rpc: InterruptHTTPServer race / workQueue use-after-free #18856

issue fanquake openend this issue on May 3, 2020
  1. fanquake commented at 3:47 am on May 3, 2020: member

    Debian. Valgrind 3.15.0. master @ 68ef9523d1bcd00afbccee2a6585c9f82ddcdb31.

     0143/158 - feature_uacomment.py failed, Duration: 90 s
     1
     2stdout:
     32020-05-03T01:05:14.172000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20200503_005846/feature_uacomment_22
     42020-05-03T01:05:20.091000Z TestFramework (INFO): test multiple -uacomment
     52020-05-03T01:05:26.771000Z TestFramework (INFO): test -uacomment max length
     62020-05-03T01:06:02.909000Z TestFramework (INFO): test -uacomment unsafe characters
     72020-05-03T01:06:44.399000Z TestFramework (ERROR): Assertion failed
     8Traceback (most recent call last):
     9  File "/bitcoin/test/functional/test_framework/test_node.py", line 450, in assert_start_raises_init_error
    10    self.wait_for_rpc_connection()
    11  File "/bitcoin/test/functional/test_framework/test_node.py", line 218, in wait_for_rpc_connection
    12    raise FailedToStartError(self._node_msg(
    13test_framework.test_node.FailedToStartError: [node 0] bitcoind exited with status 1 during initialization
    14
    15During handling of the above exception, another exception occurred:
    16
    17Traceback (most recent call last):
    18  File "/bitcoin/test/functional/test_framework/test_framework.py", line 113, in main
    19    self.run_test()
    20  File "/bitcoin/test/functional/feature_uacomment.py", line 36, in run_test
    21    self.nodes[0].assert_start_raises_init_error(["-uacomment=" + unsafe_char], expected, match=ErrorMatch.FULL_REGEX)
    22  File "/bitcoin/test/functional/test_framework/test_node.py", line 467, in assert_start_raises_init_error
    23    self._raise_assertion_error(
    24  File "/bitcoin/test/functional/test_framework/test_node.py", line 160, in _raise_assertion_error
    25    raise AssertionError(self._node_msg(msg))
    26AssertionError: [node 0] Expected message "Error: User Agent comment \(:\) contains unsafe characters." does not fully match stderr:
    27"Error: User Agent comment (:) contains unsafe characters.
    28==21155== Thread 8 b-http:
    29==21155== Invalid read of size 4
    30==21155==    at 0x48AA7E8: pthread_mutex_lock (pthread_mutex_lock.c:81)
    31==21155==    by 0x3D6F9D: __gthread_mutex_lock (gthr-default.h:749)
    32==21155==    by 0x3D6F9D: lock (std_mutex.h:100)
    33==21155==    by 0x3D6F9D: lock (unique_lock.h:141)
    34==21155==    by 0x3D6F9D: Enter (sync.h:131)
    35==21155==    by 0x3D6F9D: UniqueLock (sync.h:152)
    36==21155==    by 0x3D6F9D: Enqueue (httpserver.cpp:92)
    37==21155==    by 0x3D6F9D: http_request_cb(evhttp_request*, void*) (httpserver.cpp:267)
    38==21155==    by 0x4917E6B: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
    39==21155==    by 0x4915B9F: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
    40==21155==    by 0x4916462: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
    41==21155==    by 0x48F0543: bufferevent_run_readcb_ (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
    42==21155==    by 0x48F4E9B: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
    43==21155==    by 0x48FAB0E: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
    44==21155==    by 0x48FB24E: event_base_loop (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
    45==21155==    by 0x3D26C5: ThreadHTTP(event_base*) (httpserver.cpp:290)
    46==21155==    by 0x4AA1BDF: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.28)
    47==21155==    by 0x48A7F26: start_thread (pthread_create.c:479)
    48==21155==  Address 0x556e348 is 8 bytes inside a block of size 184 free'd
    49==21155==    at 0x4837EAB: operator delete(void*) (vg_replace_malloc.c:586)
    50==21155==    by 0x3D79A2: StopHTTPServer() (httpserver.cpp:458)
    51==21155==    by 0x1CF606: Shutdown(NodeContext&) (init.cpp:191)
    52==21155==    by 0x1B8F2F: AppInit(int, char**) (bitcoind.cpp:162)
    53==21155==    by 0x1B373F: main (bitcoind.cpp:178)
    54==21155==  Block was alloc'd at
    55==21155==    at 0x4836DEF: operator new(unsigned long) (vg_replace_malloc.c:344)
    56==21155==    by 0x3D513E: InitHTTPServer() (httpserver.cpp:402)
    57==21155==    by 0x1D1B4C: AppInitServers (init.cpp:783)
    58==21155==    by 0x1D1B4C: AppInitMain(NodeContext&) (init.cpp:1340)
    59==21155==    by 0x1B8F17: AppInit(int, char**) (bitcoind.cpp:148)
    60==21155==    by 0x1B373F: main (bitcoind.cpp:178)
    61==21155== 
    62{
    63   <insert_a_suppression_name_here>
    64   Memcheck:Addr4
    65   fun:pthread_mutex_lock
    66   fun:__gthread_mutex_lock
    67   fun:lock
    68   fun:lock
    69   fun:Enter
    70   fun:UniqueLock
    71   fun:Enqueue
    72   fun:_ZL15http_request_cbP14evhttp_requestPv
    73   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
    74   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
    75   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
    76   fun:bufferevent_run_readcb_
    77   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
    78   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
    79   fun:event_base_loop
    80   fun:_ZL10ThreadHTTPP10event_base
    81   obj:/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.28
    82   fun:start_thread
    83}
    84==21155== 
    85==21155== Exit program on first error (--exit-on-first-error=yes)"
    862020-05-03T01:06:44.450000Z TestFramework (INFO): Stopping nodes
    872020-05-03T01:06:44.450000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20200503_005846/feature_uacomment_22
    882020-05-03T01:06:44.450000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/test_runner_₿_🏃_20200503_005846/feature_uacomment_22/test_framework.log
    892020-05-03T01:06:44.451000Z TestFramework (ERROR): Hint: Call /bitcoin/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20200503_005846/feature_uacomment_22' to consolidate all logs
    
  2. fanquake added the label Tests on May 3, 2020
  3. MarcoFalke commented at 11:23 am on May 3, 2020: member
    • Is the failure reproducible?
    • What version of debian?
    • What version of libevent?
  4. fanquake commented at 11:26 am on May 3, 2020: member

    Is the failure reproducible?

    I’ve only seen it once. Debian Bullseye. Libevent 2.1.11.

  5. MarcoFalke commented at 12:13 pm on May 3, 2020: member

    I wonder if libevent cancels ongoing requests on interrupt. What happens here is:

     0 node0 2020-05-03T12:01:18.803662Z [init] Error: User Agent comment ()) contains unsafe characters. 
     1 node0 2020-05-03T12:01:18.813889Z [http] Received a POST request for / from 127.0.0.1:41780 
     2 node0 2020-05-03T12:01:18.818203Z [init] Interrupting HTTP server 
     3 node0 2020-05-03T12:01:18.822517Z [init] Interrupting HTTP RPC server 
     4 node0 2020-05-03T12:01:18.823511Z [init] Interrupting RPC 
     5 node0 2020-05-03T12:01:18.831487Z [init] Shutdown: In progress... 
     6 node0 2020-05-03T12:01:18.833661Z [shutoff] Stopping HTTP RPC server 
     7 node0 2020-05-03T12:01:18.835215Z [shutoff] Unregistering HTTP handler for / (exactmatch 1) 
     8 node0 2020-05-03T12:01:18.836974Z [shutoff] Unregistering HTTP handler for /wallet/ (exactmatch 0) 
     9 node0 2020-05-03T12:01:18.839302Z [shutoff] Stopping RPC 
    10 node0 2020-05-03T12:01:18.845307Z [shutoff] RPC stopped. 
    11 node0 2020-05-03T12:01:18.846208Z [shutoff] Stopping HTTP server 
    12 node0 2020-05-03T12:01:18.846888Z [shutoff] Waiting for HTTP worker threads to exit 
    13 node0 2020-05-03T12:01:18.852777Z [shutoff] Waiting for HTTP event thread to exit 
    14# crash here because the http POST request from earlier runs into the workQueue that has just been deleted
    
  6. MarcoFalke commented at 12:13 pm on May 3, 2020: member

    Locally I get this assertion hit:

    0bitcoind: httpserver.cpp:270: void http_request_cb(struct evhttp_request *, void *): Assertion `workQueue' failed."
    
  7. MarcoFalke commented at 12:16 pm on May 3, 2020: member
    InterruptHTTPServer does not cancel or flush already dispatched requests. It merely redirects future ones. This is a bug.
  8. MarcoFalke removed the label Tests on May 3, 2020
  9. MarcoFalke added the label Bug on May 3, 2020
  10. MarcoFalke added the label RPC/REST/ZMQ on May 3, 2020
  11. MarcoFalke added this to the milestone 0.20.0 on May 3, 2020
  12. MarcoFalke renamed this:
    feature_uacomment.py failure under valgrind
    rpc: InterruptHTTPServer race
    on May 11, 2020
  13. MarcoFalke renamed this:
    rpc: InterruptHTTPServer race
    rpc: InterruptHTTPServer race / workQueue use-after-free
    on May 11, 2020
  14. MarcoFalke commented at 12:40 pm on May 11, 2020: member
    Changed the title slightly to indicate what I believe is the problem
  15. MarcoFalke removed this from the milestone 0.20.0 on May 15, 2020
  16. MarcoFalke added this to the milestone 0.20.1 on May 15, 2020
  17. MarcoFalke commented at 12:05 pm on May 15, 2020: member
    Move milestone, because I believe this bug has been around for as long as the code exists. So it seems unlikely to be a regression in the current release.
  18. promag commented at 10:37 am on May 17, 2020: member

    InterruptHTTPServer does not cancel or flush already dispatched requests. It merely redirects future ones. This is a bug.

    I don’t think this is a bug.

    I think the bug is when the queue is deleted - which is after all worker threads terminate - but an active request still can use the queue - hence your assertion.

    IMO the fix is to run InterruptHTTPServer code in the event base.

  19. MarcoFalke commented at 10:41 am on May 17, 2020: member

    IMO the fix is to run InterruptHTTPServer code in the event base.

    This is also how the functional tests shut down the event loop.

    0        self.network_event_loop.call_soon_threadsafe(self.network_event_loop.stop)
    
  20. MarcoFalke removed this from the milestone 0.20.1 on Jun 6, 2020
  21. MarcoFalke added this to the milestone 0.19.2 on Jun 6, 2020
  22. MarcoFalke removed this from the milestone 0.19.2 on Dec 3, 2020
  23. MarcoFalke commented at 7:04 pm on December 3, 2020: member
    Cleared milestone for now. Can be backported when merged
  24. laanwj closed this on Jun 21, 2021

  25. sidhujag referenced this in commit 65b2508920 on Jun 24, 2021
  26. PastaPastaPasta referenced this in commit d98ea7d83e on Jun 27, 2021
  27. PastaPastaPasta referenced this in commit c9f495cf28 on Jun 28, 2021
  28. PastaPastaPasta referenced this in commit 35de8157e0 on Jun 29, 2021
  29. PastaPastaPasta referenced this in commit c5b5037146 on Jul 1, 2021
  30. PastaPastaPasta referenced this in commit b0f61bbd01 on Jul 1, 2021
  31. PastaPastaPasta referenced this in commit d3f9a66580 on Jul 15, 2021
  32. DrahtBot locked this on Aug 18, 2022

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-10-04 22:12 UTC

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