Prevent 504 response caching #2166
Description
Description
We're using ethers in a server-side worker that polls information from a contract every few minutes. From time to time Nginx that acts as a reverse proxy for the node fails to reach the node and returns a 504 Gateway Timeout response. Ethers (or maybe nodejs' http[s] client) caches the response forever and upon retrying will get the same response, even if the node came back online and Nginx would be able to fulfill the request without error. Even a few days later the error would show the nginx response from a few days ago when it was initially sent, without actually resending the request to Nginx.
Here's the stack trace that we get:
15|pinner | 2021-10-12 09:31:43 +00:00: Error: bad response (status=504, headers={"date":"Thu, 30 Sep 2021 20:01:43 GMT","content-type":"text/html","content-length":"176","connection":"close","server":"Nginx"}, body="<html>\r\n<head><title>504 Gateway Time-out</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>504 Gateway Time-out</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n", requestBody="{\"method\":\"eth_blockNumber\",\"params\":[],\"id\":23379,\"jsonrpc\":\"2.0\"}", requestMethod="POST", url="http://erigon.example.com", code=SERVER_ERROR, version=web/5.0.9)
15|pinner | 2021-10-12 09:31:43 +00:00: at Logger.makeError (/home/ubuntu/pinner/node_modules/@ethersproject/logger/lib/index.js:179:21)
15|pinner | 2021-10-12 09:31:43 +00:00: at Logger.throwError (/home/ubuntu/pinner/node_modules/@ethersproject/logger/lib/index.js:188:20)
15|pinner | 2021-10-12 09:31:43 +00:00: at /home/ubuntu/pinner/node_modules/@ethersproject/web/lib/index.js:227:36
15|pinner | 2021-10-12 09:31:43 +00:00: at step (/home/ubuntu/pinner/node_modules/@ethersproject/web/lib/index.js:33:23)
15|pinner | 2021-10-12 09:31:43 +00:00: at Object.next (/home/ubuntu/pinner/node_modules/@ethersproject/web/lib/index.js:14:53)
15|pinner | 2021-10-12 09:31:43 +00:00: at fulfilled (/home/ubuntu/pinner/node_modules/@ethersproject/web/lib/index.js:5:58)
15|pinner | 2021-10-12 09:31:43 +00:00: at runMicrotasks (<anonymous>)
15|pinner | 2021-10-12 09:31:43 +00:00: at processTicksAndRejections (internal/process/task_queues.js:97:5) {
15|pinner | 2021-10-12 09:31:43 +00:00: reason: 'bad response',
15|pinner | 2021-10-12 09:31:43 +00:00: code: 'SERVER_ERROR',
15|pinner | 2021-10-12 09:31:43 +00:00: status: 504,
15|pinner | 2021-10-12 09:31:43 +00:00: headers: {
15|pinner | 2021-10-12 09:31:43 +00:00: date: 'Thu, 30 Sep 2021 20:01:43 GMT',
15|pinner | 2021-10-12 09:31:43 +00:00: 'content-type': 'text/html',
15|pinner | 2021-10-12 09:31:43 +00:00: 'content-length': '176',
15|pinner | 2021-10-12 09:31:43 +00:00: connection: 'close',
15|pinner | 2021-10-12 09:31:43 +00:00: server: 'Nginx'
15|pinner | 2021-10-12 09:31:43 +00:00: },
15|pinner | 2021-10-12 09:31:43 +00:00: body: '<html>\r\n' +
15|pinner | 2021-10-12 09:31:43 +00:00: '<head><title>504 Gateway Time-out</title></head>\r\n' +
15|pinner | 2021-10-12 09:31:43 +00:00: '<body bgcolor="white">\r\n' +
15|pinner | 2021-10-12 09:31:43 +00:00: '<center><h1>504 Gateway Time-out</h1></center>\r\n' +
15|pinner | 2021-10-12 09:31:43 +00:00: '<hr><center>nginx</center>\r\n' +
15|pinner | 2021-10-12 09:31:43 +00:00: '</body>\r\n' +
15|pinner | 2021-10-12 09:31:43 +00:00: '</html>\r\n',
15|pinner | 2021-10-12 09:31:43 +00:00: requestBody: '{"method":"eth_blockNumber","params":[],"id":23379,"jsonrpc":"2.0"}',
15|pinner | 2021-10-12 09:31:43 +00:00: requestMethod: 'POST',
15|pinner | 2021-10-12 09:31:43 +00:00: url: 'http://erigon.example.com'
15|pinner | 2021-10-12 09:31:43 +00:00: }
Notice that the timestamp when this was logged was on 12th of October but the date header returned by nginx is 30th of September. I've also inspected the logs and it confirms that the requests are not being sent to nginx.
Environment:
Node version: v12.22.1
Ethers version: 5.0.9
Node: Erigon (but most likely irrelevant).
Although the ethers version is older, the web package hasn't changed in the last year so I suppose we might hit the same issue with the latest. I've just updated the package to the latest version and I'll add a comment whenever we hit the issue again.
Potential solution
One important thing that I noticed is that the request id that's being "sent" is the same so bumping the id whenever an error is encountered should probably avoid the caching issue.