Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Http] [Test] Fix test failures on shutdown #2920

Merged
merged 5 commits into from
Apr 4, 2024
Merged

[Http] [Test] Fix test failures on shutdown #2920

merged 5 commits into from
Apr 4, 2024
+65 −33

Conversation

panleone
Copy link

@panleone panleone commented Mar 26, 2024 •
edited
Loading

The aim of this PR is fixing the functional test errors that we get sometimes during shutdown, for example the failure of this action https://github.com/PIVX-Project/PIVX/actions/runs/8429115630/job/23082877380

In a few words, on HTTP server shutdown, sometimes 2 seconds are not enough time to finish handling all the RPC requests.

2024-03-26T01:35:26Z HTTP event loop did not exit within allotted time, sending loopbreak

So after this point all existing RPC requests (in particular the stop() one) does not receive any answer... And this lead to functional tests failing at the end.

For more info see the discussion in each backported PR.

Backport bitcoin PRs bitcoin#11006 bitcoin#14670 bitcoin#14993 bitcoin#14413

@laanwj @panleone
Merge bitcoin#11006: Improve shutdown process
af10755 
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
@panleone panleone added this to the 6.0.0 milestone Mar 26, 2024
@panleone panleone self-assigned this Mar 26, 2024
@panleone panleone force-pushed the http_backport_bug branch from 113c865 to 2029709 Compare March 26, 2024 10:02
@panleone panleone marked this pull request as draft March 26, 2024 14:55
@panleone panleone force-pushed the http_backport_bug branch from 2029709 to af075e3 Compare March 27, 2024 09:12
@panleone panleone force-pushed the http_backport_bug branch from 6001a0a to fd7507e Compare March 27, 2024 10:55
@panleone panleone changed the title [Http] [Test] bitcoin backports [Http] [Test] Fix test failures on shutdown Mar 27, 2024
@panleone panleone force-pushed the http_backport_bug branch from fd7507e to 05c30a8 Compare March 27, 2024 11:12
@laanwj @panleone
Merge bitcoin#14670: http: Fix HTTP server shutdown
cf6cb29 
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
@panleone panleone marked this pull request as ready for review March 27, 2024 11:12
laanwj and others added 2 commits March 27, 2024 12:12
@laanwj @panleone
Merge bitcoin#14993: rpc: Fix data race (UB) in InterruptRPC()
cb65d0a 
6c10037 rpc: Fix data race (UB) in InterruptRPC() (practicalswift)

Pull request description:

  Fix data race (UB) in `InterruptRPC()`.

  Before:

  ```
  $ ./configure --with-sanitizers=thread
  $ make
  $ test/functional/test_runner.py feature_shutdown.py
  …
  SUMMARY: ThreadSanitizer: data race rpc/server.cpp:314 in InterruptRPC()
  …
  ALL                 | ✖ Failed  | 2 s (accumulated)
  ```

  After:

  ```
  $ ./configure --with-sanitizers=thread
  $ make
  $ test/functional/test_runner.py feature_shutdown.py
  …
  ALL                 | ✓ Passed  | 3 s (accumulated)
  ```

Tree-SHA512: b139ca1a0480258f8caa7730cabd7783a821d906630f51487750a6b15b7842675ed679747e1ff1bdade77d248807e9d77bae7bb88da54d1df84a179cd9b9b987
@panleone
Merge bitcoin#14413: tests: Allow closed rpc handler in assert_start_…
05c30a8 
…raises_init_error

62c304e tests: Allow closed http server in assert_start_raises_init_error (Chun Kuan Lee)

Pull request description:

  The rpc handler may be unregistered when http server haven't been closed yet. So it may be allowable to get -342 `non-JSON HTTP response with \'%i %s\' from server` (503 Service Unavailable)

  See https://ci.appveyor.com/project/DrahtBot/bitcoin/build/master.2001. It shows "Rejecting request while shutting down" between "RPC stopped" and "Stopped HTTP server"

Tree-SHA512: e1f50ab9096cf23494ccc2850c01516c4a75f112c99108759157b22fce2011682a4b88216f206702f6a56e960182c00098053ad75f13aa0eafe27046adae63da
Liquid369
Liquid369 approved these changes Apr 3, 2024
View reviewed changes
Copy link
Member

@Liquid369 Liquid369 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

tACK 05c30a8

Fuzzbawls
Fuzzbawls approved these changes Apr 4, 2024
View reviewed changes
Copy link
Collaborator

@Fuzzbawls Fuzzbawls left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK 05c30a8

@Fuzzbawls Fuzzbawls merged commit f428a74 into PIVX-Project:master Apr 4, 2024
21 checks passed
@panleone panleone deleted the http_backport_bug branch April 4, 2024 08:41
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@Liquid369 Liquid369 Liquid369 approved these changes

@Fuzzbawls Fuzzbawls Fuzzbawls approved these changes

@Duddino Duddino Awaiting requested review from Duddino

Assignees

@panleone panleone

Labels
Backport Tests
Projects
None yet
Milestone
6.0.0
Development

Successfully merging this pull request may close these issues.
4 participants
@panleone @Fuzzbawls @Liquid369 @laanwj