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

Fix for PubSub reconnection bug #313

Merged
merged 1 commit into from
Aug 8, 2023
Merged

Conversation

mpforce1
Copy link

@mpforce1 mpforce1 commented Jul 15, 2023

Description

A fix for a bug that occurred during the response to a PubSub server RECONNECT message. In essence, a single WebSocket connection object spawned 2 new WebSockets both with the same pool index. My understanding is that there should only ever be a single WebSocket for each index in the pool and that reconnection should only produce a single new WebSocket.

I've also updated the pre-commit script with a new version of isort and changed the flake8 repo to GitHub.

INFO Logs

14/07/23 18:49:42 - INFO - [on_message]: #0 - Reconnection required
14/07/23 18:49:42 - INFO - [handle_reconnection]: #0 - Reconnecting to Twitch PubSub server in ~60 seconds
14/07/23 18:50:42 - INFO - [on_close]: #0 - WebSocket closed
14/07/23 18:50:42 - INFO - [handle_reconnection]: #0 - Reconnecting to Twitch PubSub server in ~60 seconds
14/07/23 18:54:28 - INFO - [on_message]: 🚀  +10 → Streamer(***) - Reason: WATCH.
14/07/23 18:54:28 - INFO - [claim_bonus]: 🎁  Claiming the bonus for Streamer(***)!
14/07/23 18:54:28 - INFO - [on_message]: 🚀  +10 → Streamer(***) - Reason: WATCH.
14/07/23 18:54:28 - INFO - [claim_bonus]: 🎁  Claiming the bonus for Streamer(***)!

DEBUG Logs

14/07/23 18:54:28 - DEBUG - TwitchChannelPointsMiner.classes.WebSocketsPool - [on_message]: #0 - Received: {"type":"MESSAGE","data":{"topic":"community-points-user-v1.***","message":"{\"type\":\"points-earned\",\"data\":***}}}
14/07/23 18:54:28 - INFO - TwitchChannelPointsMiner.classes.WebSocketsPool - [on_message]: +10 → Streamer(***) - Reason: WATCH.
14/07/23 18:54:28 - DEBUG - TwitchChannelPointsMiner.classes.WebSocketsPool - [on_message]: #0 - Received: {"type":"MESSAGE","data":{"topic":"community-points-user-v1.***","message":"{\"type\":\"claim-available\",\"data\":***}}}
14/07/23 18:54:28 - INFO - TwitchChannelPointsMiner.classes.Twitch - [claim_bonus]: Claiming the bonus for Streamer(***)!
14/07/23 18:54:28 - DEBUG - urllib3.connectionpool - [_new_conn]: Starting new HTTPS connection (1): www.twitch.tv:443
14/07/23 18:54:28 - DEBUG - TwitchChannelPointsMiner.classes.WebSocketsPool - [on_message]: #0 - Received: { "type": "PONG" }
14/07/23 18:54:28 - DEBUG - TwitchChannelPointsMiner.classes.WebSocketsPool - [on_message]: #0 - Received: {"type":"MESSAGE","data":{"topic":"community-points-user-v1.***","message":"{\"type\":\"points-earned\",\"data\":***}}}
14/07/23 18:54:28 - INFO - TwitchChannelPointsMiner.classes.WebSocketsPool - [on_message]: +10 → Streamer(***) - Reason: WATCH.
14/07/23 18:54:28 - DEBUG - TwitchChannelPointsMiner.classes.WebSocketsPool - [on_message]: #0 - Received: {"type":"MESSAGE","data":{"topic":"community-points-user-v1.***","message":"{\"type\":\"claim-available\",\"data\":***}}}
14/07/23 18:54:28 - INFO - TwitchChannelPointsMiner.classes.Twitch - [claim_bonus]: Claiming the bonus for Streamer(***)!

I was monitoring the info logs for a local docker image and noticed that, after a PubSub RECONNECT message was finished being handled, I was getting 2 logs for each PubSub message. You can see this in the logs above, at 18:54:28 there are 2 logs for each on_message and claim_bonus, and though I've redacted the info they are for the same channel. Looking through the debug logs I could see that I was also getting 2 corresponding points_earned and claim_available PubSub messages each. Additionally, from this point forward, the logs always showed these messages happening in pairs.

After reviewing the code paths I could see the issue was caused by on_close being called during the handle_reconnection flow. This causes an additional call to handle_reconnection and the flow gets run fully again, causing an additional WebSocket to be created and, since they're created on the same index, detaching the 1st new WebSocket from the pool's list. The result is that you end up with 1 new WebSocket in the pool and another new one detached from the pool, but both are operational.

Also, regarding pre-commit, I noticed when making a local commit that the hook failed to run. Turns out some of the packages were outdated so I've fixed that as part of the commit.

Type of change

  • Bug fix (non-breaking change which fixes an issue)

How Has This Been Tested?

It's kind of difficult to test because it relies on these 2 events happening in quick succession, however, I'm confident this is the cause of the issue. If this issue hasn't come up before, that's probably because it's pretty rare for the server to send a RECONNECT (the docs suggest this happens typically for server maintenance) and even rarer still for on_close to get called in that 60 second window.

Checklist:

  • My code follows the style guidelines of this project
  • I have performed a self-review of my code
  • I have commented on my code, particularly in hard-to-understand areas
  • I have made corresponding changes to the documentation (README.md)
  • My changes generate no new warnings
  • Any dependent changes have been updated in requirements.txt

@rdavydov rdavydov merged commit 4fd9125 into rdavydov:master Aug 8, 2023
lyw1217 pushed a commit to lyw1217/Twitch-Channel-Points-Miner-v2 that referenced this pull request Nov 5, 2023
Fix for PubSub reconnection bug
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

Successfully merging this pull request may close these issues.

2 participants