Websockets failing after upgrade to 1.21.0

[coffeexcoin]

Description
Websocket connection is completely broken since update to 1.21.0

Steps to Reproduce

Containerized minimal repro at https://github.com/coffeexcoin/dotnet-nethermind-repro

git clone https://github.com/coffeexcoin/dotnet-nethermind-repro
cd dotnet-nethermind-repro
docker build . -t repro
docker run -e WS_URL=ws://[your_node_ip:port] --network=bridge repro:latest

Actual behavior
Connection dies immediately or within one block

info: default[0]
      Connecting to ws://192.168.3.2:8545
fail: default[0]
      Error in subscription
      Nethereum.JsonRpc.Client.RpcResponseException: Client connection error
fail: default[0]
      Error in subscription
      Nethereum.JsonRpc.Client.RpcResponseException: Client connection error
fail: default[0]
      RPC Exception, RPC Request: RPC Response: 
      Newtonsoft.Json.JsonReaderException: After parsing a value an unexpected character was encountered: j. Path 'params.result.transactions[37]', line 1, position 4098.
         at Newtonsoft.Json.JsonTextReader.ParsePostValue(Boolean ignoreComments)
         at Newtonsoft.Json.JsonTextReader.Read()
         at Newtonsoft.Json.JsonWriter.WriteToken(JsonReader reader, Boolean writeChildren, Boolean writeDateConstructorAsDate, Boolean writeComments)
         at Newtonsoft.Json.Linq.JTokenWriter.WriteToken(JsonReader reader, Boolean writeChildren, Boolean writeDateConstructorAsDate, Boolean writeComments)
         at Newtonsoft.Json.JsonWriter.WriteToken(JsonReader reader, Boolean writeChildren)
         at Newtonsoft.Json.JsonWriter.WriteToken(JsonReader reader)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateJToken(JsonReader reader, JsonContract contract)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.SetPropertyValue(JsonProperty property, JsonConverter propertyConverter, JsonContainerContract containerContract, JsonProperty containerProperty, JsonReader reader, Object target)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.PopulateObject(Object newObject, JsonReader reader, JsonObjectContract contract, JsonProperty member, String id)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateObject(JsonReader reader, Type objectType, JsonContract contract, JsonProperty member, JsonContainerContract containerContract, JsonProperty containerMember, Object existingValue)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.SetPropertyValue(JsonProperty property, JsonConverter propertyConverter, JsonContainerContract containerContract, JsonProperty containerProperty, JsonReader reader, Object target)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.PopulateObject(Object newObject, JsonReader reader, JsonObjectContract contract, JsonProperty member, String id)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateObject(JsonReader reader, Type objectType, JsonContract contract, JsonProperty member, JsonContainerContract containerContract, JsonProperty containerMember, Object existingValue)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.Deserialize(JsonReader reader, Type objectType, Boolean checkAdditionalContent)
         at Newtonsoft.Json.JsonSerializer.DeserializeInternal(JsonReader reader, Type objectType)
         at Newtonsoft.Json.JsonSerializer.Deserialize(JsonReader reader, Type objectType)
         at Newtonsoft.Json.JsonSerializer.Deserialize[T](JsonReader reader)
         at Nethereum.JsonRpc.WebSocketStreamingClient.StreamingWebSocketClient.HandleIncomingMessagesAsync()

Expected behavior
Persistent websocket connection that does not fail

Screenshots
If applicable, please include screenshots to help illustrate the problem.

Desktop (please complete the following information):
Please provide the following information regarding your setup:

• Operating System: debian
• Version: 1.21.0
• Installation Method: Dappnode docker
• Consensus Client: Nimbus 23.5.1

Additional context
Issue appeared immediately after updating Dappnode images from nethermind 1.20.1 to 1.21.0.

Downgrading my node back to 1.20.1 fixes the issue immediately.

Logs

[coffeexcoin]

Ethers js repro here: https://github.com/coffeexcoin/node-nethermind-repro

Run

git clone https://github.com/coffeexcoin/node-nethermind-repro
cd node-nethermind-repro
npm i
export WS_URL=ws://[your_node_ip:port]
node .

Fails after a few blocks with one of the following two errors:

Error 1

node:events:491
      throw er; // Unhandled 'error' event
      ^

RangeError: Invalid WebSocket frame: invalid opcode 0
    at Receiver.getInfo (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/receiver.js:216:16)
    at Receiver.startLoop (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/receiver.js:136:22)
    at Receiver._write (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/receiver.js:83:10)
    at writeOrBuffer (node:internal/streams/writable:392:12)
    at _write (node:internal/streams/writable:333:10)
    at Writable.write (node:internal/streams/writable:337:10)
    at Socket.socketOnData (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/websocket.js:1231:35)
    at Socket.emit (node:events:513:28)
    at addChunk (node:internal/streams/readable:324:12)
    at readableAddChunk (node:internal/streams/readable:297:9)
