bitcoin-cli: print useful error if bitcoind rpc work queue exceeded #18335

If 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:

seq 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:

2020-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.

The second commit undoes the first, and fixes the problem in the server by having it return JSON in the body of the response:

error code: -32603
error message:
Work queue depth exceeded

(Here's where that error code, RPC_INTERNAL_ERROR is defined.) It makes sense that this is similar to:

$ src/bitcoin-cli not-a-valid-rpc
error code: -32601
error message:
Method not found
$ 

Ok, looks like his is actually non-trivial.

HTTP_INTERNAL_SERVER_ERROR

$2 = {
  status = 500, 
  error = -1, 
  body = "Work queue depth exceeded"
}

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:

static void JSONErrorReply(HTTPRequest* req, const UniValue& objError, const UniValue& id)
{
    // Send error reply from json-rpc error object
    int nStatus = HTTP_INTERNAL_SERVER_ERROR;
    int code = find_value(objError, "code").get_int();

    if (code == RPC_INVALID_REQUEST)
        nStatus = HTTP_BAD_REQUEST;
    else if (code == RPC_METHOD_NOT_FOUND)
        nStatus = HTTP_NOT_FOUND;

    std::string strReply = JSONRPCReply(NullUniValue, objError, id);

    req->WriteHeader("Content-Type", "application/json");
    req->WriteReply(nStatus, strReply);
}

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 :)

<!--e57a25ab6845829454e8d69fc972939a-->

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

<!--174a7506f384e20aa4161008e828411d-->

Conflicts

No conflicts as of last run.

@hebasto

If you find this approach simpler you may grab it :)

Yes, your solution is much better, thank you! I tested your fix, and cherry-picked your commit to this PR (and force-push-removed my 3 commits).

utACK 4bb892cec2375d919ae66a743e2ad29cd56ba888

Rebase (refresh)

self-ACK b5a80fa7e487c37b7ac0e3874a2fabade41b9ca8

Concept ACK. Could you please add functional tests for this in one of the 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).

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.

<details><summary>some suggested edits to the test</summary><p>

index e0e6fc57aa..cdbed53dd6 100755
--- a/test/functional/interface_rpc.py
+++ b/test/functional/interface_rpc.py
@@ -11,6 +11,7 @@ from test_framework.util import assert_equal, assert_greater_than_or_equal
 from threading import Thread
 import subprocess
 
+
 def expect_http_status(expected_http_status, expected_rpc_code,
                        fcn, *args):
     try:
@@ -20,7 +21,10 @@ def expect_http_status(expected_http_status, expected_rpc_code,
         assert_equal(exc.error["code"], expected_rpc_code)
         assert_equal(exc.http_status, expected_http_status)
 
+
 got_exceeded_error = False
+
+
 def test_work_queue_getblock(node):
     global got_exceeded_error
     for _ in range(400):
@@ -29,10 +33,9 @@ def test_work_queue_getblock(node):
         try:
             node.cli('getrpcinfo').send_cli()
         except subprocess.CalledProcessError as e:
-            if e.output != 'error: Server response: Work queue depth exceeded\n':
-                raise AssertionError("Unexpected cli error: :{}:".format(e.output))
+            assert_equal(e.output, 'error: Server response: Work queue depth exceeded\n')
             got_exceeded_error = True
-            break
+
 
 class RPCInterfaceTest(BitcoinTestFramework):
     def set_test_params(self):
@@ -84,19 +87,18 @@ class RPCInterfaceTest(BitcoinTestFramework):
         expect_http_status(500, -8, self.nodes[0].getblockhash, 42)
 
     def test_work_queue_exceeded(self):
+        self.log.info("Test work queue exceeded")
         global got_exceeded_error
-        self.restart_node(0,['-rpcworkqueue=1'])
+        self.restart_node(0, ['-rpcworkqueue=1'])
         threads = []
         for _ in range(5):
-            t = Thread(target=test_work_queue_getblock, args=(self.nodes[0], ))
+            t = Thread(target=test_work_queue_getblock, args=(self.nodes[0],))
             t.start()
             threads.append(t)
-            if got_exceeded_error:
-                break
         for t in threads:
             t.join()
         # This likely just means more threads are needed.
-        assert(got_exceeded_error)
+        assert got_exceeded_error
 
     def run_test(self):
         self.test_getrpcinfo()

</p></details>

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 :)

Addressed review suggestions, force-pushed (diff), thank you. The test will run until it succeeds (there's no longer an arbitrary loop iteration count), or CI will timeout the test (which is extremely unlikely). Starting three threads should be enough, even two works, but the test runs faster with three (greater chance of exceeded the work queue depth limit).

Thanks @LarryRuane for removing the global and the update. The tests appear to be timing out, though it's unclear.

ACK db0d4605b9e57230a02f8b620f93e5e4d191972c, tested on Linux Mint 20 (x86_64).

https://cirrus-ci.com/task/5913926858702848 timeout seems irrelevant (could be restarted though).

Travis failure seems related to #19654.

re-ACK 8dd5946c0b7aa8f3976b14a5de4ce84b80a9c32a, only suggested changes since my previous review.

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.

@luke-jr as you've incorporated this PR into Bitcoin Knots, mind refreshing your previous ACK to get things done?

utACK 8dd5946c0b7aa8f3976b14a5de4ce84b80a9c32a (no changes since previous utACK)

ACK 8dd5946c0b7aa8f3976b14a5de4ce84b80a9c32a

Thanks for doing this, going to be helpful downstream :-) Left a few nits only if you have to retouch