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.

Sign up for GitHub

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

Jump to bottom

onRelayClientDisconnect/Connect Emitted Twice #116

Open
bobwith2bees opened this issue Jun 27, 2023 · 8 comments
Open

onRelayClientDisconnect/Connect Emitted Twice #116

bobwith2bees opened this issue Jun 27, 2023 · 8 comments
Assignees
@quetool
Labels
bug Something isn't working

Comments

@bobwith2bees
Copy link

The connection retry logic or the load balancer is causing a short lived connection every other connection.

I haven't verified on the wire if this is hitting the relay, but the onRelayClientDisconnect and onRelayClientConnect are firing. I can see this on IOS and Android. And the connections used to be ~300 seconds reliably. Not sure if the load balancers are being tuned or the recent relay work is the root cause.

With walletconnect_flutter_v2: ^2.0.12

❯ cat logv12.txt| grep lasted
I/flutter ( 4442): 10:35:41 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 298 seconds.
I/flutter ( 4442): 10:35:42 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 0 seconds.
I/flutter ( 4442): 10:40:41 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 298 seconds.
I/flutter ( 4442): 10:40:42 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 0 seconds.

with the previous release walletconnect_flutter_v2: ^2.0.11. It dwelled a bit longer.

~/tmp on ☁️  bob@fifthpint.com(us-central1) took 24s 
❯ cat logv11.txt| grep lasted
I/flutter (14252): 18:37:25 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 294 seconds.
I/flutter (14252): 18:37:30 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 4 seconds.
I/flutter (14252): 18:42:26 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 294 seconds.
I/flutter (14252): 18:42:31 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 3 seconds.
@Luzzotica
Copy link
Contributor

Just took a look at my code.

For some reason it seems that the disconnect() function is getting called twice before the reconnect occurs.
From my point of view this is actually better, and is proof that my system is functioning as intended (Not the second disconnect call). What is means is that I am properly detecting when the relay load balances, and I am reconnecting appropriately.

I'll keep this in mind, but this isn't a massive bug to me. Having disconnect get called twice isn't a big issue, as it's just closing sockets.

@bobwith2bees
Copy link
Author

bobwith2bees commented Jun 29, 2023 •
edited
Loading

Since there is no direct way to check the state of the relay connection, we were supposed to use the callbacks.

I see BOTH RelayClient.connect and RelayClient.disconnect fire twice. So from the app perspective it is flapping.

Good to hear the relay isn't getting unwanted traffic or dropping traffic, so I can agree this is lower priority.

Here is the more complete log

I/flutter ( 4442): 10:40:41 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 298 seconds.
I/flutter ( 4442): 10:40:42 🐛 WalletConnctSvc - Core.onRelayClientConnect - Marking relay connection up.
I/flutter ( 4442): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): │ #0   RelayClient._handleRelayClose (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:290:17)
I/flutter ( 4442): │ #1   RelayClient._createJsonRPCProvider.<anonymous closure> (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:268:11)
I/flutter ( 4442): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4442): │ 💡 Handling relay close, code: 4010, reason: Disconnecting for load balancing reasons
I/flutter ( 4442): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): │ #0   RelayClient.disconnect (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:190:17)
I/flutter ( 4442): │ #1   RelayClient.connect (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:178:13)
I/flutter ( 4442): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4442): │ Disconnecting from relay server
I/flutter ( 4442): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): 10:40:42 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 0 seconds.
I/flutter ( 4442): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): │ #0   RelayClient._createJsonRPCProvider (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:209:17)
I/flutter ( 4442): │ #1   <asynchronous suspension>
I/flutter ( 4442): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4442): │ Signed JWT: <REDACTED>
I/flutter ( 4442): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): │ #0   RelayClient._createJsonRPCProvider (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:235:19)
I/flutter ( 4442): │ #1   <asynchronous suspension>
I/flutter ( 4442): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4442): │ Initializing WebSocket with wss://relay.walletconnect.com?<READACTED>
I/flutter ( 4442): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): 10:40:44 🐛 WalletConnctSvc - Core.onRelayClientConnect - Marking relay connection up.

@AnhTu6610
Copy link

Since there is no direct way to check the state of the relay connection, we were supposed to use the callbacks.

I see BOTH RelayClient.connect and RelayClient.disconnect fire twice. So from the app perspective it is flapping.

Good to hear the relay isn't getting unwanted traffic or dropping traffic, so I can agree this is lower priority.

