Drops with short(er) streams are sometimes missed

ThisIsCyreX commented 1 year ago

Hi :)

I have noticed a few times now, that the Warframe drops aren't completely mined, because the stream ends before.

I think either the miner overlaps with another drop that is currently running (which is okay) or the maintenance task idles to long before it "notices" there is an active drop?

for example an ESO drop was active from 23:04-23:30 and got only 93%. Although the drop only needs 15 minutes

DevilXD commented 1 year ago

Hi o/

Is this from the latest master? I've added some code responsible for re-gathering channels when a campaign starts before the maintenance task triggers a reload, a short while ago.

Also, how was a drop "active" since 23:04, did the devs set such an arbitrary time or was that the time the stream started at?

ThisIsCyreX commented 1 year ago

I cloned master yesterday, yes. 23:04? Good question 😄 The miner displays that:

All right - I'll try to monitor the next drops to see what exactly happens. If it happens again.

DevilXD commented 1 year ago

Huh, well, alright then.

In terms of handling cases like this:

The channel fetch step of the main loop will fetch channels for a campaign that'll start within the next hour, so between now and the next reload:

https://github.com/DevilXD/TwitchDropsMiner/blob/a33c93aa8340561c7c5ce096904fc3b3a44b94fa/twitch.py#L797-L806

