Improve shutdown process #11006

promag · 2017-08-08T03:02:25Z

Improve the shutdown time by not having to wait up to 2 seconds.

Here is a comparison running wallet.py function tests before this PR:

2017-08-08 03:25:20.881000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testq_ramjjr
2017-08-08 03:25:23.853000 TestFramework (INFO): Mining blocks...
2017-08-08 03:25:24.132000 TestFramework (INFO): test getmemoryinfo
2017-08-08 03:25:24.559000 TestFramework (INFO): test gettxout
2017-08-08 03:25:59.858000 TestFramework (INFO): check -rescan
2017-08-08 03:26:07.735000 TestFramework (INFO): check -reindex
2017-08-08 03:26:15.751000 TestFramework (INFO): check -zapwallettxes=1
2017-08-08 03:26:24.105000 TestFramework (INFO): check -zapwallettxes=2
2017-08-08 03:26:36.694000 TestFramework (INFO): Stopping nodes
2017-08-08 03:26:43.599000 TestFramework (INFO): Cleaning up
2017-08-08 03:26:43.612000 TestFramework (INFO): Tests successful

After:

2017-08-08 03:24:04.319000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testoqeyi50_
2017-08-08 03:24:07.035000 TestFramework (INFO): Mining blocks...
2017-08-08 03:24:07.317000 TestFramework (INFO): test getmemoryinfo
2017-08-08 03:24:07.763000 TestFramework (INFO): test gettxout
2017-08-08 03:24:25.715000 TestFramework (INFO): check -rescan
2017-08-08 03:24:27.792000 TestFramework (INFO): check -reindex
2017-08-08 03:24:29.797000 TestFramework (INFO): check -zapwallettxes=1
2017-08-08 03:24:32.207000 TestFramework (INFO): check -zapwallettxes=2
2017-08-08 03:24:36.812000 TestFramework (INFO): Stopping nodes
2017-08-08 03:24:37.915000 TestFramework (INFO): Cleaning up
2017-08-08 03:24:37.927000 TestFramework (INFO): Tests successful

This largely improves the time spent in Travis (under evaluation).

promag · 2017-08-08T03:14:34Z

With this change the time should be significantly lower than 5 seconds. This was motivated by @jnewbery comment.

promag · 2017-08-08T03:39:40Z

For the record, running with version libevent@2.1.8.

If there is a minimum version required, can it be defined, like boost?

jnewbery · 2017-08-08T09:48:30Z

This PR should just have 2195bb0e579336f2b9adfb9a2e23957e794f5621. You can remove the other commits.

You could potentially protect this change with a preprocessor:

#if LIBEVENT_VERSION_NUMBER >= 0x02xxxxxx

I don't know what version of libevent the event_base_loopexit behaviour was fixed. Perhaps @laanwj can offer some clues (he's the author of #6990).

Definitely seems like a good win for test run times.

laanwj · 2017-08-08T09:51:58Z

src/httpserver.cpp

-            LogPrintf("HTTP event loop did not exit within allotted time, sending loopbreak\n");
-            event_base_loopbreak(eventBase);
-        }
+        event_base_loopexit(eventBase, nullptr);


I don't get it - you don't give any rationale for reverting this and removing the comment.

As I understand it, removing the timeout here (resulting in instant shutdown) means that responses from RPC stop might not come back, as the http event handler is killed before that could finish. This resulted in intermittent travis errors.

No, that happens when evhttp_free is called.

I'm sure that at least used to be the case, we had problems here in the past, this is why this particular shutdown sequence was changed so many times.

laanwj · 2017-08-08T09:53:18Z

I don't know what version of libevent the event_base_loopexit behaviour was fixed. Perhaps @laanwj can offer some clues (he's the author of #6990).

No, I don't know, and we certainly can't assume that everyone is building against a version where this is fixed. Not least because libevent's release schedule is very slow.

promag · 2017-08-08T09:58:42Z

@jnewbery yes extra commits were mistakenly pushed when testing with other branch. Will fix.

promag · 2017-08-08T09:59:45Z

@laanwj what about keeping the older code for older libevents?

laanwj · 2017-08-08T10:00:19Z

@laanwj what about keeping the older code for older libevents?

Yes, I'd say that is a requirement.

promag · 2017-08-08T12:36:08Z

@laanwj @jnewbery will try to dissect which version has bad behaviour.

Will add a comment before event_base_loopexit.

promag · 2017-08-09T06:36:43Z

