WS error: i/o error: Transport endpoint is not connected (os error 107); and terminate connection 1056

[jasl]

Is there an existing issue?

• I have searched the existing issues

Experiencing problems? Have you tried our Stack Exchange first?

• This is not a support question.

Description of bug

Disclaimer: I can't reproduce the problem but I get many reports from our users, including other parachain teams

The node log only showed WS error: i/o error: Transport endpoint is not connected (os error 107); and terminate connection 1056 then the client (e.g. polkadot.js, subxt) will be disconnected.

I found https://substrate.stackexchange.com/questions/3403/intermitent-errors-with-jsonrpsee-ws-error-i-o-error-transport-endpoint-is-no so looks Polkadot node also has this issue

It might not relates to max-connection args because default is large enough and usually only few (1-5) clients connect to the node

Steps to reproduce

User reports only update to our latest Docker image (based on polkadot-v0.9.24) and change nothing, then the problem occurred, downgrade can workaround.

[niklasad1]

Hey,

Is the connection accepted by the server at all?

Can you elaborate how the you run the node i.e., if it's inside a kubernetes cluster, reverse proxy or something else?
Additional logs from the node, subxt, wireshark would useful for sure.

WS error: i/o error: Transport endpoint is not connected (os error 107); and terminate connection 1056

That can occur just if the some client disconnects so I think that's it's not really the issue.
Thus, my guess is that the connection is denied and has nothing to do with the log.
I suppose we could make those logs better.

[jasl]

Hey,

Is the connection accepted by the server at all?

Can you elaborate how the you run the node i.e., if it's inside a kubernetes cluster, reverse proxy or something else? Additional logs from the node, subxt, wireshark would useful for sure.

WS error: i/o error: Transport endpoint is not connected (os error 107); and terminate connection 1056

That can occur just if the some client disconnects so I think that's it's not really the issue. Thus, my guess is that the connection is denied and has nothing to do with the log. I suppose we could make those logs better.

For our chain usage it's usually only 1 or 2 clients connect to a node (people run a node then run another service connect to it), and they can't connect to the node at all, report by our users.

Sadly, My Ops colleague and I can't reproduce

Here's another parachain team report this issue @99Kies can you share some details?

[jasl]

BTW, the SO question isn't report by me and our users, they found the link and shared to me

This is the node start command /~https://github.com/Phala-Network/khala-docker/blob/main/dockerfile.d/start_node.sh

[99Kies]

@niklasad1 Yes, we had the same problem.
relaychain network: kusama
We are trying to upgrade the client to 0.9.22
but ran into this problem:

WS error: i/o error: Transport endpoint is not connected (os error 107); and terminate connection 1954

This is our error log:

After a period of time, the process is automatically killed.

[jasl]

here's a screenshot from our user

[niklasad1]

@jasl

From the log the above it looks like that RPC node crashes because of a segfault which led to that the connections were not accepted anymore?