The maintenance task will trigger a channel cleanup, re-fetch and selecting a new channel (if it'd be already online prior to the campaign starting), just as the campaign is about to start:

https://github.com/DevilXD/TwitchDropsMiner/blob/a33c93aa8340561c7c5ce096904fc3b3a44b94fa/twitch.py#L988-L999

If the channel would come online after the campaign starts, the events system would handle selecting it too:

https://github.com/DevilXD/TwitchDropsMiner/blob/a33c93aa8340561c7c5ce096904fc3b3a44b94fa/twitch.py#L1086-L1095

The only possible reason I can think of this may happen, is where the channel comes online, but with the drops being disabled. This will make the miner not consider is as a possible mining candidate, and skip it. If the channel then adds the "Drops Enabled" tag later, this fact isn't picked up until the next full reload happens. The same applies to a channel that changes it's played game, without stopping the stream. These updates are sent over the websocket, via a system different than the one that reads the channel's online status. Adding handling for this is possible, but it'd essentially cut the amount of channels possible to keep track of at the same time, by half. Which is the main reason I've kinda avoided adding this so far, even though I ran into one of these cases myself, when the Rainbow6 channel went online but without drops being enabled, and I had to trigger a manual reload to start mining properly.

Still, it is an issue I'd eventually want to resolve, even if it means losing on the tracking capabilities though.

ThisIsCyreX commented 1 year ago

The only possible reason I can think of this may happen, is where the channel comes online, but with the drops being disabled.

Now that you mention it. That will probably be the problem. Sometimes a stream starts, but has no active drops and if I do not reload the miner in time, the time to mine may not be enough 🕵️

ThisIsCyreX commented 1 year ago

Campaign: Bethesda BLX Stream Stars: 2022-12-07 17:00 Ends: 2022-12-07 19:30 Stream is running since 17:06 but without drops and another directory/game. They will switch to the drop and the correct game around 19:00.

So we have both: Stream starts without drops and most likely switching games without restarting the stream.

DevilXD commented 1 year ago

Handling this extra websocket event would solve this issue, but there's no way for me to implement and test it, because changing things like the stream's title, game or tags, doesn't happen often. Unless you know a streamer that is online most of the time and changes these multiple times a day.

I want to get this handled before v15 is released.

DevilXD commented 1 year ago

I've got this:

{"type":"MESSAGE","data":{"topic":"broadcast-settings-update.94706671","message":"{\"channel_id\":\"94706671\",\"type\":\"broadcast_settings_update\",\"channel\":\"paladinsgame\",\"old_status\":\"What's going on here? w/ !beam [ENG]\",\"status\":\"What's going on here? w/ !beam [ENG]\",\"old_game\":\"Paladins\",\"game\":\"Paladins\",\"old_game_id\":491115,\"game_id\":491115}"}}

This looks like it could handle detecting a game and topic change, but not the tags. It's a good starting point at least.

ThisIsCyreX commented 1 year ago

If you want, I could run a teststream, mod you, and you test game/directory and tag changes yourself?

DevilXD commented 1 year ago

Sounds good, but I don't know if / when I'd be able to find time for this. Maybe on the weekend. Theoretically, you should be able to do it yourself, as long as you can watch your own stream - no need for a mod if you can control your own stream too. All you'd have to do is tune into a stream that's about to get changed, open the browsers dev tools, find the websocket connection (gotta pre-open dev tools before the page loads), and note the messages. Here's some pics from my Firefox:

connection messages

ThisIsCyreX commented 1 year ago

Stream start {"type":"MESSAGE","data":{"topic":"video-playback-by-id.11223344","message":"{\"server_time\":1670491746,\"play_delay\":0,\"type\":\"stream-up\"}"}}

Changing game from Halo Infinite to Fortnite {"type":"MESSAGE","data":{"topic":"broadcast-settings-update.11223344","message":"{\"channel_id\":\"11223344\",\"type\":\"broadcast_settings_update\",\"channel\":\"CHANNELNAME\",\"old_status\":\"Bar.\",\"status\":\"Bar.\",\"old_game\":\"Halo Infinite\",\"game\":\"Fortnite\",\"old_game_id\":506416,\"game_id\":33214}"}}

Changing game again from Fortnite to Blasphemous {"type":"MESSAGE","data":{"topic":"broadcast-settings-update.11223344","message":"{\"channel_id\":\"11223344\",\"type\":\"broadcast_settings_update\",\"channel\":\"CHANNELNAME\",\"old_status\":\"Bar.\",\"status\":\"Bar.\",\"old_game\":\"Fortnite\",\"game\":\"Blasphemous\",\"old_game_id\":33214,\"game_id\":502914}"}}

Adding or removing tags (the info is not in here?) {"type":"MESSAGE","data":{"topic":"broadcast-settings-update.11223344","message":"{\"channel_id\":\"11223344\",\"type\":\"broadcast_settings_update\",\"channel\":\"CHANNELNAME\",\"old_status\":\"Bar.\",\"status\":\"Bar.\",\"old_game\":\"Blasphemous\",\"game\":\"Blasphemous\",\"old_game_id\":502914,\"game_id\":502914}"}}

Changing title from "Bar." to "Foobar." {"type":"MESSAGE","data":{"topic":"broadcast-settings-update.11223344","message":"{\"channel_id\":\"11223344\",\"type\":\"broadcast_settings_update\",\"channel\":\"CHANNELNAME\",\"old_status\":\"Bar.\",\"status\":\"Foobar.\",\"old_game\":\"Blasphemous\",\"game\":\"Blasphemous\",\"old_game_id\":502914,\"game_id\":502914}"}}

I tried to "simulate" enabling/disabling drops with the tags, but they won't show up in the data. But I can check again if you need it.

DevilXD commented 1 year ago

Tags have to be in a different event topic. I'm already using video-playback-by-id for stream state changes and viewer count updates. broadcast-settings-update was also mentioned by me here: https://github.com/DevilXD/TwitchDropsMiner/issues/90#issuecomment-1341387281 What we need is the event for tags getting updated. If they're updating on the channel stream as soon as they're changed, there has to be some kind of an information about that happening sent. I expect it to be over the websocket as well, but If not, you can also check the GQL operations to see if it doesn't do smth like recheck if the stream is online or smth.

DevilXD commented 1 year ago

It's a GQL request:

request

response

I'll need to do some testing to see how this fairs compared to just re-fetching the entire stream status. The good news is that updating the tags sends a broadcast-settings-update event over the websocket, so it's really just a matter of also asking GQL for the tags (or whole new stream info) when that happens. I'll try to put something together this weekend.

DevilXD commented 1 year ago

Just realized something. One of the steps of the main loop is to fetch online channels with drops enabled (specifically with that tag) for every game that has a campaign without an ACL. This normally works okay if the game is popular enough for such channels to exist, but it may also happen that no channels will be returned (they're all offline, or online but without the tag). I don't think there's a good way to remedy this case. If the channels aren't tracked by the application at all, it won't receive any updates when they do come online until the next reload. One could just retry the fetch without the "has tag" restriction, but there's no guarantee the resulting list of channels will net you ones that will enable the tag "soon". The list could be made longer because of that, but it's really just increasing the odds of getting a proper channel, but still not making it 100% and thus a reliable solution.

Thoughts on this case? Technically this is an already-existing issue that won't be solved by this change. Should I do something about it or just skip it over?

ThisIsCyreX commented 1 year ago

Fetching channels without "the tag" - sounds like a lot of channels in some cases? I would skip it and wait for feedback if drops were missed (again).

DevilXD commented 1 year ago

This is from the current master: obraz

With this, hopefully I can release v15 "Soon™" :)

ThisIsCyreX commented 1 year ago

Not sure what is happening. Warframe was again a miss:

16:31:41: No available channels to watch. Waiting for an ONLINE channel...
17:31:49: No available channels to watch. Waiting for an ONLINE channel...
18:00:00: No available channels to watch. Waiting for an ONLINE channel...
18:31:57: No available channels to watch. Waiting for an ONLINE channel...
19:32:06: No available channels to watch. Waiting for an ONLINE channel...
20:32:14: No available channels to watch. Waiting for an ONLINE channel...
21:00:00: No available channels to watch. Waiting for an ONLINE channel...
22:08:09: WarframeInternational goes OFFLINE, switching...

Starts 21:00 runs for an hour +/-

DevilXD commented 1 year ago

There's no "online" message indicating a switch, meaning it was picked up by a reload that's triggered by the maintenance task when a campaign starts. Also, this log is incomplete, there should be at least one more message after that last one, indicating what happened after the switch (started watching a different channel, or there was nothing valid to watch). Shame you didn't run it in the CALL logging mode I've been slowly adding to everything recently, because that'd help me a lot to understand what exactly happened in this case. It's -vvv as the argument when starting. I'm assuming you've updated your local code before that happened?

ThisIsCyreX commented 1 year ago

[...]
20:32:14: No available channels to watch. Waiting for an ONLINE channel...
21:00:00: No available channels to watch. Waiting for an ONLINE channel...
22:08:09: WarframeInternational goes OFFLINE, switching...
23:18:34: Claimed drop: Halo Infinite Got Milked Name & Emblem (1/1)
00:19:02: No available channels to watch. Waiting for an ONLINE channel...
[...]

Yeah, my bad I didn't increase the verbosity 😞 - But will do now :) Yes, build is after https://github.com/DevilXD/TwitchDropsMiner/commit/1cc4c4d1c38d07e0c36c2fb91111a50840d4f613

DevilXD commented 1 year ago

22:08:09: WarframeInternational goes OFFLINE, switching...
23:18:34: Claimed drop: Halo Infinite Got Milked Name & Emblem (1/1)

There's still no message indicating what happened after the switch here, which was weird to me at first, but then I checked the code and realized that I never put a "Watching: ..." message printout into the output window when the channel switches. So I just pushed https://github.com/DevilXD/TwitchDropsMiner/commit/751178c04c334a45296f305f89f47917b1b502f4 which adds that too, since that's kinda important information for debugging purposes.

ThisIsCyreX commented 1 year ago

Starts: 13:00 Ends: 14:15

[...]
12:00:03: CALL: Maintenance task waiting until: 12:30:03 (Reload)
12:00:03: No available channels to watch. Waiting for an ONLINE channel...
12:30:03: CALL: Maintenance task waiting until: 13:00:03 (Reload)
12:57:15: CALL: Channel update from websocket: Bethesda_DE
12:59:15: INFO: Bethesda_DE goes ONLINE
13:00:03: CALL: Maintenance task requests reload
13:00:20: CALL: Maintenance task waiting until: 13:30:20 (Reload)
13:00:21: No available channels to watch. Waiting for an ONLINE channel...
13:30:20: CALL: Maintenance task waiting until: 14:00:20 (Reload)
14:00:20: CALL: Maintenance task requests reload
14:00:37: CALL: Maintenance task waiting until: 14:15:00 (Cleanup)
14:00:37: Watching: Bethesda_DE
14:00:42: CALL: Drop update from websocket: Ouroboros Crown Crate (The Elder Scrolls Online, 1/15)
14:01:43: CALL: Drop update from websocket: Ouroboros Crown Crate (The Elder Scrolls Online, 2/15)
14:02:42: CALL: Drop update from websocket: Ouroboros Crown Crate (The Elder Scrolls Online, 2/15)
14:02:51: Bethesda_DE goes OFFLINE, switching...
14:02:52: CALL: Channel update from websocket: Bethesda_DE
14:04:52: CALL: Bethesda_DE stays OFFLINE
14:15:00: CALL: Maintenance task requests channels cleanup
14:15:00: No available channels to watch. Waiting for an ONLINE channel...
14:15:00: CALL: Maintenance task waiting until: 14:45:00 (Reload)
14:45:00: CALL: Maintenance task waiting until: 15:00:00 (Cleanup)
14:59:59: CALL: Maintenance task requests channels cleanup
14:59:59: CALL: Maintenance task waiting until: 15:00:37 (Reload)
14:59:59: No available channels to watch. Waiting for an ONLINE channel...
15:00:37: CALL: Maintenance task requests reload
15:00:53: No active campaigns to mine drops for. Waiting for an active campaign...
15:00:53: CALL: Maintenance task waiting until: 15:30:53 (Reload)
[...]

DevilXD commented 1 year ago

12:30:03: CALL: Maintenance task waiting until: 13:00:03 (Reload)
# a reload is scheduled to be performed shortly after the campaign starts

12:57:15: CALL: Channel update from websocket: Bethesda_DE
# there's an event received about the channel changing it's state 3 minutes before the campaign starts

12:59:15: INFO: Bethesda_DE goes ONLINE
# 2 minutes later, the state change is determined to be the stream coming online (with or without the drops enabled tag being there, we don't know as that wasn't logged)
# note there's no channel switching message as the campaign didn't start yet

13:00:03: CALL: Maintenance task requests reload
# the campaign starts, the miner reloads inventory as scheduled

13:00:20: CALL: Maintenance task waiting until: 13:30:20 (Reload)
13:00:21: No available channels to watch. Waiting for an ONLINE channel...
# no valid/online channel is found 20s after the reload started - what happened with the online one?

13:30:20: CALL: Maintenance task waiting until: 14:00:20 (Reload)
# The parentheses word should be saying "Points" in the latest master, but whatevs - this is just an intermediate reloop of the task

14:00:20: CALL: Maintenance task requests reload
14:00:37: CALL: Maintenance task waiting until: 14:15:00 (Cleanup)
14:00:37: Watching: Bethesda_DE
# an hour since the last reload passes, another reload is triggered and ends up in watching the channel as expected. Somehow the channel is immediately back?

14:00:42: CALL: Drop update from websocket: Ouroboros Crown Crate (The Elder Scrolls Online, 1/15)
14:01:43: CALL: Drop update from websocket: Ouroboros Crown Crate (The Elder Scrolls Online, 2/15)
14:02:42: CALL: Drop update from websocket: Ouroboros Crown Crate (The Elder Scrolls Online, 2/15)
14:02:51: Bethesda_DE goes OFFLINE, switching...
14:02:52: CALL: Channel update from websocket: Bethesda_DE
14:04:52: CALL: Bethesda_DE stays OFFLINE
# 2 minutes into the watching, the channel goes (and stays) offline

14:15:00: CALL: Maintenance task requests channels cleanup
14:15:00: No available channels to watch. Waiting for an ONLINE channel...
14:15:00: CALL: Maintenance task waiting until: 14:45:00 (Reload)
# the campaign ends, a cleanup is triggered, another intermediate reloop is scheduled 30 minutes from now

14:45:00: CALL: Maintenance task waiting until: 15:00:00 (Cleanup)
# and so on

Couple of things to note here:

Even if the channel would somehow miss on the "going online" event, there are viewer counter updates sent in every few minutes, to update the active viewers counter(s). The miner will set a channel ONLINE if it's found OFFLINE when such event is received.
Because of the above, there is no real way for the channel to remain offline for an hour, unless it really was offline during that time, or the topic responsible for it's status updates got removed from the websocket (most probable cause).
With the topic removed, the channel essentially remained in it's last set state, until an hour later the reload caused the channel's status to refresh.
The fact that there's a 14:02:51: Bethesda_DE goes OFFLINE, switching... line, but without CALL: Channel update from websocket: Bethesda_DE 2 minutes before it, indicates that the topic that supposedly got removed before, is now added back again. The "Channel update from websocket" line is triggered only by this new, 2nd topic that I've added recently. They're added and removed together though, so if the 1st one was gone, 2nd one was likely gone too.

Overall, all of this sounds quite messy, and it seems like I didn't think hard enough while I was making the "two topics per channel instead of one" change. Still, I'll need to do some targeted debugging to confirm this issue exists and that's really what happened. This log is quite valuable in terms of letting me know what exactly happened, thank you :) I'll try sitting down to it this weekend.

DevilXD commented 1 year ago

I didn't find enough time to do proper testing, but from a quick study and re-checking of the code, everything seems to be okay with the websocket topics. However, handling #102 has reminded me that drops don't have to follow the same start and end times as the campaign does, and that's what could've fooled the miner here. If the starts_at of the drop wouldn't be exactly 13:00, then the 13:00:21: No available channels to watch. Waiting for an ONLINE channel... message is perfectly normal. The wording of it might be a bit misleading, but this message is printed out when the can_watch(channel) function fails for every tracked channel, where it internally calls campaign.can_earn(channel), followed by an any() of drop.can_earn() for every drop in a campaign, where this drop.can_earn function ensures drop's timeframe is valid. If it isn't, then even if the campaign's timeframe is valid, the channel is deemed "unwatchable", as in, it's impossible to earn any (or at least that particular) drop by watching that particular channel at the given time of the check.

Because of the above, I've just pushed out https://github.com/DevilXD/TwitchDropsMiner/commit/d100c4b7ff05d6bc53a1dfdb14b4d8b345c0e3e7, which ensures that when time triggers are collected from a campaign, each of the drop's triggers are included as well. A set is used to de-duplicate the resulting timestamps, so for campaigns where drops follow the campaign's timestamps, the old behavior is retained (all starts_at from each drop and the campaign collapse to one, same for ends_at), but for campaigns where drops have different timestamps, a bigger set (>2 elements) is returned.

All of this suggests to me that a tree-like internal structure of campaigns to channels, with some kind of events system propagating changes to each leaf, would be a simpler approach to this "state updating" problem we have here. The current system of loops and triggers telling those loops to re-loop and recheck all conditions works "okay", but does a lot of work unnecessarily, for example, each time a reload happens, all "old" campaigns are just purged from memory, and a new set of campaigns is fetched and processed onto their place. Doing this leads to then having to do the same for all tracked channels, including unsubscribing and resubscribing websocket topics, having to "relink" the watching channel (because the internal object for it changed to a new one), and many other similar things. If none of the campaign's changed anything within the hour between each reload though, none of this would be needed and the miner could just continue on with it's state as-is. Similarly, even if the state would change and a new campaign would be added (for example), normally it'd be just a matter of:

checking if we have to fetch some new channels for this new campaign
checking if we need to possibly switch the watching channel

..., and that's it. Existing campaign and channel objects could be retained between reloads, to avoid hammering the RAM and CPU with deleting and readding objects with identical structure and data.

All of this would require quite a big rewrite to the miner though, which is something that's definitely suited for at least the next major version after v15, so v16 or higher. That's assuming #100 isn't the end of this project, of course. Fow now, lets stick to these "time triggers" we have.

DevilXD commented 1 year ago

I want to avoid this blocking the v15 release, and I think it should mostly work for now. If the issue would persist after the release, please open another issue.

DevilXD / TwitchDropsMiner

Drops with short(er) streams are sometimes missed #90