Multiple Lines of Error when Streamer Goes Offline

[Cryptic-Soldier]

Describe the bug

https://i.imgur.com/HOu3ToI.png

When a streamer goes offline, my terminal is spammed with this message. The script itself is working flawlessly and running just fine. This error doesn't stop the script either. It's only when someone goes offline.

I assume I've got something wrong in my run.py? But I'm not exactly sure what it would be?

Steps to reproduce

N/A - User Error?

Expected behavior

Not to have this error?

Operating system

Mac OS Monterey

Python version

3.8.X

Miner version

1.8.1

Other relevant software versions

No response

Logs

N/A at this time - Just noticed it, would have to wait for someone to go offline again w/ logs enabled, log file would be huge.

Additional context

No response

[Cryptic-Soldier]

I found the problem. SOMEHOW a rouge -1 got inserted into my config when I checked it. Removed it.

Problem solved - User Error

[Cryptic-Soldier]

Okay.. so I had found the rouge -1 in my run.py and I removed it...

A streamer went offline and the error persisted... I checked my run.py again and even tried the find option to find a -1 and I couldn't find any... so I don't know what's causing this.

Not script breaking... just spams my console when someone goes offline..

[rdavydov]

Well, we need logs to analyze.

[rdavydov]

Related to the IRC (chat) client.

Twitch-Channel-Points-Miner-v2/TwitchChannelPointsMiner/classes/Chat.py

Line 46 in 6341bb8

f"Exception raised: {e}. Thread is active: {self.__active}"

[rdavydov]

Okay.. so I had found the rouge -1 in my run.py and I removed it...

What do you mean by "rouge -1"? Could you elaborate here and give some specifics?

[Cryptic-Soldier]

Okay.. so I had found the rouge -1 in my run.py and I removed it...

What do you mean by "rouge -1"? Could you elaborate here and give some specifics?

When I checked my run.py I found a -1 at the beginning of where I specified what colors I wanted in the console for each event. I removed it thinking that was the problem.

It was not the problem. Obviously it didn't need to be in there, and I'm not sure how it got in there, but that was not what is causing this error when someone goes off line.

I'm farming two twitch accounts. Fresh installs on a Mac OS. Everything is identical down to the run.pys with the log in information, discord webhook links, and telegram bot information being different respectively.

Only one of the accounts is experiencing this problem.

[Cryptic-Soldier]

Related to the IRC (chat) client.

Twitch-Channel-Points-Miner-v2/TwitchChannelPointsMiner/classes/Chat.py

Line 46 in 6341bb8

f"Exception raised: {e}. Thread is active: {self.__active}"

I checked my chat.py file, it matches the github exactly.

[rdavydov]

Logs.

[Cryptic-Soldier]

I'm chalking this up to a corrupted file. I took a copy of the working install I had and replaced all of the ones in the bad file (except for the cookies and run.py), it is now working properly. So I'm going to just chalk this up as a corrupted file. I thank you of helping me with this issue, and I'll be closing this out.

[Cryptic-Soldier]

And now it's back and on both instances. Let me grab logs.

To properly get them I need to enable logs, start the script, wait for error, then disable the script and get the logs from the logs folder right @rdavydov ?

[rdavydov]

Yes. file_level=logging.DEBUG

[Cryptic-Soldier]

Yes. file_level=logging.DEBUG

So as luck would have it.. I had logging turned on, on one of the instances.

The problem is.. the log is SO large I can't get it to paste anywhere for viewing. Pastebin freezes, and gist gives me the unicorn error page.

[Cryptic-Soldier]

I can do this though...

The log file is inside the zip. That's the best I can do. I've tried Gist numerous times on different machines, and even pastebin. The log is 53 mb, but both sites just refuse to accept it.

edge1337.zip

[Cryptic-Soldier]

Still no idea what's causing this? @rdavydov

[Cryptic-Soldier]

So this problem is still going on. I've enabled logs again, and will try to get a fresh set of logs.

[Cryptic-Soldier]

@rdavydov So I'm having a problem getting fresh logs. I have the level set to debug, but the log is generating over 100K+ lines (like 250MB+ size logs) before the error happens (someone goes offline).

As such, because it's so big, I can't paste it into pastebin, or gist, or even upload a compressed .zip here.

[Cryptic-Soldier]

Doing a little research, maybe this is the cause of the error? https://www.askpython.com/python/examples/debug-ioerror-errno9-bad-file-descriptor-in-os-system

From editing the run.py files? Maybe MacOS isn't closing them properly?

[chrswt]

I've also encountered this error whenever a streamer goes offline.

19/08/23 18:07:52 - INFO - [stop]: 💬 Leave IRC Chat: xxxx
19/08/23 18:07:52 - ERROR - [start]: Exception raised: [Errno 9] Bad file descriptor. Thread is active: True
19/08/23 18:07:52 - ERROR - [start]: Exception raised: file descriptor cannot be a negative integer (-1). Thread is active: True

The last error message is repeated about 100x as a warning, but it doesn't affect the rest of the script continuing to run.

[Cryptic-Soldier]

@rdavydov Reading this - https://www.askpython.com/python/examples/debug-ioerror-errno9-bad-file-descriptor-in-os-system And looking at when the error comes up... it looks like this is attributed to something with chat. It only displays this error when the miner leaves the IRC chat of a channel.

So possibly there's something with the chat.py file that it's not closed properly as mentioned in the link above?

I'm wondering if I set the config to never leave the IRC channel if that will stop the error, but then I also wonder what affect that will have on drops.

I think I'll take the risk and test it, and I'll report back in a few days, so the miner has time to cycle through a few streams.

[Cryptic-Soldier]

So this didn't take long to test.

Having chat presence set to online, you're able to farm two channels for points at one time, and the miner works as intended, prioritize drops, then the channels you want to farm for points in the order you've set them.

When a channel goes off line, and the miner exits the irc, this error is spammed.

Having the presence set to always prevents the error.. but you only farm one channel at a time, and it's prioritizing the channel that recently came online, ignoring if channels that have drops and the order you've set channels you want to farm. I believe this would affect drops and cause users to miss out on them.

This leads me to believe that there is a file related to the irc chat that isn't coded correctly to close properly, in accordance with the link.

I suspect chat.py is the culprit, as that's the only thing I could find in the files that relates to any of this, but I don't know enough to determine whst exactly I'm looking at.

I'm setting the presence back to online, as the error doesn't affect the miner, just annoying to see the error spammed.

Hopefully this helps debug and determine where the error is coming from @rdavydov.

[mpforce1]

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:

Twitch-Channel-Points-Miner-v2/TwitchChannelPointsMiner/classes/WebSocketsPool.py

Lines 233 to 235 in 62c01c4

	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:
   

   Twitch-Channel-Points-Miner-v2/TwitchChannelPointsMiner/classes/Chat.py

   Lines 49 to 51 in 62c01c4

   	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:

Twitch-Channel-Points-Miner-v2/TwitchChannelPointsMiner/classes/Chat.py

Lines 40 to 47 in 62c01c4

	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.