Have your "users" done any investigations on the segfault (that's quite concerning)?
Would be super useful to have a backtrace so we actually know what is causing the segfault.

Can you double check if this is only reproducible only on RPC nodes?

You can tell them to enable export RUST_LOG="jsonrpsee=trace" warning this is extremely noisy but I reckon that it
could help you to find which RPC call was invoked before the segfault, if it's RPC related

Would also be good to inspect RPC related prometheous metrics

[niklasad1]

@99Kies

You are saying the RPC node runs but the block production stopped after ~1 hour and then you restart the RPC node?
So it sounds like you and @jasl run into different things.

The logs you linked to is just the a connection was just closed by "client" and nothing serious what I can tell.
I don't why your block production has halted but the RPC stuff looks alright to me but I could be wrong of course.

[niklasad1]

However, if the entire connection is denied and it's possible to connect to a RPC node via your "app"

It's possible that your users may run into the host filtering/origin filter bug
That should be fixed in polkadot v0.9.25

[99Kies]

@99Kies

You are saying the RPC node runs but the block production stopped after ~1 hour and then you restart the RPC node? So it sounds like you and @jasl run into different things.

The logs you linked to is just the a connection was just closed by "client" and nothing serious what I can tell. I don't why your block production has halted but the RPC stuff looks alright to me but I could be wrong of course.

Sorry, I meant the upgraded nodes were killed, but since we have 3 collators, the block production is still normal.

[jasl]

@jasl

From the log the above it looks like that RPC node crashes because of a segfault which led to that the connections were not accepted anymore?

Have your "users" done any investigations on the segfault (that's quite concerning)? Would be super useful to have a backtrace so we actually know what is causing the segfault.

Can you double check if this is only reproducible only on RPC nodes?

You can tell them to enable export RUST_LOG="jsonrpsee=trace" warning this is extremely noisy but I reckon that it could help you to find which RPC call was invoked before the segfault, if it's RPC related

Would also be good to inspect RPC related prometheous metrics

Thank for advice! I'll asking who suffered the problem try export RUST_LOG="jsonrpsee=trace" first

[jasl]

@niklasad1 sorry for one more question, as you can see the error messages are not include chain tag, so it impossible to locate the parachain or the relaychain trigger this, could Substrate can improve this?

[jasl]

@niklasad1 finally a user willing to help me, I finally got a log contains jsonrpsee=trace

I uploaded first 100MB log to GH, and you can search terminate to quick locate the error

zhe-node.splitted00.zip

I did a rough glance, I found an interesting log

2022-08-27 14:19:48.011 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: recv 73 bytes
2022-08-27 14:19:48.011 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: recv method call=chain_getBlockHash
2022-08-27 14:19:48.011 TRACE tokio-runtime-worker jsonrpsee_ws_server::server: recv: req=Request { jsonrpc: TwoPointZero, id: Number(4), method: "chain_getBlockHash", params: Some(RawValue([8325311])) }
2022-08-27 14:19:48.011 TRACE tokio-runtime-worker jsonrpsee_types::params: [next_inner] Params JSON: "[8325311]"
2022-08-27 14:19:48.011 TRACE tokio-runtime-worker jsonrpsee_core::server::helpers: send: "{\"jsonrpc\":\"2.0\",\"result\":\"0xff93a4a903207ad45af110a3e15f8b66c903a0045f886c528c23fe7064532b08\",\"id\":4}"
2022-08-27 14:19:48.011 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: send 102 bytes
2022-08-27 14:19:48.011 TRACE tokio-runtime-worker jsonrpsee_ws_server::server: send: {"jsonrpc":"2.0","result":"0xff93a4a903207ad45af110a3e15f8b66c903a0045f886c528c23fe7064532b08","id":4}
2022-08-27 14:19:48.011 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: recv 137 bytes
2022-08-27 14:19:48.011 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: recv method call=state_getStorage
2022-08-27 14:19:48.011 TRACE tokio-runtime-worker jsonrpsee_ws_server::server: recv: req=Request { jsonrpc: TwoPointZero, id: Number(4), method: "state_getStorage", params: Some(RawValue(["0x0d715f2646c8f85767b5d2764bb2782604a74d81251e398fd8a0a4d55023bb3f",null])) }
2022-08-27 14:19:48.011 TRACE tokio-runtime-worker jsonrpsee_types::params: [next_inner] Params JSON: "[\"0x0d715f2646c8f85767b5d2764bb2782604a74d81251e398fd8a0a4d55023bb3f\",null]"
2022-08-27 14:19:48.012 TRACE tokio-runtime-worker jsonrpsee_types::params: [next_inner] Params JSON: ",null]"
2022-08-27 14:19:48.012 TRACE tokio-runtime-worker jsonrpsee_core::server::helpers: send: "{\"jsonrpc\":\"2.0\",\"result\":\"0xd4070000\",\"id\":4}"
2022-08-27 14:19:48.012 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: send 46 bytes
2022-08-27 14:19:48.012 TRACE tokio-runtime-worker jsonrpsee_ws_server::server: send: {"jsonrpc":"2.0","result":"0xd4070000","id":4}
2022-08-27 14:19:48.012 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: recv 225 bytes
2022-08-27 14:19:48.012 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: recv method call=state_getStorage
2022-08-27 14:19:48.012 TRACE tokio-runtime-worker jsonrpsee_ws_server::server: recv: req=Request { jsonrpc: TwoPointZero, id: Number(5), method: "state_getStorage", params: Some(RawValue(["0xcd710b30bd2eab0352ddcc26417aa1941b3c252fcb29d88eff4f3de5de4476c39f434b9dae0bfb8ed4070000","0xff93a4a903207ad45af110a3e15f8b66c903a0045f886c528c23fe7064532b08"])) }
2022-08-27 14:19:48.012 TRACE tokio-runtime-worker jsonrpsee_types::params: [next_inner] Params JSON: "[\"0xcd710b30bd2eab0352ddcc26417aa1941b3c252fcb29d88eff4f3de5de4476c39f434b9dae0bfb8ed4070000\",\"0xff93a4a903207ad45af110a3e15f8b66c903a0045f886c528c23fe7064532b08\"]"
2022-08-27 14:19:48.012 TRACE tokio-runtime-worker jsonrpsee_types::params: [next_inner] Params JSON: ",\"0xff93a4a903207ad45af110a3e15f8b66c903a0045f886c528c23fe7064532b08\"]"
2022-08-27 14:19:48.012 TRACE tokio-runtime-worker jsonrpsee_core::server::helpers: send: "{\"jsonrpc\":\"2.0\",\"error\":{\"code\":-32000,\"message\":\"Client error: UnknownBlock: State already discarded for BlockId::Hash(0xff93a4a903207ad45af110a3e15f8b66c903a0045f886c528c23fe7064532b08)\"},\"id\":5}"
2022-08-27 14:19:48.012 DEBUG tokio-runtime-worker jsonrpsee_ws_server::server: send 198 bytes
2022-08-27 14:19:48.012 TRACE tokio-runtime-worker jsonrpsee_ws_server::server: send: {"jsonrpc":"2.0","error":{"code":-32000,"message":"Client error: UnknownBlock: State already discarded for BlockId::Hash(0xff93a4a903207ad45af110a3e15f8b66c903a0045f886c528c23fe7064532b08)"},"id":5}
2022-08-27 14:19:48.012  WARN tokio-runtime-worker jsonrpsee_ws_server::server: WS error: i/o error: Transport endpoint is not connected (os error 107); terminate connection 6
2022-08-27 14:19:48.013  WARN tokio-runtime-worker jsonrpsee_ws_server::server: WS error: i/o error: Transport endpoint is not connected (os error 107); terminate connection 6

[jasl]

I can see the client got {"jsonrpc":"2.0","error":{"code":-32000,"message":"Client error: UnknownBlock: State already discarded for BlockId::Hash(0xff93a4a903207ad45af110a3e15f8b66c903a0045f886c528c23fe7064532b08)"},"id":5}

So if RPC returns error, the node will force disconnect the client?

[jasl]

OK, I wrap up all the things, so WS error: i/o error: Transport endpoint is not connected (os error 107); terminate connection 6 is because the client panic that not disconnect gracefully.

Sorry for wasting time.