Here is the more complete log

I/flutter ( 4442): 10:40:41 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 298 seconds.
I/flutter ( 4442): 10:40:42 🐛 WalletConnctSvc - Core.onRelayClientConnect - Marking relay connection up.
I/flutter ( 4442): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): │ #0   RelayClient._handleRelayClose (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:290:17)
I/flutter ( 4442): │ #1   RelayClient._createJsonRPCProvider.<anonymous closure> (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:268:11)
I/flutter ( 4442): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4442): │ 💡 Handling relay close, code: 4010, reason: Disconnecting for load balancing reasons
I/flutter ( 4442): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): │ #0   RelayClient.disconnect (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:190:17)
I/flutter ( 4442): │ #1   RelayClient.connect (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:178:13)
I/flutter ( 4442): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4442): │ Disconnecting from relay server
I/flutter ( 4442): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): 10:40:42 🐛 WalletConnctSvc - Core.onRelayClientDisconnect - Marking relay connection down. Connection lasted 0 seconds.
I/flutter ( 4442): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): │ #0   RelayClient._createJsonRPCProvider (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:209:17)
I/flutter ( 4442): │ #1   <asynchronous suspension>
I/flutter ( 4442): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4442): │ Signed JWT: <REDACTED>
I/flutter ( 4442): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): │ #0   RelayClient._createJsonRPCProvider (package:walletconnect_flutter_v2/apis/core/relay_client/relay_client.dart:235:19)
I/flutter ( 4442): │ #1   <asynchronous suspension>
I/flutter ( 4442): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4442): │ Initializing WebSocket with wss://relay.walletconnect.com?<READACTED>
I/flutter ( 4442): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4442): 10:40:44 🐛 WalletConnctSvc - Core.onRelayClientConnect - Marking relay connection up.

I am having similar problem. Have you solved it yet?

@Luzzotica Luzzotica changed the title Every other relay connection is less than 5 seconds in duration per onRelayxxx callbacks onRelayClientDisconnect/Connect Emitted Twice Jul 14, 2023
@Luzzotica Luzzotica added the bug Something isn't working label Jul 14, 2023
@Luzzotica
Copy link
Contributor

Looking at this issue again, it looks like I might be trying to reconnect too fast after a load balance event, and the load balance response occurs again, causing a secondary disconnect/connect emission.

Not sure what to do about this. Perhaps wait a short amount of time before I attempt to reconnect?
Waiting for a determined amount of time generally causes issues however, and is more a bandaid to the problem in these situations.

Curious what you think @bobwith2bees

@bobwith2bees
Copy link
Author

bobwith2bees commented Aug 8, 2023 •
edited
Loading

@Luzzotica

I would ask the team in charge of the load balancer for their opinion. Also make sure they are aware in case this is related to a setting on their side. In short - get an agreement on expected client behavior.

As far as well behaved clients on receiving a load balancer notification - you should consider a truncated exponential backoff algorithm that also implements some randomization. You want to avoid having all the Flutter clients become synchronized and hit the load balancer at the same time. This could occur if there was an outage and the load balancer had to drop multiple clients at one.

Some links on the topic, but I don't have a go-to solution at the moment

@bobwith2bees
Copy link
Author

Update on behavior as of 2.1.4 release:

  • I no longer see any onDisconnects
  • I see a single Core.onRelayClientConnect every 300 seconds or so
  • Pairing sessions re-establish on startup and reconnect
  • Sign client sessions are not re-establishing after the session times out. (My app is likely offline at the moment of timeout. )

I use the onRelayClientConnect event to re-read in all the active signing sessions for that relay connection. I would expect any children sign client sessions to be re-established when the peer connection is restored.

Not sure if the sign client sessions issue is related. But it appears to be a possible cause for for #176 #176 (comment)

@bobwith2bees
Copy link
Author

@quetool - Since you were looking at older bugs. ;-)

The signing session re-connect after the 7 day expiration timer appears broken. I asked in #176 (comment) how one might code a workaround, but there has been no update. I assumed this was introduced with the connection logic changes, so I did not enter a separate bug.

Issue can be reproduced by connecting one or more wallets then waiting 7 days.

@quetool
Copy link
Collaborator

quetool commented Oct 5, 2023

Thanks @bobwith2bees , I'll look into this ASAP!

@quetool quetool self-assigned this Nov 7, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@quetool quetool

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@quetool @Luzzotica @AnhTu6610 @bobwith2bees