With libevent@2.0.21 (the version that supposedly has issues with event_base_loopexit everything seems to work (at least on my system). Maybe the problem was in other place? I'll dig a bit more.

laanwj · 2017-08-09T09:46:59Z

everything seems to work (at least on my system)

As I remember the intermittent errors on issuing stop, might well not happen locally in good-weather conditions. As we all know, travis VMs run on overbooked, extremely busy servers, so it's more likely to happen there. Maybe it can be simulated by adding an artificial delay somewhere, my hunch would be to have the client side read the RPC response to stop after a delay.

jnewbery · 2017-08-09T20:35:37Z

@laanwj - forgive me, I'm trying to piece together the history of changes to the shutdown procedure:

In Make HTTP server shutdown more graceful #6719, you changed from using event_base_loopbreak() to event_base_loopexit() with a timeout. That was to make sure that the server shut down gracefully and didn't just drop responses to pending requests.
In http: speed up shutdown #6990, you say that 'event_base_loopexit was not doing what I expected it to. What I expected was that it sets a timeout, given that no other pending events it would exit in N seconds. However, what it does was delay the event loop exit with N seconds, even if nothing is pending.' I can't understand the difference between those two statements. That PR switches from calling event_base_loopexit() to call event_base_loopbreak() after a 2 second delay.
Later in the same PR, you say 'it appears that with libevent master, this issue doesn't exist.
event_base_loopexit does actually do what I expect it to in the OP.' Looking at the documentation, if event_base_loopexit is called with a time value, then it will always wait for that long before exiting. If it's called without a time value, it'll exit after the next base loop iteration (http://www.wangafu.net/~nickm/libevent-2.1/doxygen/html/event_8h.html#ab89f0c907906f784fc80a3107016c3dc)

So I think what we want is to just call event_base_loopexit() without a time value. That would allow the current loop to exit, so shutdown should be graceful. I can't tell from the history or your notes whether you tried that before. Is there any reason that wouldn't work? (specifically, I'm just looking for your issue with event_base_loopexit was)

jnewbery · 2017-08-09T20:36:31Z

Oh, and Concept ACK:

locally with this PR:

TEST                           | STATUS    | DURATION

abandonconflict.py             | ✓ Passed  | 4 s 
...
zmq_test.py                    | ✓ Passed  | 2 s 

ALL                            | ✓ Passed  | 630 s (accumulated)
Runtime: 162 s

locally without this PR:

TEST                           | STATUS    | DURATION

abandonconflict.py             | ✓ Passed  | 14 s
...
zmq_test.py                    | ✓ Passed  | 7 s 

ALL                            | ✓ Passed  | 985 s (accumulated)
Runtime: 269 s

Seems like a huge win (40% over the BASE_SCRIPTS test suite)

promag · 2017-08-09T20:42:50Z

Nice @jnewbery. Furthermore, the the docs say

tv	the amount of time after which the loop should terminate, or NULL to exit after running all currently active events.

And while the RPC response is being handled, there is an active event.

promag · 2017-08-09T20:44:36Z

IMO we should just add the loop exit, and keep the break after the timeout.

jnewbery · 2017-08-09T20:55:14Z

IMO we should just add the loop exit, and keep the break after the timeout.

Sounds reasonable if you're able to test this against old versions of libevent (and pending any further background info from @laanwj)

promag · 2017-08-12T03:33:31Z

@laanwj you mean:

diff --git a/test/functional/test_framework/authproxy.py b/test/functional/test_framework/authproxy.py
index b3671cbdc..5a2f9c514 100644
--- a/test/functional/test_framework/authproxy.py
+++ b/test/functional/test_framework/authproxy.py
@@ -166,6 +166,8 @@ class AuthServiceProxy(object):
     def _get_response(self):
         req_start_time = time.time()
         try:
+            if self._service_name == 'stop':
+                time.sleep(3)
             http_response = self.__conn.getresponse()
         except socket.timeout as e:
             raise JSONRPCException({

All looks good, even with libevent@2.0.21.

laanwj · 2017-10-18T14:06:17Z

utACK 793667a, my concerns have been addressed.

793667a Improve shutdown process (João Barbosa) Pull request description: Improve the shutdown time by not having to wait up to 2 seconds. Here is a comparison running `wallet.py` function tests before this PR: ``` 2017-08-08 03:25:20.881000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testq_ramjjr 2017-08-08 03:25:23.853000 TestFramework (INFO): Mining blocks... 2017-08-08 03:25:24.132000 TestFramework (INFO): test getmemoryinfo 2017-08-08 03:25:24.559000 TestFramework (INFO): test gettxout 2017-08-08 03:25:59.858000 TestFramework (INFO): check -rescan 2017-08-08 03:26:07.735000 TestFramework (INFO): check -reindex 2017-08-08 03:26:15.751000 TestFramework (INFO): check -zapwallettxes=1 2017-08-08 03:26:24.105000 TestFramework (INFO): check -zapwallettxes=2 2017-08-08 03:26:36.694000 TestFramework (INFO): Stopping nodes 2017-08-08 03:26:43.599000 TestFramework (INFO): Cleaning up 2017-08-08 03:26:43.612000 TestFramework (INFO): Tests successful ``` After: ``` 2017-08-08 03:24:04.319000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testoqeyi50_ 2017-08-08 03:24:07.035000 TestFramework (INFO): Mining blocks... 2017-08-08 03:24:07.317000 TestFramework (INFO): test getmemoryinfo 2017-08-08 03:24:07.763000 TestFramework (INFO): test gettxout 2017-08-08 03:24:25.715000 TestFramework (INFO): check -rescan 2017-08-08 03:24:27.792000 TestFramework (INFO): check -reindex 2017-08-08 03:24:29.797000 TestFramework (INFO): check -zapwallettxes=1 2017-08-08 03:24:32.207000 TestFramework (INFO): check -zapwallettxes=2 2017-08-08 03:24:36.812000 TestFramework (INFO): Stopping nodes 2017-08-08 03:24:37.915000 TestFramework (INFO): Cleaning up 2017-08-08 03:24:37.927000 TestFramework (INFO): Tests successful ``` This largely improves the time spent in Travis (under evaluation). Tree-SHA512: 023012fb3f8a380addf5995a4bf865862fed712cdd1a648d82a710e6566bc3bd34b6c49f9f06d6cc6bd81ca859da50d30d7f786c816e702549ab642e3476426f

HTTP Server cherries from Core: bitcoin/bitcoin#6719 - Make HTTP server shutdown more graceful bitcoin/bitcoin#6859 - http: Restrict maximum size of http + headers bitcoin/bitcoin#6990 - http: speed up shutdown bitcoin/bitcoin#7966 - http: Do a pending c++11 simplification handling work items bitcoin/bitcoin#8421 - httpserver: drop boost (#8023 dependency) bitcoin/bitcoin#11006 - Improve shutdown process

28479f9 qa: Test bitcond shutdown (João Barbosa) 8d3f46e http: Remove timeout to exit event loop (João Barbosa) e98a9ee http: Remove unnecessary event_base_loopexit call (João Barbosa) 6b13580 http: Unlisten sockets after all workers quit (João Barbosa) 18e9685 http: Send "Connection: close" header if shutdown is requested (João Barbosa) 02e1e4e rpc: Add wait argument to stop (João Barbosa) Pull request description: Fixes #11777. Reverts #11006. Replaces #13501. With this change the HTTP server will exit gracefully, meaning that all requests will finish processing and sending the response, even if this means to wait more than 2 seconds (current time allowed to exit the event loop). Another small change is that connections are accepted even when the server is stopping, but HTTP requests are rejected. This can be improved later, especially if chunked replies are implemented. Briefly, before this PR, this is the order or events when a request arrives (RPC `stop`): 1. `bufferevent_disable(..., EV_READ)` 2. `StartShutdown()` 3. `evhttp_del_accept_socket(...)` 4. `ThreadHTTP` terminates (event loop exits) because there are no active or pending events thanks to 1. and 3. 5. client doesn't get the response thanks to 4. This can be verified by applying ```diff // Event loop will exit after current HTTP requests have been handled, so // this reply will get back to the client. StartShutdown(); + MilliSleep(2000); return "Bitcoin server stopping"; } ``` and checking the log output: ``` Received a POST request for / from 127.0.0.1:62443 ThreadRPCServer method=stop user=__cookie__ Interrupting HTTP server ** Exited http event loop Interrupting HTTP RPC server Interrupting RPC tor: Thread interrupt Shutdown: In progress... torcontrol thread exit Stopping HTTP RPC server addcon thread exit opencon thread exit Unregistering HTTP handler for / (exactmatch 1) Unregistering HTTP handler for /wallet/ (exactmatch 0) Stopping RPC RPC stopped. Stopping HTTP server Waiting for HTTP worker threads to exit msghand thread exit net thread exit ... sleep 2 seconds ... Waiting for HTTP event thread to exit Stopped HTTP server ``` For this reason point 3. is moved right after all HTTP workers quit. In that moment HTTP replies are queued in the event loop which keeps spinning util all connections are closed. In order to trigger the server side close with keep alive connections (implicit in HTTP/1.1) the header `Connection: close` is sent if shutdown was requested. This can be tested by ``` bitcoind -regtest nc localhost 18443 POST / HTTP/1.1 Authorization: Basic ... Content-Type: application/json Content-Length: 44 {"jsonrpc": "2.0","method":"stop","id":123} ``` Summing up, this PR: - removes explicit event loop exit — event loop exits once there are no active or pending events - changes the moment the listening sockets are removed — explained above - sends header `Connection: close` on active requests when shutdown was requested which is relevant when it's a persistent connection (default in HTTP 1.1) — libevent is aware of this header and closes the connection gracefully - removes event loop explicit break after 2 seconds timeout Tree-SHA512: 4dac1e86abe388697c1e2dedbf31fb36a394cfafe5e64eadbf6ed01d829542785a8c3b91d1ab680d3f03f912d14fc87176428041141441d25dcb6c98a1e069d8

Summary: Backport of Core PR11006 bitcoin/bitcoin#11006 Prevents a 2-5 second delay every time a node shuts down. Test Plan: `test_runner.py` Before change: ``` ALL | ✓ Passed | 579 s (accumulated) Runtime: 312 s ``` After change: ``` ALL | ✓ Passed | 325 s (accumulated) Runtime: 183 s ``` Reviewers: deadalnix, Fabien, #bitcoin_abc Reviewed By: deadalnix, Fabien, #bitcoin_abc Subscribers: markblundeberg, dagurval, teamcity, schancel Differential Revision: https://reviews.bitcoinabc.org/D2544

793667a Improve shutdown process (João Barbosa) Pull request description: Improve the shutdown time by not having to wait up to 2 seconds. Here is a comparison running `wallet.py` function tests before this PR: ``` 2017-08-08 03:25:20.881000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testq_ramjjr 2017-08-08 03:25:23.853000 TestFramework (INFO): Mining blocks... 2017-08-08 03:25:24.132000 TestFramework (INFO): test getmemoryinfo 2017-08-08 03:25:24.559000 TestFramework (INFO): test gettxout 2017-08-08 03:25:59.858000 TestFramework (INFO): check -rescan 2017-08-08 03:26:07.735000 TestFramework (INFO): check -reindex 2017-08-08 03:26:15.751000 TestFramework (INFO): check -zapwallettxes=1 2017-08-08 03:26:24.105000 TestFramework (INFO): check -zapwallettxes=2 2017-08-08 03:26:36.694000 TestFramework (INFO): Stopping nodes 2017-08-08 03:26:43.599000 TestFramework (INFO): Cleaning up 2017-08-08 03:26:43.612000 TestFramework (INFO): Tests successful ``` After: ``` 2017-08-08 03:24:04.319000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testoqeyi50_ 2017-08-08 03:24:07.035000 TestFramework (INFO): Mining blocks... 2017-08-08 03:24:07.317000 TestFramework (INFO): test getmemoryinfo 2017-08-08 03:24:07.763000 TestFramework (INFO): test gettxout 2017-08-08 03:24:25.715000 TestFramework (INFO): check -rescan 2017-08-08 03:24:27.792000 TestFramework (INFO): check -reindex 2017-08-08 03:24:29.797000 TestFramework (INFO): check -zapwallettxes=1 2017-08-08 03:24:32.207000 TestFramework (INFO): check -zapwallettxes=2 2017-08-08 03:24:36.812000 TestFramework (INFO): Stopping nodes 2017-08-08 03:24:37.915000 TestFramework (INFO): Cleaning up 2017-08-08 03:24:37.927000 TestFramework (INFO): Tests successful ``` This largely improves the time spent in Travis (under evaluation). Tree-SHA512: 023012fb3f8a380addf5995a4bf865862fed712cdd1a648d82a710e6566bc3bd34b6c49f9f06d6cc6bd81ca859da50d30d7f786c816e702549ab642e3476426f

28479f9 qa: Test bitcond shutdown (João Barbosa) 8d3f46e http: Remove timeout to exit event loop (João Barbosa) e98a9ee http: Remove unnecessary event_base_loopexit call (João Barbosa) 6b13580 http: Unlisten sockets after all workers quit (João Barbosa) 18e9685 http: Send "Connection: close" header if shutdown is requested (João Barbosa) 02e1e4e rpc: Add wait argument to stop (João Barbosa) Pull request description: Fixes bitcoin#11777. Reverts bitcoin#11006. Replaces bitcoin#13501. With this change the HTTP server will exit gracefully, meaning that all requests will finish processing and sending the response, even if this means to wait more than 2 seconds (current time allowed to exit the event loop). Another small change is that connections are accepted even when the server is stopping, but HTTP requests are rejected. This can be improved later, especially if chunked replies are implemented. Briefly, before this PR, this is the order or events when a request arrives (RPC `stop`): 1. `bufferevent_disable(..., EV_READ)` 2. `StartShutdown()` 3. `evhttp_del_accept_socket(...)` 4. `ThreadHTTP` terminates (event loop exits) because there are no active or pending events thanks to 1. and 3. 5. client doesn't get the response thanks to 4. This can be verified by applying ```diff // Event loop will exit after current HTTP requests have been handled, so // this reply will get back to the client. StartShutdown(); + MilliSleep(2000); return "Bitcoin server stopping"; } ``` and checking the log output: ``` Received a POST request for / from 127.0.0.1:62443 ThreadRPCServer method=stop user=__cookie__ Interrupting HTTP server ** Exited http event loop Interrupting HTTP RPC server Interrupting RPC tor: Thread interrupt Shutdown: In progress... torcontrol thread exit Stopping HTTP RPC server addcon thread exit opencon thread exit Unregistering HTTP handler for / (exactmatch 1) Unregistering HTTP handler for /wallet/ (exactmatch 0) Stopping RPC RPC stopped. Stopping HTTP server Waiting for HTTP worker threads to exit msghand thread exit net thread exit ... sleep 2 seconds ... Waiting for HTTP event thread to exit Stopped HTTP server ``` For this reason point 3. is moved right after all HTTP workers quit. In that moment HTTP replies are queued in the event loop which keeps spinning util all connections are closed. In order to trigger the server side close with keep alive connections (implicit in HTTP/1.1) the header `Connection: close` is sent if shutdown was requested. This can be tested by ``` bitcoind -regtest nc localhost 18443 POST / HTTP/1.1 Authorization: Basic ... Content-Type: application/json Content-Length: 44 {"jsonrpc": "2.0","method":"stop","id":123} ``` Summing up, this PR: - removes explicit event loop exit — event loop exits once there are no active or pending events - changes the moment the listening sockets are removed — explained above - sends header `Connection: close` on active requests when shutdown was requested which is relevant when it's a persistent connection (default in HTTP 1.1) — libevent is aware of this header and closes the connection gracefully - removes event loop explicit break after 2 seconds timeout Tree-SHA512: 4dac1e86abe388697c1e2dedbf31fb36a394cfafe5e64eadbf6ed01d829542785a8c3b91d1ab680d3f03f912d14fc87176428041141441d25dcb6c98a1e069d8

793667a Improve shutdown process (João Barbosa) Pull request description: Improve the shutdown time by not having to wait up to 2 seconds. Here is a comparison running `wallet.py` function tests before this PR: ``` 2017-08-08 03:25:20.881000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testq_ramjjr 2017-08-08 03:25:23.853000 TestFramework (INFO): Mining blocks... 2017-08-08 03:25:24.132000 TestFramework (INFO): test getmemoryinfo 2017-08-08 03:25:24.559000 TestFramework (INFO): test gettxout 2017-08-08 03:25:59.858000 TestFramework (INFO): check -rescan 2017-08-08 03:26:07.735000 TestFramework (INFO): check -reindex 2017-08-08 03:26:15.751000 TestFramework (INFO): check -zapwallettxes=1 2017-08-08 03:26:24.105000 TestFramework (INFO): check -zapwallettxes=2 2017-08-08 03:26:36.694000 TestFramework (INFO): Stopping nodes 2017-08-08 03:26:43.599000 TestFramework (INFO): Cleaning up 2017-08-08 03:26:43.612000 TestFramework (INFO): Tests successful ``` After: ``` 2017-08-08 03:24:04.319000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testoqeyi50_ 2017-08-08 03:24:07.035000 TestFramework (INFO): Mining blocks... 2017-08-08 03:24:07.317000 TestFramework (INFO): test getmemoryinfo 2017-08-08 03:24:07.763000 TestFramework (INFO): test gettxout 2017-08-08 03:24:25.715000 TestFramework (INFO): check -rescan 2017-08-08 03:24:27.792000 TestFramework (INFO): check -reindex 2017-08-08 03:24:29.797000 TestFramework (INFO): check -zapwallettxes=1 2017-08-08 03:24:32.207000 TestFramework (INFO): check -zapwallettxes=2 2017-08-08 03:24:36.812000 TestFramework (INFO): Stopping nodes 2017-08-08 03:24:37.915000 TestFramework (INFO): Cleaning up 2017-08-08 03:24:37.927000 TestFramework (INFO): Tests successful ``` This largely improves the time spent in Travis (under evaluation). Tree-SHA512: 023012fb3f8a380addf5995a4bf865862fed712cdd1a648d82a710e6566bc3bd34b6c49f9f06d6cc6bd81ca859da50d30d7f786c816e702549ab642e3476426f

28479f9 qa: Test bitcond shutdown (João Barbosa) 8d3f46e http: Remove timeout to exit event loop (João Barbosa) e98a9ee http: Remove unnecessary event_base_loopexit call (João Barbosa) 6b13580 http: Unlisten sockets after all workers quit (João Barbosa) 18e9685 http: Send "Connection: close" header if shutdown is requested (João Barbosa) 02e1e4e rpc: Add wait argument to stop (João Barbosa) Pull request description: Fixes bitcoin#11777. Reverts bitcoin#11006. Replaces bitcoin#13501. With this change the HTTP server will exit gracefully, meaning that all requests will finish processing and sending the response, even if this means to wait more than 2 seconds (current time allowed to exit the event loop). Another small change is that connections are accepted even when the server is stopping, but HTTP requests are rejected. This can be improved later, especially if chunked replies are implemented. Briefly, before this PR, this is the order or events when a request arrives (RPC `stop`): 1. `bufferevent_disable(..., EV_READ)` 2. `StartShutdown()` 3. `evhttp_del_accept_socket(...)` 4. `ThreadHTTP` terminates (event loop exits) because there are no active or pending events thanks to 1. and 3. 5. client doesn't get the response thanks to 4. This can be verified by applying ```diff // Event loop will exit after current HTTP requests have been handled, so // this reply will get back to the client. StartShutdown(); + MilliSleep(2000); return "Bitcoin server stopping"; } ``` and checking the log output: ``` Received a POST request for / from 127.0.0.1:62443 ThreadRPCServer method=stop user=__cookie__ Interrupting HTTP server ** Exited http event loop Interrupting HTTP RPC server Interrupting RPC tor: Thread interrupt Shutdown: In progress... torcontrol thread exit Stopping HTTP RPC server addcon thread exit opencon thread exit Unregistering HTTP handler for / (exactmatch 1) Unregistering HTTP handler for /wallet/ (exactmatch 0) Stopping RPC RPC stopped. Stopping HTTP server Waiting for HTTP worker threads to exit msghand thread exit net thread exit ... sleep 2 seconds ... Waiting for HTTP event thread to exit Stopped HTTP server ``` For this reason point 3. is moved right after all HTTP workers quit. In that moment HTTP replies are queued in the event loop which keeps spinning util all connections are closed. In order to trigger the server side close with keep alive connections (implicit in HTTP/1.1) the header `Connection: close` is sent if shutdown was requested. This can be tested by ``` bitcoind -regtest nc localhost 18443 POST / HTTP/1.1 Authorization: Basic ... Content-Type: application/json Content-Length: 44 {"jsonrpc": "2.0","method":"stop","id":123} ``` Summing up, this PR: - removes explicit event loop exit — event loop exits once there are no active or pending events - changes the moment the listening sockets are removed — explained above - sends header `Connection: close` on active requests when shutdown was requested which is relevant when it's a persistent connection (default in HTTP 1.1) — libevent is aware of this header and closes the connection gracefully - removes event loop explicit break after 2 seconds timeout Tree-SHA512: 4dac1e86abe388697c1e2dedbf31fb36a394cfafe5e64eadbf6ed01d829542785a8c3b91d1ab680d3f03f912d14fc87176428041141441d25dcb6c98a1e069d8

793667a Improve shutdown process (João Barbosa) Pull request description: Improve the shutdown time by not having to wait up to 2 seconds. Here is a comparison running `wallet.py` function tests before this PR: ``` 2017-08-08 03:25:20.881000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testq_ramjjr 2017-08-08 03:25:23.853000 TestFramework (INFO): Mining blocks... 2017-08-08 03:25:24.132000 TestFramework (INFO): test getmemoryinfo 2017-08-08 03:25:24.559000 TestFramework (INFO): test gettxout 2017-08-08 03:25:59.858000 TestFramework (INFO): check -rescan 2017-08-08 03:26:07.735000 TestFramework (INFO): check -reindex 2017-08-08 03:26:15.751000 TestFramework (INFO): check -zapwallettxes=1 2017-08-08 03:26:24.105000 TestFramework (INFO): check -zapwallettxes=2 2017-08-08 03:26:36.694000 TestFramework (INFO): Stopping nodes 2017-08-08 03:26:43.599000 TestFramework (INFO): Cleaning up 2017-08-08 03:26:43.612000 TestFramework (INFO): Tests successful ``` After: ``` 2017-08-08 03:24:04.319000 TestFramework (INFO): Initializing test directory /var/folders/1v/8_69hby54nj2k3n6fywt44x80000gn/T/testoqeyi50_ 2017-08-08 03:24:07.035000 TestFramework (INFO): Mining blocks... 2017-08-08 03:24:07.317000 TestFramework (INFO): test getmemoryinfo 2017-08-08 03:24:07.763000 TestFramework (INFO): test gettxout 2017-08-08 03:24:25.715000 TestFramework (INFO): check -rescan 2017-08-08 03:24:27.792000 TestFramework (INFO): check -reindex 2017-08-08 03:24:29.797000 TestFramework (INFO): check -zapwallettxes=1 2017-08-08 03:24:32.207000 TestFramework (INFO): check -zapwallettxes=2 2017-08-08 03:24:36.812000 TestFramework (INFO): Stopping nodes 2017-08-08 03:24:37.915000 TestFramework (INFO): Cleaning up 2017-08-08 03:24:37.927000 TestFramework (INFO): Tests successful ``` This largely improves the time spent in Travis (under evaluation). Tree-SHA512: 023012fb3f8a380addf5995a4bf865862fed712cdd1a648d82a710e6566bc3bd34b6c49f9f06d6cc6bd81ca859da50d30d7f786c816e702549ab642e3476426f

28479f9 qa: Test bitcond shutdown (João Barbosa) 8d3f46e http: Remove timeout to exit event loop (João Barbosa) e98a9ee http: Remove unnecessary event_base_loopexit call (João Barbosa) 6b13580 http: Unlisten sockets after all workers quit (João Barbosa) 18e9685 http: Send "Connection: close" header if shutdown is requested (João Barbosa) 02e1e4e rpc: Add wait argument to stop (João Barbosa) Pull request description: Fixes bitcoin#11777. Reverts bitcoin#11006. Replaces bitcoin#13501. With this change the HTTP server will exit gracefully, meaning that all requests will finish processing and sending the response, even if this means to wait more than 2 seconds (current time allowed to exit the event loop). Another small change is that connections are accepted even when the server is stopping, but HTTP requests are rejected. This can be improved later, especially if chunked replies are implemented. Briefly, before this PR, this is the order or events when a request arrives (RPC `stop`): 1. `bufferevent_disable(..., EV_READ)` 2. `StartShutdown()` 3. `evhttp_del_accept_socket(...)` 4. `ThreadHTTP` terminates (event loop exits) because there are no active or pending events thanks to 1. and 3. 5. client doesn't get the response thanks to 4. This can be verified by applying ```diff // Event loop will exit after current HTTP requests have been handled, so // this reply will get back to the client. StartShutdown(); + MilliSleep(2000); return "Bitcoin server stopping"; } ``` and checking the log output: ``` Received a POST request for / from 127.0.0.1:62443 ThreadRPCServer method=stop user=__cookie__ Interrupting HTTP server ** Exited http event loop Interrupting HTTP RPC server Interrupting RPC tor: Thread interrupt Shutdown: In progress... torcontrol thread exit Stopping HTTP RPC server addcon thread exit opencon thread exit Unregistering HTTP handler for / (exactmatch 1) Unregistering HTTP handler for /wallet/ (exactmatch 0) Stopping RPC RPC stopped. Stopping HTTP server Waiting for HTTP worker threads to exit msghand thread exit net thread exit ... sleep 2 seconds ... Waiting for HTTP event thread to exit Stopped HTTP server ``` For this reason point 3. is moved right after all HTTP workers quit. In that moment HTTP replies are queued in the event loop which keeps spinning util all connections are closed. In order to trigger the server side close with keep alive connections (implicit in HTTP/1.1) the header `Connection: close` is sent if shutdown was requested. This can be tested by ``` bitcoind -regtest nc localhost 18443 POST / HTTP/1.1 Authorization: Basic ... Content-Type: application/json Content-Length: 44 {"jsonrpc": "2.0","method":"stop","id":123} ``` Summing up, this PR: - removes explicit event loop exit — event loop exits once there are no active or pending events - changes the moment the listening sockets are removed — explained above - sends header `Connection: close` on active requests when shutdown was requested which is relevant when it's a persistent connection (default in HTTP 1.1) — libevent is aware of this header and closes the connection gracefully - removes event loop explicit break after 2 seconds timeout Tree-SHA512: 4dac1e86abe388697c1e2dedbf31fb36a394cfafe5e64eadbf6ed01d829542785a8c3b91d1ab680d3f03f912d14fc87176428041141441d25dcb6c98a1e069d8

28479f9 qa: Test bitcond shutdown (João Barbosa) 8d3f46e http: Remove timeout to exit event loop (João Barbosa) e98a9ee http: Remove unnecessary event_base_loopexit call (João Barbosa) 6b13580 http: Unlisten sockets after all workers quit (João Barbosa) 18e9685 http: Send "Connection: close" header if shutdown is requested (João Barbosa) 02e1e4e rpc: Add wait argument to stop (João Barbosa) Pull request description: Fixes bitcoin#11777. Reverts bitcoin#11006. Replaces bitcoin#13501. With this change the HTTP server will exit gracefully, meaning that all requests will finish processing and sending the response, even if this means to wait more than 2 seconds (current time allowed to exit the event loop). Another small change is that connections are accepted even when the server is stopping, but HTTP requests are rejected. This can be improved later, especially if chunked replies are implemented. Briefly, before this PR, this is the order or events when a request arrives (RPC `stop`): 1. `bufferevent_disable(..., EV_READ)` 2. `StartShutdown()` 3. `evhttp_del_accept_socket(...)` 4. `ThreadHTTP` terminates (event loop exits) because there are no active or pending events thanks to 1. and 3. 5. client doesn't get the response thanks to 4. This can be verified by applying ```diff // Event loop will exit after current HTTP requests have been handled, so // this reply will get back to the client. StartShutdown(); + MilliSleep(2000); return "Bitcoin server stopping"; } ``` and checking the log output: ``` Received a POST request for / from 127.0.0.1:62443 ThreadRPCServer method=stop user=__cookie__ Interrupting HTTP server ** Exited http event loop Interrupting HTTP RPC server Interrupting RPC tor: Thread interrupt Shutdown: In progress... torcontrol thread exit Stopping HTTP RPC server addcon thread exit opencon thread exit Unregistering HTTP handler for / (exactmatch 1) Unregistering HTTP handler for /wallet/ (exactmatch 0) Stopping RPC RPC stopped. Stopping HTTP server Waiting for HTTP worker threads to exit msghand thread exit net thread exit ... sleep 2 seconds ... Waiting for HTTP event thread to exit Stopped HTTP server ``` For this reason point 3. is moved right after all HTTP workers quit. In that moment HTTP replies are queued in the event loop which keeps spinning util all connections are closed. In order to trigger the server side close with keep alive connections (implicit in HTTP/1.1) the header `Connection: close` is sent if shutdown was requested. This can be tested by ``` bitcoind -regtest nc localhost 18443 POST / HTTP/1.1 Authorization: Basic ... Content-Type: application/json Content-Length: 44 {"jsonrpc": "2.0","method":"stop","id":123} ``` Summing up, this PR: - removes explicit event loop exit — event loop exits once there are no active or pending events - changes the moment the listening sockets are removed — explained above - sends header `Connection: close` on active requests when shutdown was requested which is relevant when it's a persistent connection (default in HTTP 1.1) — libevent is aware of this header and closes the connection gracefully - removes event loop explicit break after 2 seconds timeout Tree-SHA512: 4dac1e86abe388697c1e2dedbf31fb36a394cfafe5e64eadbf6ed01d829542785a8c3b91d1ab680d3f03f912d14fc87176428041141441d25dcb6c98a1e069d8 # Conflicts: # src/rpc/client.cpp # src/rpc/server.cpp # test/functional/feature_shutdown.py # test/functional/test_framework/test_framework.py

promag force-pushed the 201708-fast-shutdown branch 2 times, most recently from 00c4678 to 2195bb0 Compare August 8, 2017 03:33

promag changed the title ~~WIP: Improve shutdown process~~ Improve shutdown process Aug 8, 2017

laanwj reviewed Aug 8, 2017

View reviewed changes

laanwj added the RPC/REST/ZMQ label Aug 8, 2017

promag force-pushed the 201708-fast-shutdown branch from 2195bb0 to 6c8e93d Compare August 8, 2017 12:30

promag force-pushed the 201708-fast-shutdown branch from 6c8e93d to f0cbc4b Compare August 12, 2017 03:13

Improve shutdown process

793667a

promag force-pushed the 201708-fast-shutdown branch from f0cbc4b to 793667a Compare August 12, 2017 03:42

promag mentioned this pull request Sep 28, 2017

[tests] add functional test for mempoolreplacement command line arg #11407

Merged

laanwj merged commit 793667a into bitcoin:master Oct 18, 2017

jasondavies mentioned this pull request Oct 23, 2017

Fix various thread assertion errors caused during shutdown. zcash/zcash#2555

Merged

sickpig mentioned this pull request Mar 12, 2018

HTTP servers Core ports BitcoinUnlimited/BitcoinUnlimited#1005

Merged

laanwj mentioned this pull request May 10, 2018

Use a semaphore or pipe for shutdown notification (skeees, laanwj) #13211

Closed

ken2812221 mentioned this pull request Jun 17, 2018

Ensure that http event loop is empty before the loop exit #13485

Closed

ryanofsky mentioned this pull request Nov 2, 2018

~~Correctly~~ terminate HTTP server #13501

Closed

promag mentioned this pull request Nov 7, 2018

http: Fix HTTP server shutdown #14670

Merged

promag mentioned this pull request Feb 7, 2019

http: Release server before waiting for event base loop exit #15363

Closed

bitcoin locked as resolved and limited conversation to collaborators Sep 8, 2021

Improve shutdown process #11006

Improve shutdown process #11006

Uh oh!

Conversation

promag commented Aug 8, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

promag commented Aug 8, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

promag commented Aug 8, 2017

Uh oh!

jnewbery commented Aug 8, 2017

Uh oh!

laanwj Aug 8, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

laanwj Aug 8, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

promag Aug 8, 2017

Choose a reason for hiding this comment

Uh oh!

laanwj Aug 8, 2017

Choose a reason for hiding this comment

Uh oh!

laanwj commented Aug 8, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

promag commented Aug 8, 2017

Uh oh!

promag commented Aug 8, 2017

Uh oh!

laanwj commented Aug 8, 2017

Uh oh!

promag commented Aug 8, 2017

Uh oh!

promag commented Aug 9, 2017

Uh oh!

laanwj commented Aug 9, 2017

Uh oh!

jnewbery commented Aug 9, 2017

Uh oh!

jnewbery commented Aug 9, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

promag commented Aug 9, 2017

Uh oh!

promag commented Aug 9, 2017

Uh oh!

jnewbery commented Aug 9, 2017

Uh oh!

promag commented Aug 12, 2017

Uh oh!

laanwj commented Oct 18, 2017

Uh oh!

Uh oh!

promag commented Aug 8, 2017 •

edited

Loading

promag commented Aug 8, 2017 •

edited

Loading

laanwj Aug 8, 2017 •

edited

Loading

laanwj Aug 8, 2017 •

edited

Loading

laanwj commented Aug 8, 2017 •

edited

Loading

jnewbery commented Aug 9, 2017 •

edited

Loading