[BE] Connection to node is constantly being lost or turns into On Hold state

[pburykh]

Connection to node is constantly being lost. In some cases its being lost right after connection is established. In other cases it looses connection during surfing the web or downloading data.

Also it is often case when node connection turns into On Hold state during internet surfing session. In this case internet connection is disabled. In some cases reconnection is established but there are often cases when it does not happen so user needs to disconnect and reconnect to node manually.

STR

1. Connect to node
2. Go surfing internet / download some large files
3. Pay attention at node connection status during session.

Actual result: described in the description.

Environment

• Node version: network.mysterium:mobile-node:0.62.0
• OS: Android 11

Additional context Bug does not reproduce every time. Try to connect to different nodes, make internet sessions of different duration.

[Snawoot]

Reproduced this issue with exactly same provider 0x57b8109ba4590510c3804879bae03f83ceb303f4. It's pretty hard to judge what happened w/o having logs from other side, but I'll try.

Testing conditions: Windows 10 with latest desktop application (6.0.0, node 0.61.0). Connected, sending ICMP echo to some server. No heavy network activity was happening.

At some point traffic stops going:

Few seconds later, connection was dropped.

Following these events in node logs:

2021-09-02T08:57:12.306 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:351.6241ms}
2021-09-02T08:57:17.665 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:359.6733ms}
2021-09-02T08:57:22.791 DBG source/session/pingpong/factory.go:136   > Received P2P message for "p2p-payment-invoice": AgreementID:"42405017923516364420389289904908022284348344141457676389988437653795815847995" AgreementTotal:"178803706576583" TransactorFee:"0" Hashlock:"66112da99c8a176a4363abe0f6b7cdd1644e3bef112c246663b12dc7ff7b46a4" Provider:"0x57b8109ba4590510c3804879bae03f83ceb303f4" ChainID:80001
2021-09-02T08:57:22.791 DBG source/session/pingpong/invoice_payer.go:146 > Invoice received: {42405017923516364420389289904908022284348344141457676389988437653795815847995 178803706576583 0 66112da99c8a176a4363abe0f6b7cdd1644e3bef112c246663b12dc7ff7b46a4 0x57b8109ba4590510c3804879bae03f83ceb303f4 80001}
2021-09-02T08:57:22.791 DBG source/session/pingpong/price_calculator.go:51 > Calculated price 1428169749083355. Time component: 9.655920734872810196e+12, data component: 1.4185138283484834023e+15 
2021-09-02T08:57:22.791 DBG source/session/pingpong/invoice_payer.go:191 > Estimated tolerance 1.21, upper bound 1727757254851432
2021-09-02T08:57:22.791 DBG source/session/pingpong/invoice_payer.go:244 > Loaded previous state: already promised: 178957112724272
2021-09-02T08:57:22.791 DBG source/session/pingpong/invoice_payer.go:245 > Incrementing promised amount by 12748866805075
2021-09-02T08:57:22.792 DBG source/session/pingpong/exchange_messaging.go:68 > Sending P2P message to "p2p-payment-message": Promise:{ChannelID:"\x16h;a\x8f-\x8cX\x85\xd3\xec8(\rd\xefCjm\xa7" Amount:"191705979529347" Fee:"0" Hashlock:"f\x11-\xa9\x9c\x8a\x17jCc\xab\xe0\xf6\xb7\xcd\xd1dN;\xef\x11,$fc\xb1-\xc7\xff{F\xa4" ChainID:80001 Signature:"\xc4/\x81\x90\x16\x04\xa7\xd6z\xe1\xc9\x07\x91\x9f\x0e*|Oa\x0c闉\xa7ObǞ\x832\xae\xd3L\x8c\r\x01d\x8b\xd87m\xb6\x97\xbc;j\xefrR\t\xe9\x1e&\x18\xad\x86\xa2\x05K\xdfx\x98\xb9\xbf\x1c"} AgreementID:"42405017923516364420389289904908022284348344141457676389988437653795815847995" AgreementTotal:"178803706576583" Provider:"0x57b8109ba4590510c3804879bae03f83ceb303f4" Signature:"d022eee3d46af7cd3e413d476bbf1ea639afad93f30fee5e6dd5e90f287945b0426105310d5a277622394df8ce7183e3b657e0c97eba05f5948d19d7227a85661c" HermesID:"0x7119442C7E627438deb0ec59291e31378F88DD06" ChainID:80001
2021-09-02T08:57:23.047 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:378.0617ms}
2021-09-02T08:57:23.149 DBG source/eventbus/event_bus.go:81          > Published topic="invoice_paid" event={ConsumerID:{Address:0x6d1b3bd95b16b4f06b5e1fee49f090c13abd84ac} SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Invoice:{AgreementID:+42405017923516364420389289904908022284348344141457676389988437653795815847995 AgreementTotal:+178803706576583 TransactorFee:+0 Hashlock:66112da99c8a176a4363abe0f6b7cdd1644e3bef112c246663b12dc7ff7b46a4 Provider:0x57b8109ba4590510c3804879bae03f83ceb303f4 ChainID:80001}}
2021-09-02T08:57:23.158 DBG source/consumer/session/session_storage.go:287 > Session 9be7d17a-5af6-4c13-bb0a-67849b1a2258 updated
2021-09-02T08:57:23.160 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_grand_total_change" event={Current:+191705979529347 ChainID:80001 HermesID:0x7119442C7E627438deb0ec59291e31378F88DD06 ConsumerID:{Address:0x6d1b3bd95b16b4f06b5e1fee49f090c13abd84ac}}
2021-09-02T08:57:23.160 DBG source/eventbus/event_bus.go:81          > Published topic="balance_change" event={Identity:{Address:0x6d1b3bd95b16b4f06b5e1fee49f090c13abd84ac} Previous:+1000000000000000000 Current:+999808294020470653}
2021-09-02T08:57:23.370 DBG source/config/config.go:224              > Returning default value default-currency:MYSTT
2021-09-02T08:57:23.370 DBG source/config/config.go:224              > Returning default value default-currency:MYSTT
2021-09-02T08:57:23.370 INF source/core/state/state.go:482           > Session ID: 9be7d17a-5af6-4c13-bb0a-67849b1a2258, state: Connected, duration: 9m8.2978418s data: 1.7MiB/1014.7KiB, throughput: 1.5KiBs/1.5KiBs, spent: 0.000179MYSTT