Emitted 'error' event on WebSocket instance at:
    at Receiver.receiverOnError (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/websocket.js:1117:13)
    at Receiver.emit (node:events:513:28)
    at emitErrorNT (node:internal/streams/destroy:151:8)
    at emitErrorCloseNT (node:internal/streams/destroy:116:3)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
  code: 'WS_ERR_INVALID_OPCODE',
  [Symbol(status-code)]: 1002
}

Error 2

undefined:1
{"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x60ae20377bb64552beae17bc7642b641","result":{"address":"0xd29f5f02f5ffcd102faf467f2f236c601830780d","blockHash":"0x568b7829b5f322cee9621a7a059e0cbd97ed4a6a1f404415cbfde1cedf5c0112","blockNumber":"0x11729c9","data":"0x","logIndex":"0x44","removed":false,"topics":["0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef","0x0000000000000000000000003103d824e9862112bba56f8be0d029385de54554","0x000000000000000000000000ef0b56692f78a44cf4034b07f80204757c31bcc9","0x0000000000000000000000000000000000000000000000000000000000001b8f"],"transactionHash":"0xaff1500d4746cfc43497ccda4f6ace28eb5c55f2e1a00b975158219013121de9","transactionIndex":"0x1c","transactionLogIndex":"0x0"}}}{"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x60ae20377bb64552beae17bc7642b641","result":{"address":"0xd29f5f02f5ffcd102faf467f2f236c601830780d","blockHash":"0x568b7829b5f322cee9621a7a059e0cbd97ed4a6a1f404415cbfde1cedf5c0112","blockNumber":"0x11729c9","data":"0x","logIndex":"0x46","removed":false,"topics":["0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef","0x000000000000000000000000ef0b56692f78a44cf4034b07f80204757c31bcc9","0x00000000000000000000000095eab0299f6b29c231a275bd78eeecd0953a0900","0x0000000000000000000000000000000000000000000000000000000000001b8f"],"transactionHash":"0xaff1500d4746cfc43497ccda4f6ace28eb5c55f2e1a00b975158219013121de9","transactionIndex":"0x1c","transactionLogIndex":"0x2"}}}
                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                   ^

