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.

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

websocket: read limit exceeded #2955

Open
qiujun8023 opened this issue May 19, 2022 · 11 comments
Open

websocket: read limit exceeded #2955

qiujun8023 opened this issue May 19, 2022 · 11 comments

Comments

@qiujun8023
Copy link

qiujun8023 commented May 19, 2022

After upgrading to 1.7.2+release.

dcrwallet cannot provide services normally, and the rpc call always return

{
    "jsonrpc": "2.0",
    "result": null,
    "error": {
        "code": -4,
        "message": "write tcp 127.0.0.1:43464->127.0.0.1:9109: write: connection reset by peer"
    },
    "id": "0"
}

After checking, it was found that the websocket connection between dcrwallet and dcrd was disconnected due to an error.

image

I checked all startup parameters and there is nowhere to fix it.

It may not be caused by the upgrade, but may be caused by the restart. After startup, dcrwallet will scan the transaction. dcrwallet currently manages around 60k addresses.

@davecgh
Copy link
Member

davecgh commented May 19, 2022

Are you able to tell which RPC it is on the wallet side?

@jrick Looks like wallet is likely sending a message that exceeds 16MiB which it shouldn't be.

@qiujun8023
Copy link
Author

Sorry, I don't know which RPC call it is, but I can be sure that it happens in the dcrwallet startup phase, and the CPU usage is 100%. At this time dcrwallet has not received external rpc request

@davecgh
Copy link
Member

davecgh commented May 19, 2022

If you run dcrd with --debuglevel RPCS=debug (or use dcrctl debuglevel RPCS=debug to set it without needing to restart dcrd), then connect the wallet, you should see some Received command <FOO> from 127.0.0.1:xxxxx debug messages that will reveal which command is causing it.

@qiujun8023
Copy link
Author

Thanks for your help, here is the log

2022-05-19 05:13:54.535 [INF] RPCS: New websocket client 127.0.0.1:43912
2022-05-19 05:13:54.536 [DBG] RPCS: Received command <getcurrentnet> from 127.0.0.1:43912
2022-05-19 05:13:54.536 [DBG] RPCS: Received command <version> from 127.0.0.1:43912
2022-05-19 05:13:54.537 [DBG] RPCS: Received command <notifyblocks> from 127.0.0.1:43912
2022-05-19 05:13:54.537 [DBG] RPCS: Received command <getrawmempool> from 127.0.0.1:43912
2022-05-19 05:13:54.537 [DBG] RPCS: Received command <notifytspend> from 127.0.0.1:43912
2022-05-19 05:13:54.538 [DBG] RPCS: Received command <getheaders> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.539 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:43912
2022-05-19 05:13:54.557 [DBG] RPCS: Received command <getheaders> from 127.0.0.1:43912
2022-05-19 05:14:54.540 [DBG] RPCS: ping received: len 0
2022-05-19 05:15:06.997 [INF] SYNC: New valid peer 51.81.186.122:9108 (outbound) (/dcrwire:1.0.0/dcrd:1.7.1/)
2022-05-19 05:15:54.551 [DBG] RPCS: ping received: len 0
2022-05-19 05:16:54.539 [DBG] RPCS: ping received: len 0
2022-05-19 05:17:23.014 [ERR] RPCS: Websocket receive error from 127.0.0.1:43912: websocket: read limit exceeded
2022-05-19 05:17:23.014 [INF] RPCS: Disconnected websocket client 127.0.0.1:43912

@davecgh
Copy link
Member

davecgh commented May 19, 2022

Thanks for posting. It looks like it's on existsaddresses from tracing the wallet code. I wouldn't think it should be hitting anywhere near 16MiB though given each address is about 40 bytes with accompanying JSON, so 60k addresses * 40 ~= 2.29 MiB.

This is going to require some digging by the wallet devs to figure out why it's sending messages over the limit for a proper fix.

However, in the mean time, if you're able to build from source on the release-v1.7 branch, the following diff will increase the read limit for (what should be) a quick and dirty workaround for now:

diff --git a/internal/rpcserver/rpcwebsocket.go b/internal/rpcserver/rpcwebsocket.go
index 121e34ea..277632be 100644
--- a/internal/rpcserver/rpcwebsocket.go
+++ b/internal/rpcserver/rpcwebsocket.go
@@ -48,7 +48,7 @@ const (

        // websocketReadLimitAuthenticated is the maximum number of bytes allowed
        // for an authenticated JSON-RPC message read from a websocket client.
-       websocketReadLimitAuthenticated = 1 << 24 // 16 MiB
+       websocketReadLimitAuthenticated = 1 << 26 // 64 MiB

        // websocketPongTimeout is the maximum amount of time attempts to respond to
        // websocket ping messages with a pong will wait before giving up.

@qiujun8023
Copy link
Author

Thank you very much.

@qiujun8023
Copy link
Author

Thank you very much, it seems to be working fine

2022-05-19 07:02:23.510 [INF] RPCS: New websocket client 127.0.0.1:44756
2022-05-19 07:02:23.511 [DBG] RPCS: Received command <getcurrentnet> from 127.0.0.1:44756
2022-05-19 07:02:23.511 [DBG] RPCS: Received command <version> from 127.0.0.1:44756
2022-05-19 07:02:23.512 [DBG] RPCS: Received command <notifyblocks> from 127.0.0.1:44756
2022-05-19 07:02:23.512 [DBG] RPCS: Received command <getrawmempool> from 127.0.0.1:44756
2022-05-19 07:02:23.512 [DBG] RPCS: Received command <notifytspend> from 127.0.0.1:44756
2022-05-19 07:02:23.513 [DBG] RPCS: Received command <getheaders> from 127.0.0.1:44756
2022-05-19 07:02:23.514 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.514 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.514 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.514 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.514 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.515 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.516 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.516 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.516 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.517 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:02:23.559 [DBG] RPCS: Received command <getheaders> from 127.0.0.1:44756
2022-05-19 07:02:36.576 [INF] SYNC: New valid peer 178.238.227.132:9108 (outbound) (/dcrwire:0.3.0/dcrd:1.4.0/)
2022-05-19 07:02:36.895 [INF] SYNC: New valid peer 104.199.112.136:9108 (outbound) (/dcrwire:1.0.0/dcrd:1.7.1/)
2022-05-19 07:03:06.570 [INF] SYNC: New valid peer 88.198.75.244:9108 (outbound) (/dcrwire:1.0.0/dcrd:1.7.2/)
2022-05-19 07:03:06.590 [INF] SYNC: New valid peer 195.49.75.206:9108 (outbound) (/dcrwire:1.0.0/dcrd:1.8.0(pre)/)
2022-05-19 07:03:06.680 [INF] SYNC: New valid peer 142.93.61.153:9108 (outbound) (/dcrwire:1.0.0/dcrd:1.7.1/)
2022-05-19 07:03:23.528 [DBG] RPCS: ping received: len 0
2022-05-19 07:03:37.515 [INF] SYNC: New valid peer 8.135.103.125:9108 (outbound) (/dcrwire:0.4.0/dcrd:1.6.0/)
2022-05-19 07:04:23.522 [DBG] RPCS: ping received: len 0
2022-05-19 07:04:27.691 [INF] SYNC: New block 00000000000000007a49425a9db346975049a2fca81616b5bdaf3e8c33aef648 (7 transactions, 12 tickets, 5 votes, 0 revocations, height 660306, interval 3m43s)
2022-05-19 07:04:27.716 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:05:23.519 [DBG] RPCS: ping received: len 0
2022-05-19 07:05:53.833 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:05:55.479 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:05:57.606 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:06:00.228 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:06:03.383 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:06:06.354 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:06:23.525 [DBG] RPCS: ping received: len 0
2022-05-19 07:07:23.561 [DBG] RPCS: ping received: len 0
2022-05-19 07:08:23.513 [DBG] RPCS: ping received: len 0
2022-05-19 07:08:56.085 [INF] SYNC: New block 00000000000000007a3e91bc285384c86495344054ad678213dfbcb1f9b8d814 (7 transactions, 1 ticket, 5 votes, 0 revocations, height 660307, interval 3m26s)
2022-05-19 07:08:56.106 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:09:23.529 [DBG] RPCS: ping received: len 0
2022-05-19 07:10:23.526 [DBG] RPCS: ping received: len 0
2022-05-19 07:11:23.524 [DBG] RPCS: ping received: len 0
2022-05-19 07:12:20.385 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:12:23.161 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:12:25.794 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:12:25.804 [DBG] RPCS: ping received: len 0
2022-05-19 07:12:30.119 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:12:33.187 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:12:35.955 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:13:23.550 [DBG] RPCS: ping received: len 0
2022-05-19 07:14:23.511 [DBG] RPCS: ping received: len 0
2022-05-19 07:15:20.298 [INF] SYNC: New block 000000000000000017ae3ad8dd3fa250b9ca619a9832692ef89a2dceb4bb46e4 (5 transactions, 8 tickets, 5 votes, 0 revocations, height 660308, interval 6m11s)
2022-05-19 07:15:20.327 [DBG] RPCS: Received command <getcfilterv2> from 127.0.0.1:44756
2022-05-19 07:15:23.516 [DBG] RPCS: ping received: len 0
2022-05-19 07:16:23.529 [DBG] RPCS: ping received: len 0
2022-05-19 07:17:23.523 [DBG] RPCS: ping received: len 0
2022-05-19 07:18:23.519 [DBG] RPCS: ping received: len 0
2022-05-19 07:18:43.199 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:18:48.287 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:18:52.463 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:18:54.600 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756
2022-05-19 07:18:56.992 [DBG] RPCS: Received command <existsaddresses> from 127.0.0.1:44756

@davecgh
Copy link
Member

davecgh commented May 19, 2022

Great, thanks for confirming. I'm glad the workaround is working for now. I'll leave this open until the wallet devs are able to address it properly.

@jrick
Copy link
Member

jrick commented May 19, 2022

Are you by chance running a very large --gaplimit option in dcrwallet? and if so, why?

@qiujun8023
Copy link
Author

Yes, what we are doing is a wallet service, we do not implement address management ourselves, but use the node's wallet service.

In order to distinguish the attribution of transactions, we assign each user an address

@jrick
Copy link
Member

jrick commented May 29, 2022

OK.. well just so are aware, even with a large gap limit, there is still the possibility that none of the addresses will be used and eventually wraparround will occur after returning too many addresses. The proper solution would be to generate address while ignoring the gap limit (use "ignore" as the gappolicy option when doing a getnewaddress).

Large gap limits are only really useful when restoring a wallet, or if you must keep a watching wallet up to date with another wallet that runs with a custom gap.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants