bitcoind is processing 16 RPC requests, attempting to submit another request using bitcoin-cli produces this less-than-helpful error message: error: couldn't parse reply from server. This PR changes the error to: error: server response: Work queue depth exceeded.
To reproduce the problem, start the client: bitcoind -rpcworkqueue=1. This reduces the maximum number of in-progress RPCs from 16 (DEFAULT_HTTP_WORKQUEUE) to 1. Then run:
0seq 10 | while read i;do src/bitcoin-cli getblockhash 0 >/dev/null&done
This submits this trivial RPC 10 time in the background (the & character) and usually produces one or more of the error: couldn't parse reply from server errors. If it doesn’t, try again, or increase the load to more than 10. You will see a reasonable error message in debug.log:
02020-03-12T17:32:28Z WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting
But most users wouldn’t think to look there, or wouldn’t have access.
With this PR, the error is more understandable. The failed request in this case is retryable, so maybe that should be indicated in the text, but this text (Work queue depth exceeded) comes from bitcoind, which probably shouldn’t be changed, especially since there could be other RPC clients that depend on that exact text. We could have bitcoin-cli include additional text like please try again but it doesn’t really know for certain in every case that the request is retryable.
403@@ -404,7 +404,7 @@ static UniValue CallRPC(BaseRequestHandler *rh, const std::string& strMethod, co
404 // Parse reply
405 UniValue valReply(UniValue::VSTR);
406 if (!valReply.read(response.body))
407- throw std::runtime_error("couldn't parse reply from server");
408+ throw std::runtime_error(strprintf("server response: %s", response.body));
It does seem wrong that my proposed fix retains the practice of trying to decode a non-JSON string as JSON, and depending on that to fail. Yes, perhaps this is a bug in the server – should it be returning JSON in body here rather than a plain string? But as I said at the end of the comment above, I was hesitant to change the server because I’m worried that there may be other RPC clients besides bitcoin-cli that depend on the current (plain string) response. What do you think? If the fix is better in the server, I can do that.
Just for further information, the response returned in this work queue depth exceeded is (status 500 is HTTP_INTERNAL_SERVER_ERROR):
0(gdb) f 0
1Breakpoint 1, CallRPC (rh=0x555555845e90, strMethod="getblockhash", args=std::vector of length 1, capacity 2 = {...})
2 at bitcoin-cli.cpp:406
3406 if (!valReply.read(response.body))
4(gdb) p response
5$2 = {
6 status = 500,
7 error = -1,
8 body = "Work queue depth exceeded"
9}
10(gdb)
Here’s a successful reply:
0(gdb) p response
1$6 = {
2 status = 200,
3 error = -1,
4 body = "{\"result\":\"000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f\",\"error\":null,\"id\":1}\n"
5}
Here’s the response when requesting a nonsense method:
0(gdb) p response
1$2 = {
2 status = 404,
3 error = -1,
4 body = "{\"result\":null,\"error\":{\"code\":-32601,\"message\":\"Method not found\"},\"id\":1}\n"
5}
As part of this PR, I could also systematically search for and fix any other places where body is returned as plain string (not JSON); so far I see only one:
0req->WriteReply(HTTP_BAD_METHOD, "JSONRPC server handles only POST requests")
The second commit undoes the first, and fixes the problem in the server by having it return JSON in the body of the response:
0error code: -32603
1error message:
2Work queue depth exceeded
(Here’s where that error code, RPC_INTERNAL_ERROR is defined.) It makes sense that this is similar to:
0$ src/bitcoin-cli not-a-valid-rpc
1error code: -32601
2error message:
3Method not found
4$
Ok, looks like his is actually non-trivial.
HTTP_INTERNAL_SERVER_ERROR
0$2 = {
1 status = 500,
2 error = -1,
3 body = "Work queue depth exceeded"
4}
So in this case, possibly you could detect this error code in bitcoin-cli, and print an error message instead of trying to parse as JSON. Or are there cases in which it returns 500 but the response needs to be parsed as JSON?
I must admit we’re sometimes inconsistent about whether to report errors at the HTTP layer or the JSON-RPC, so it’s very possible that your solution of changing the server to return a JSON error is the most consistent one!
(I’m not personally very worried about clients depending on a specific exact error message text, though we might want to mention it briefly in the release notes)
I must admit we’re sometimes inconsistent about whether to report errors at the HTTP layer or the JSON-RPC
I checked this and yes, we do return JSON errors with HTTP_INTERNAL_SERVER_ERROR:
0static void JSONErrorReply(HTTPRequest* req, const UniValue& objError, const UniValue& id)
1{
2 // Send error reply from json-rpc error object
3 int nStatus = HTTP_INTERNAL_SERVER_ERROR;
4 int code = find_value(objError, "code").get_int();
5
6 if (code == RPC_INVALID_REQUEST)
7 nStatus = HTTP_BAD_REQUEST;
8 else if (code == RPC_METHOD_NOT_FOUND)
9 nStatus = HTTP_NOT_FOUND;
10
11 std::string strReply = JSONRPCReply(NullUniValue, objError, id);
12
13 req->WriteHeader("Content-Type", "application/json");
14 req->WriteReply(nStatus, strReply);
15}
So we have no way to distinguish “parse this as JSON?” based on just the status code.
I think the current change of changing the server to always return JSON errors is OK. I think it’s slightly more elegant than doing “try to parse as JSON and print the raw text otherwise” in the client. But I don’t have a strong opinion.
@LarryRuane Just was noted about this PR by GH :)
If you find this approach simpler you may grab it :)
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
No conflicts as of last run.
test/functional/interface* files? Say, interface_bitcoin_cli.py (which has a lot of error response testing) or interface_rpc.py (which has a batch request test).
30+ node.cli('getrpcinfo').send_cli()
31+ except subprocess.CalledProcessError as e:
32+ if e.output != 'error: Server response: Work queue depth exceeded\n':
33+ raise AssertionError("Unexpected cli error: :{}:".format(e.output))
34+ got_exceeded_error = True
35+ break
Tested almost-ACK. Thanks for adding the test! Runs quickly, but one of the Travis jobs failed at assert got_exceeded_error so it may need to be more reliable. Some suggested changes below: add a line of logging, attempt to remove perhaps-unneeded breaks, and PEP8 suggestions from pycodestyle and black – feel free to ignore the style nits. Tested that the test fails on master and passes on this branch.
0index e0e6fc57aa..cdbed53dd6 100755
1--- a/test/functional/interface_rpc.py
2+++ b/test/functional/interface_rpc.py
3@@ -11,6 +11,7 @@ from test_framework.util import assert_equal, assert_greater_than_or_equal
4 from threading import Thread
5 import subprocess
6
7+
8 def expect_http_status(expected_http_status, expected_rpc_code,
9 fcn, *args):
10 try:
11@@ -20,7 +21,10 @@ def expect_http_status(expected_http_status, expected_rpc_code,
12 assert_equal(exc.error["code"], expected_rpc_code)
13 assert_equal(exc.http_status, expected_http_status)
14
15+
16 got_exceeded_error = False
17+
18+
19 def test_work_queue_getblock(node):
20 global got_exceeded_error
21 for _ in range(400):
22@@ -29,10 +33,9 @@ def test_work_queue_getblock(node):
23 try:
24 node.cli('getrpcinfo').send_cli()
25 except subprocess.CalledProcessError as e:
26- if e.output != 'error: Server response: Work queue depth exceeded\n':
27- raise AssertionError("Unexpected cli error: :{}:".format(e.output))
28+ assert_equal(e.output, 'error: Server response: Work queue depth exceeded\n')
29 got_exceeded_error = True
30- break
31+
32
33 class RPCInterfaceTest(BitcoinTestFramework):
34 def set_test_params(self):
35@@ -84,19 +87,18 @@ class RPCInterfaceTest(BitcoinTestFramework):
36 expect_http_status(500, -8, self.nodes[0].getblockhash, 42)
37
38 def test_work_queue_exceeded(self):
39+ self.log.info("Test work queue exceeded")
40 global got_exceeded_error
41- self.restart_node(0,['-rpcworkqueue=1'])
42+ self.restart_node(0, ['-rpcworkqueue=1'])
43 threads = []
44 for _ in range(5):
45- t = Thread(target=test_work_queue_getblock, args=(self.nodes[0], ))
46+ t = Thread(target=test_work_queue_getblock, args=(self.nodes[0],))
47 t.start()
48 threads.append(t)
49- if got_exceeded_error:
50- break
51 for t in threads:
52 t.join()
53 # This likely just means more threads are needed.
54- assert(got_exceeded_error)
55+ assert got_exceeded_error
56
57 def run_test(self):
58 self.test_getrpcinfo()
Concept ACK
Code looks good at a glance but the test fails on Travis, so I will come back for a more in-depth review when that is fixed :)
79@@ -67,10 +80,23 @@ def test_http_status_codes(self):
80 expect_http_status(404, -32601, self.nodes[0].invalidmethod)
81 expect_http_status(500, -8, self.nodes[0].getblockhash, 42)
82
83+ def test_work_queue_exceeded(self):
84+ self.log.info("Test work queue exceeded")
85+ self.restart_node(0, ['-rpcworkqueue=1'])
86+ got_exceeded_error = []
nit:
Is it worth a comment explaining that? I tend to think not.
I don’t think so, but it’s a bit awkward for the list to be named like a boolean, maybe exceeded_errors if you have to retouch ?
79@@ -67,10 +80,23 @@ def test_http_status_codes(self):
80 expect_http_status(404, -32601, self.nodes[0].invalidmethod)
81 expect_http_status(500, -8, self.nodes[0].getblockhash, 42)
82
83+ def test_work_queue_exceeded(self):
84+ self.log.info("Test work queue exceeded")
85+ self.restart_node(0, ['-rpcworkqueue=1'])
This would make CI testing more reliable:
0 self.restart_node(0, ["-rpcworkqueue=1", "-rpcthreads=1"])
79@@ -67,10 +80,23 @@ def test_http_status_codes(self):
80 expect_http_status(404, -32601, self.nodes[0].invalidmethod)
81 expect_http_status(500, -8, self.nodes[0].getblockhash, 42)
82
83+ def test_work_queue_exceeded(self):
84+ self.log.info("Test work queue exceeded")
nit: Mind rewording to make it consistent with other log messages
0 self.log.info("Testing work queue exceeded...")
ACK db0d4605b9e57230a02f8b620f93e5e4d191972c, tested on Linux Mint 20 (x86_64).
https://cirrus-ci.com/task/5913926858702848 timeout seems irrelevant (could be restarted though).
tACK 8dd5946c0b7aa8f3976b14a5de4ce84b80a9c32a
Confirmed that the test fails without the fix. Ran test multiple times and seemed stable.
mini-nit if you have to retouch: The commit message of the test commit is too general for our usual conventions.
20@@ -18,6 +21,16 @@ def expect_http_status(expected_http_status, expected_rpc_code,
21 assert_equal(exc.error["code"], expected_rpc_code)
22 assert_equal(exc.http_status, expected_http_status)
23
24+
25+def test_work_queue_getblock(node, got_exceeded_error):
queue_getblock but queues a getrpcinfo ? Maybe queue_rpc_call
ACK 8dd5946c0b7aa8f3976b14a5de4ce84b80a9c32a
Thanks for doing this, going to be helpful downstream :-) Left a few nits only if you have to retouch
268@@ -269,7 +269,7 @@ static void http_request_cb(struct evhttp_request* req, void* arg)
269 item.release(); /* if true, queue took ownership */
270 else {
271 LogPrintf("WARNING: request rejected because http work queue depth exceeded, it can be increased with the -rpcworkqueue= setting\n");
272- item->req->WriteReply(HTTP_INTERNAL_SERVER_ERROR, "Work queue depth exceeded");
273+ item->req->WriteReply(HTTP_SERVICE_UNAVAILABLE, "Work queue depth exceeded");
Does this need release notes to explain the changed http status code? Just in case a user relies on this?
Just asking, you don’t have to invalidate review. Release note can be added after merge.
doc/release-notes.md on the master branch