SyntaxError: Unexpected token { in JSON at position 755
    at JSON.parse (<anonymous>)
    at WebSocketProvider._processMessage (file:///Users/coffee/code/node-nethermind-repro/node_modules/ethers/lib.esm/providers/provider-socket.js:241:30)
    at WebSocketProvider.websocket.onmessage (file:///Users/coffee/code/node-nethermind-repro/node_modules/ethers/lib.esm/providers/provider-websocket.js:47:18)
    at WebSocket.onMessage (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/event-target.js:199:18)
    at WebSocket.emit (node:events:513:28)
    at Receiver.receiverOnMessage (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/websocket.js:1137:20)
    at Receiver.emit (node:events:513:28)
    at Receiver.dataMessage (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/receiver.js:528:14)
    at Receiver.getData (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/receiver.js:446:17)
    at Receiver.startLoop (/Users/coffee/code/node-nethermind-repro/node_modules/ws/lib/receiver.js:148:22)

[fselmo]

web3.py repro here

--> 238 return json.loads(msg)

File ~/.pyenv/versions/3.11.2/lib/python3.11/json/__init__.py:346, in loads(s, cls, object_hook, parse_float, parse_int, parse_constant, object_pairs_hook, **kw)
    341     s = s.decode(detect_encoding(s), 'surrogatepass')
    343 if (cls is None and object_hook is None and
    344         parse_int is None and parse_float is None and
    345         parse_constant is None and object_pairs_hook is None and not kw):
--> 346     return _default_decoder.decode(s)
    347 if cls is None:
    348     cls = JSONDecoder

File ~/.pyenv/versions/3.11.2/lib/python3.11/json/decoder.py:340, in JSONDecoder.decode(self, s, _w)
    338 end = _w(s, end).end()
    339 if end != len(s):
--> 340     raise JSONDecodeError("Extra data", s, end)
    341 return obj

JSONDecodeError: Extra data: line 1 column 1439 (char 1438)

It seems like every once in a while a subscription message comes in with two messages attached as one object. At the character where the error is it begins again with {"jsonrpc":"2.0",...}

{"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x47db02118dda47c0856c1a066e91f783","result":{"hash":"0x53af3714ff0b025006c2684ecd3e84ff4be81627c3906164e04a2e1c7de93e2e","nonce":"0x9b07","blockHash":null,"blockNumber":null,"transactionIndex":null,"from":"0xc055a530a444c1a76b654e4d171d99b4d226c990","to":"0xa278d7234327bf4a6f2cd0fc46dac3320d484e1f","value":"0x0","gasPrice":"0x3dfffcb8d7","maxPriorityFeePerGas":"0x198ac929","maxFeePerGas":"0x3dfffcb8d7","gas":"0x67d4","input":"0x009019b9ce5501dfac8403ab88e74a0fdc00000000014a78dadac93283f127cb941f3e0be6c7cc8ddab7e9627dfdd5f51bca8e28cfde58c018a555bdbf5b45f4cacb2ce915739a5d4aa416ecedbcf927533063c26689e6b7b29296bb38a7df7edccdfcb9745fff4cd9c6794a1d2da99a3f9c0efc6471fec99cf123fb47c6c70d0c2482af60234096bd6e76293e76b42555f3f38305ec7b593ad72475aed5e15aaed5f565f33f5f39e1e7b316703ebeca2552f0353956a08102cb9c87ad652ef4b4cc959e96b9d1d332f7416e19b95639926a15d93679906a5333eb94a588a249d75ea9de68fd31e6cacc15554bcfbeaae27a37f5d8bedfd2b296d76badad27ad7cdbec5222bd40782ddffc20b58dd9e613e6fed8e4ef334f7ba917ffeb657a27180c6277ab2cf69202bb83f2a2c9839e89c113e4337a59e6454f9f79d1d367def4b4cc879e96f90e72cbe8560a926d931fa99e6a669db216100000ffffb10cc30301","chainId":"0xaa36a7","type":"0x2","accessList":[],"v":"0x1","s":"0x2173ce07ec36c708a4ccae90a59421f6dd4c3e02b3bc33e08e2b769454ca24fe","r":"0xdcef62b87fa03cf6fa24f99ccf2f48ac172869cc08c16ddd78f4e8abf8b8d3c9","yParity":"0x1"}}}

{"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x47db02118dda47c0856c1a066e91f783","result":{"hash":"0xdb4117734d5a9c667d8310f48397b893d6b23374347907b168f823a1852ebf01","nonce":"0x1905a","blockHash":null,"blockNumber":null,"transactionIndex":null,"from":"0x8f23bb38f531600e5d8fddaaec41f13fab46e98c","to":"0xff00000000000000000000000000000011155420","value":"0x0","gasPrice":"0x3dfffcb8d7","maxPriorityFeePerGas":"0x198ac929","maxFeePerGas":"0x3dfffcb8d7","gas":"0x9658","input":"0x0091ef0eeea4d1e47528093a194ce6b41200000000043678da8cd1fb379b0703c0f1861445a97b5189f74551a608a16ed32d13ead6d6ce581bd311cca56ae554dc2a244f555193a6254404b56aa7682a1a4eac514626d16aa8ba36da89ba46b498ba343bce9efdfefc039f73bee7cb09deb719c0149995b21e1bc7394bfb2877d45d740aec5d92553c7bd6c472e27999737db01e09c3f7672af496c73e1a2eb189aaf18c7d78568a38dd99754e4c0d8bf271aabd0a2cdf5c2547db316678ff820acd8215d79ded7cd82d65d2c4441c0f51abcc463aba199dfc986a27c4138490c15910f432500d42034a4746262fdc6d5e819fb6c2690fc6bb4f718e37276918c66d379030fc00a62e7ea53d46ed76e7159e1b8a37fa4d79b7c5c09ba553934181faaf0f4a46fc57f6c03910d4d426c9febf2ecc34c5fd8ace285b14b94c38886a23b0558758492df4b0041264700104114d6e336138fd01fc143cd4c3614500c7d2d8ccf0e564c4edff5954e576c920834b2078ae0d97441aa0104336da22c7c4f2c4f01ae76754468f0e35a0cef8e2e4c5779041290876dc1973d6ba979a2d514cb35ecc556c9f494eebcf534efc9dabd4e9ca9284b6420665200804974f1b551fd04ea9db9264eddebd4f7d397fef9727d702e83fbc3229a6597b43063f80e09c39ba0cadd6b8a9e76d36fc60c416bf3f8da158e3e998138aeaab1c1513f72e0732fffc3ec281ca86d97e00b655c23a4fa07d4d012f59607d2446ed8bf1922cc7f43d700d04ad367e434bf27a05dd0fa49e3fce45b5d7bec7ee2ba47dad4a2e6ab876e9b959366470030423058ed24f85a17ef3066f894eeda890413d2fc28dd62f33d7f9d23391e14918c8e02608ee167e34df982aca50d038b8b148ddc9f1d585612d5d50ee6352ba2dadf5590964700b047fea28b149e74c13b13a42b8af264cd8de9ded5c7904353e34ab795dd451e00719dc01c1ebd4c041a6cf23caf4b279fee198939c9d4c261df5a60f18c5bac7fabbf19c20839fff4b6676859c32eb0774615a233e017c790dedc0c35506b259b181755e5611049030fc20a6757af16a5eebbc72ddb1e2cbfd83bd2686b6f67674b1c052445d62b3867f562447db55ef03c1e3e387c80906f2c29780da30977e3fb7623f7b57df72aa3eff069dcda091d1904105105c5db27847c1c333f047f96343552fd681b5d1bf1915b8d285cbbd3d5704041fc8201c048b52a235e2dba8b5e96fbd915d316a657d5af6dfda6e11221800e5d3cc4d6e2964500904858fa529672d87bf4bf1eadc41a5bed0c478bfb6765c1623db12399bcd8d082464500504ede5c712ae7ee5e7155b07231373a875d5f972d8ab49e32c96b7b8c83d02b800195405414681eb1fe573279a1a8d01c4bc67cbd324426549fcf45fb76c66168466f6461412861fcccc781fd8489d1555b509d471b948b726712c1d2e2161fbf81e2d26898069d11ea80e8267e22a47e1fa9ccf470d4db94f820835872f5919ae8f5b719f6fc53df5e00ef543063578ff040000ffff56247d4d01","chainId":"0xaa36a7","type":"0x2","accessList":[],"v":"0x1","s":"0x5d5941176cc1d4324d34755c091dac3725a460289b8ab2afadd720bcbb75ea68","r":"0x9ebf1f98d4475487cb71692ddb274a7bf0d0630e1f536e58315f5848fd21646d","yParity":"0x1"}}}

I've spaced them out above but these two messages came in as one and so are unable to be parsed by native json libraries.

[emlautarom1]

Hello, thanks for reporting this issue. Could you please share your Nethermind config (CLI flags/ENV)?

[coffeexcoin]

I am using the DAppNode image (https://github.com/dappnode/DAppNodePackage-nethermind)

Their runtime flags are:

exec /nethermind/nethermind \
  --JsonRpc.Enabled=true \
  --JsonRpc.JwtSecretFile=${JWT_PATH} \
  --Init.BaseDbPath=/data \
  --HealthChecks.Enabled true \
  --Init.LogDirectory=/data/logs \
  $EXTRA_OPTS

I do not have anything set for EXTRA_OPTS.

The following additional ENV variables are set by dappnode:

[emlautarom1]

I'm currently trying to reproduce the issue with the JS app you shared (https://github.com/coffeexcoin/node-nethermind-repro) but I'm not getting any messages at all.

Could you please elaborate on the steps to trigger this issue?

[fselmo]

Here is a reproducible example in python with web3.py v6.11.1

>>> import asyncio
>>> from web3 import AsyncWeb3
>>> from web3.providers import WebsocketProviderV2

>>> async def pending_transactions():
...     async with AsyncWeb3.persistent_websocket(
...         WebsocketProviderV2(f"ws://127.0.0.1:8546")  # Nethermind and Lighthouse running Sepolia and synced 
...     ) as w3:
...         # subscribe to new pending transactions
...         subscription_id = await w3.eth.subscribe("newPendingTransactions", True)
...
...         async for response in w3.ws.listen_to_websocket():
...             print(f"{response}\n")
...             # each response prints here

>>> asyncio.run(pending_transactions())

I was running Sepolia network with Nethermind + Lighthouse combo locally and running into these issues every ~3 min or so. After downgrading Nethermind to v1.20.4 the issues went away, all other things were kept the same.

[emlautarom1]

Thanks for the example. Does this issue show up with other methods like newHeads, logs or syncing? (https://docs.nethermind.io/nethermind/ethereum-client/json-rpc/subscribe).

[fselmo]

Does this issue show up with other methods like newHeads, logs or syncing?

I'm not sure as I have downgraded to 1.20.4 and things are running smoothly. But subscribing to those via web3.py to test against would just be a matter of changing this line:

subscription_id = await w3.eth.subscribe("newPendingTransactions", True)

to

# newHeads
subscription_id = await w3.eth.subscribe("newHeads")

# or, logs:
subscription_id = await w3.eth.subscribe("logs", {"fromBlock": "latest", "toBlock": "latest", "address": "0xb7705ae4c6f81b66cdb323c65f4e8133690fc099"})

Depending on your logs filter, you could get many results or not that many but newHeads might take quite a while to see any error if it does happen since they are slow to come by. newPendingTransactions sends many messages so it seems it's way easier to test against and it still takes about ~3 minutes or so to see an error / double message, on average.

[emlautarom1]

Thank you for your help. We were able to reproduce the issue and a fix is available on #6210.