Everything is good so far: we have received payment request, invoice was paid, P2P service channel is working. Meanwhile, provider pings consumer via P2P service channel every 14 seconds and expects response in 5 seconds. Consumer pings provider via service channel every 5 seconds. Each ping attempt skews next attempt by round trip time between Provider and Consumer:

2021-09-02T08:57:26.275 DBG source/core/connection/manager.go:865    > Received p2p keepalive ping with SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258
2021-09-02T08:57:28.415 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:356.1983ms}
2021-09-02T08:57:33.768 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:352.7197ms}
2021-09-02T08:57:39.155 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:381.4518ms}
2021-09-02T08:57:40.627 DBG source/core/connection/manager.go:865    > Received p2p keepalive ping with SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258
2021-09-02T08:57:44.509 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:353.7109ms}
2021-09-02T08:57:49.888 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:370.1023ms}
2021-09-02T08:57:59.890 ERR source/core/connection/manager.go:879    > Failed to send p2p keepalive ping. SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258 error="timeout waiting for reply to \"p2p-keepalive\": p2p send timeout"
2021-09-02T08:58:07.325 ERR source/core/quality/mysterium_morqa.go:106 > Failed to sent batch metrics request error="Post https://testnet3-quality.mysterium.network/api/v2/batch: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)"
2021-09-02T08:58:09.893 ERR source/core/connection/manager.go:879    > Failed to send p2p keepalive ping. SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258 error="timeout waiting for reply to \"p2p-keepalive\": p2p send timeout"
2021-09-02T08:58:19.898 ERR source/core/connection/manager.go:879    > Failed to send p2p keepalive ping. SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258 error="timeout waiting for reply to \"p2p-keepalive\": p2p send timeout"
2021-09-02T08:58:29.901 ERR source/core/connection/manager.go:879    > Failed to send p2p keepalive ping. SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258 error="timeout waiting for reply to \"p2p-keepalive\": p2p send timeout"
2021-09-02T08:58:39.904 ERR source/core/connection/manager.go:879    > Failed to send p2p keepalive ping. SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258 error="timeout waiting for reply to \"p2p-keepalive\": p2p send timeout"
2021-09-02T08:58:39.904 ERR source/core/connection/manager.go:882    > Max p2p keepalive err count reached, disconnecting. SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258
2021-09-02T08:58:39.904 DBG source/config/config.go:224              > Returning default value keep-connected-on-fail:false
2021-09-02T08:58:39.904 INF source/core/connection/manager.go:671    > Connection state: Connected -> Disconnecting

At some point consumer stopped receiving responses from provider and after few failed attempts dropped connection. Timings are important here. Here is anomalies we can spot solely by events time:

• Line 2021-09-02T08:57:40.627 DBG source/core/connection/manager.go:865 > Received p2p keepalive ping with SessionID=9be7d17a-5af6-4c13-bb0a-67849b1a2258 indicates that last provider to consumer ping was received in 2021-09-02T08:57:40.627. Having RTT about 0.35 seconds, next one was due to ~2021-09-02T08:57:54.977. It's a lower boundary of timestamp when P2P service channel stopped working.
• Line 2021-09-02T08:57:49.888 DBG source/eventbus/event_bus.go:81 > Published topic="consumer_ping_p2p" event={SessionID:9be7d17a-5af6-4c13-bb0a-67849b1a2258 Duration:370.1023ms} indicates successful ping from Consumer to Provider. So, 2021-09-02T08:57:49.888 is an upper boundary of timestamp when P2P service channel was working.
• Error 2021-09-02T08:58:07.325 ERR source/core/quality/mysterium_morqa.go:106 > Failed to sent batch metrics request error="Post https://testnet3-quality.mysterium.network/api/v2/batch: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)" indicates we've lost network access via VPN channel (which is separate from P2P service channel). Default timeout of this particular instance of HTTP client is 20 seconds. Therefore request attempt was initiated no later than 2021-09-02T08:57:29.888 and failed.

Taking this into account we can see that Wireguard UDP session was disrupted no later than 2021-09-02T08:57:29.888. P2P service channel became nonoperational between 2021-09-02T08:57:49.888 and 2021-09-02T08:57:54.977.

UDP traffic was just cut off, in this particular case there is nothing wrong with node. Can't know for sure why that happens, but I know some datacenters filter UDP to protect their clients from DDoS attacks.