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

Debian. Valgrind 3.15.0. master @ 68ef9523d1bcd00afbccee2a6585c9f82ddcdb31.

143/158 - feature_uacomment.py failed, Duration: 90 s

stdout:
2020-05-03T01:05:14.172000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20200503_005846/feature_uacomment_22
2020-05-03T01:05:20.091000Z TestFramework (INFO): test multiple -uacomment
2020-05-03T01:05:26.771000Z TestFramework (INFO): test -uacomment max length
2020-05-03T01:06:02.909000Z TestFramework (INFO): test -uacomment unsafe characters
2020-05-03T01:06:44.399000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/bitcoin/test/functional/test_framework/test_node.py", line 450, in assert_start_raises_init_error
    self.wait_for_rpc_connection()
  File "/bitcoin/test/functional/test_framework/test_node.py", line 218, in wait_for_rpc_connection
    raise FailedToStartError(self._node_msg(
test_framework.test_node.FailedToStartError: [node 0] bitcoind exited with status 1 during initialization

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/bitcoin/test/functional/test_framework/test_framework.py", line 113, in main
    self.run_test()
  File "/bitcoin/test/functional/feature_uacomment.py", line 36, in run_test
    self.nodes[0].assert_start_raises_init_error(["-uacomment=" + unsafe_char], expected, match=ErrorMatch.FULL_REGEX)
  File "/bitcoin/test/functional/test_framework/test_node.py", line 467, in assert_start_raises_init_error
    self._raise_assertion_error(
  File "/bitcoin/test/functional/test_framework/test_node.py", line 160, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected message "Error: User Agent comment \(:\) contains unsafe characters." does not fully match stderr:
"Error: User Agent comment (:) contains unsafe characters.
==21155== Thread 8 b-http:
==21155== Invalid read of size 4
==21155==    at 0x48AA7E8: pthread_mutex_lock (pthread_mutex_lock.c:81)
==21155==    by 0x3D6F9D: __gthread_mutex_lock (gthr-default.h:749)
==21155==    by 0x3D6F9D: lock (std_mutex.h:100)
==21155==    by 0x3D6F9D: lock (unique_lock.h:141)
==21155==    by 0x3D6F9D: Enter (sync.h:131)
==21155==    by 0x3D6F9D: UniqueLock (sync.h:152)
==21155==    by 0x3D6F9D: Enqueue (httpserver.cpp:92)
==21155==    by 0x3D6F9D: http_request_cb(evhttp_request*, void*) (httpserver.cpp:267)
==21155==    by 0x4917E6B: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
==21155==    by 0x4915B9F: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
==21155==    by 0x4916462: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
==21155==    by 0x48F0543: bufferevent_run_readcb_ (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
==21155==    by 0x48F4E9B: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
==21155==    by 0x48FAB0E: ??? (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
==21155==    by 0x48FB24E: event_base_loop (in /usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0)
==21155==    by 0x3D26C5: ThreadHTTP(event_base*) (httpserver.cpp:290)
==21155==    by 0x4AA1BDF: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.28)
==21155==    by 0x48A7F26: start_thread (pthread_create.c:479)
==21155==  Address 0x556e348 is 8 bytes inside a block of size 184 free'd
==21155==    at 0x4837EAB: operator delete(void*) (vg_replace_malloc.c:586)
==21155==    by 0x3D79A2: StopHTTPServer() (httpserver.cpp:458)
==21155==    by 0x1CF606: Shutdown(NodeContext&) (init.cpp:191)
==21155==    by 0x1B8F2F: AppInit(int, char**) (bitcoind.cpp:162)
==21155==    by 0x1B373F: main (bitcoind.cpp:178)
==21155==  Block was alloc'd at
==21155==    at 0x4836DEF: operator new(unsigned long) (vg_replace_malloc.c:344)
==21155==    by 0x3D513E: InitHTTPServer() (httpserver.cpp:402)
==21155==    by 0x1D1B4C: AppInitServers (init.cpp:783)
==21155==    by 0x1D1B4C: AppInitMain(NodeContext&) (init.cpp:1340)
==21155==    by 0x1B8F17: AppInit(int, char**) (bitcoind.cpp:148)
==21155==    by 0x1B373F: main (bitcoind.cpp:178)
==21155== 
{
   <insert_a_suppression_name_here>
   Memcheck:Addr4
   fun:pthread_mutex_lock
   fun:__gthread_mutex_lock
   fun:lock
   fun:lock
   fun:Enter
   fun:UniqueLock
   fun:Enqueue
   fun:_ZL15http_request_cbP14evhttp_requestPv
   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
   fun:bufferevent_run_readcb_
   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
   obj:/usr/lib/x86_64-linux-gnu/libevent-2.1.so.7.0.0
   fun:event_base_loop
   fun:_ZL10ThreadHTTPP10event_base
   obj:/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.28
   fun:start_thread
}
==21155== 
==21155== Exit program on first error (--exit-on-first-error=yes)"
2020-05-03T01:06:44.450000Z TestFramework (INFO): Stopping nodes
2020-05-03T01:06:44.450000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20200503_005846/feature_uacomment_22
2020-05-03T01:06:44.450000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/test_runner_₿_🏃_20200503_005846/feature_uacomment_22/test_framework.log
2020-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

• Is the failure reproducible?
• What version of debian?
• What version of libevent?

Is the failure reproducible?

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

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

 node0 2020-05-03T12:01:18.803662Z [init] Error: User Agent comment ()) contains unsafe characters. 
 node0 2020-05-03T12:01:18.813889Z [http] Received a POST request for / from 127.0.0.1:41780 
 node0 2020-05-03T12:01:18.818203Z [init] Interrupting HTTP server 
 node0 2020-05-03T12:01:18.822517Z [init] Interrupting HTTP RPC server 
 node0 2020-05-03T12:01:18.823511Z [init] Interrupting RPC 
 node0 2020-05-03T12:01:18.831487Z [init] Shutdown: In progress... 
 node0 2020-05-03T12:01:18.833661Z [shutoff] Stopping HTTP RPC server 
 node0 2020-05-03T12:01:18.835215Z [shutoff] Unregistering HTTP handler for / (exactmatch 1) 
 node0 2020-05-03T12:01:18.836974Z [shutoff] Unregistering HTTP handler for /wallet/ (exactmatch 0) 
 node0 2020-05-03T12:01:18.839302Z [shutoff] Stopping RPC 
 node0 2020-05-03T12:01:18.845307Z [shutoff] RPC stopped. 
 node0 2020-05-03T12:01:18.846208Z [shutoff] Stopping HTTP server 
 node0 2020-05-03T12:01:18.846888Z [shutoff] Waiting for HTTP worker threads to exit 
 node0 2020-05-03T12:01:18.852777Z [shutoff] Waiting for HTTP event thread to exit 
# crash here because the http POST request from earlier runs into the workQueue that has just been deleted

Locally I get this assertion hit:

bitcoind: httpserver.cpp:270: void http_request_cb(struct evhttp_request *, void *): Assertion `workQueue' failed."

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

Changed the title slightly to indicate what I believe is the problem

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.

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.

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

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

        self.network_event_loop.call_soon_threadsafe(self.network_event_loop.stop)

Cleared milestone for now. Can be backported when merged