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

This final method sets __active to False only after calling disconnect on the underlying connection #499

Open
rdavydov opened this issue Apr 21, 2024 · 0 comments
Assignees
Labels
🐜 bug Something isn't working ➕ todo

Comments

@rdavydov
Copy link
Owner

I recently encountered this error by chance when looking at my logs. I checked the last week's worth of logs and it looks like it had only occurred once. The relevant lines are:

20/04/24 02:17:02 - DEBUG - TwitchChannelPointsMiner.classes.WebSocketsPool - [on_message]: #0 - Received: {"type":"MESSAGE","data":{"topic":"video-playback-by-id.###","message":"{\"server_time\":1713575822,\"type\":\"stream-down\"}"}}
20/04/24 02:17:02 - INFO - TwitchChannelPointsMiner.classes.Chat - [stop]: Leave IRC Chat: ###
20/04/24 02:17:02 - ERROR - TwitchChannelPointsMiner.classes.Chat - [start]: Exception raised: file descriptor cannot be a negative integer (-1). Thread is active: True
// above line repeated 195 times
20/04/24 02:17:02 - INFO - TwitchChannelPointsMiner.classes.entities.Streamer - [set_offline]: Streamer(username=###, channel_id=###, channel_points=###) is Offline!

This is the code that processes that message:

elif message.type == "stream-down":
if ws.streamers[streamer_index].is_online is True:
ws.streamers[streamer_index].set_offline()

Looking through the code, in response to a stream-down message the miner will:

  1. Call Streamer.set_offline() for the appropriate Streamer
  2. This sets Streamer.is_online = False
  3. Then it calls Streamer.toggle_chat()
  4. Assuming Streamer.settings.chat is ChatPresence.ONLINE it will then call Streamer.leave_chat() (Incidentally this is likely why the issue doesn't show up for ChatPresence.ALWAYS)
  5. This calls self.irc_chat.stop() which is a method on ThreadChat in Chat.py
  6. This ends up calling self.chat_irc.die() which is a method on ClientIRC:
    def die(self, msg="Bye, cruel world!"):
    self.connection.disconnect(msg)
    self.__active = False

I believe this is where a race condition happens. This final method sets __active to False only after calling disconnect on the underlying connection. Disconnect ends up invalidating the underlying Socket and I think the File Descriptor will be -1 for a closed Socket, however I'm no expert on this. This is likely the -1 in the error message.

At the same time as this is happening we also have ClientIRC.start. In there is the while loop that processes the IRC connection:

while self.__active:
try:
self.reactor.process_once(timeout=0.2)
time.sleep(0.01)
except Exception as e:
logger.error(
f"Exception raised: {e}. Thread is active: {self.__active}"
)

As previously noted by @rdavydov, that call to logger.error is the source of the error we see in the log. So the Exception that caused it must have come from that try block.

Since these 2 things (processing the connection and responding to stream-down) are happening in 2 different Threads it's entirely possible, albeit unlikely, for execution to change Threads mid-disconnection after the socket becomes invalid but before it sets the __active state. And since this while loop uses that state to determine whether to continue trying to process the connection, it could end up trying to read from a closed socket.

I believe a simple fix to this is to set __active = False prior to starting the disconnection, just swap those 2 lines in ClientIRC.die:

def die(self, msg="Bye, cruel world!"):
    self.__active = False
    self.connection.disconnect(msg)

That should allow the while loop to exit early. It doesn't look like anything else relies on __active so there should be no other side-effects.

Originally posted by @mpforce1 in #250 (comment)

@rdavydov rdavydov added ➕ todo 🐜 bug Something isn't working labels Apr 21, 2024
@rdavydov rdavydov self-assigned this Apr 21, 2024
@rdavydov rdavydov pinned this issue Jun 15, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
🐜 bug Something isn't working ➕ todo
Projects
None yet
Development

No branches or pull requests

1 participant