Fix double popup counting

[Azure-Agst]

Sometimes FATE rewards in maps will pop up, be interrupted by another chest opening, then show the first one again, causing them to be double counted. We need to figure out how to differentiate between that.

[Azure-Agst]

I think I have reliable logic for detection of this now?

I've learned that the game always sends the reward chat messages (even if no logs have the Loot Notices filter enabled) a few milliseconds before the FATE Reward popup appears. Assuming this behavior is constant, new detection logic should go as follows:

• Every time a Type 2110 (Loot Notices) Chat is sent that says we got gil, record that gil value
• Every time a FATE Reward popup appears, "consume" the recorded value
• If the consumed value matches the value in the popup, then it's probably legit and can be added to the records

// If we get a message in the Loot Notices channel...
if ((int)type == 2110) {

    // ... See if it's gil and if so, stash the value
    var r = gilRegex.Match(message.ToString());
    if (r.Success)
    {
        var gilStr = gilRegex.Match(message.ToString()).Groups[1].ToString();
        gilOnDeck = int.Parse(gilStr, NumberStyles.AllowThousands);
        Services.Log.Debug($"chat: gilOnDeck = {gilOnDeck}");
    }
}

// Ensure that this gil was actually given to us, and isn't just a duplicate popup
// We "consume" gilOnDeck regardless of what happens here
Services.Log.Debug($"addon pre-con: gilOnDeck = {gilOnDeck}");
int tempGilVal = gilOnDeck; gilOnDeck = 0;
if (tempGilVal != gil)
{
    Services.Log.Warning("Chat/FateReward Desync detected!");
    return;
}
Services.Log.Debug($"addon post-con: gilOnDeck = {gilOnDeck}");

A few predictable failure points:

• Time between chat + popup is about 23ms. If player is rewarded gil from another source in that time period, race condition occurs.

Will continue to iterate.

[Azure-Agst]

Fuck it, gonna bundle this with 0.0.0.3 for Major to test tomorrow, see how it works

[Azure-Agst]

Reopening this now that testing has showed that this does NOT work fully. Needs more testing.

[Azure-Agst]

Weird! Ran a few boarskins, and found out that chest rewards are logged in a totally separate channel. 62, not 2110.

[Azure-Agst]

New regex seems to work better, no more desync. Commiting into the v0.0.0.4 branch soon.

[Azure-Agst]

This is gonna kill me. Race condition. UI + Chat are probably on separate threads.

[Azure-Agst]

I have once again redone the logic for Gil reward tracking, now utilizing a custom TimedList data structure.

The main idea here is that now, chat events and FATE reward addon events have their own timed list associated with them. Every time one type of event fires, it checks the list of the other kind of event to see if there's a matching value. If so, process. If not, add the value to the first event's timed list with an expiration time of 20 seconds.

Instead of using a timer to purge on a normal basis, our application is small enough that I just purge whenever an event happens, in the Contains function.

Preliminary testing is promising!

[Azure-Agst]

I now have video footage of this bug being patched using the new TimedList implementation. I did a run of Aquapolis with Killiam and was watching the logs & chat the entire time, and was able to replicate the bug to the tee.

Opened a 10k gil leather sack immediately followed by the chest. This resulted in the popup for the 10k being dismissed and re-shown later again. Using old logic, this would have double counted the 10k. On current dev build, the 10k is only recorded once, as intended. (Keep your eye on game chat!)

double_counting_bug_fixed.mp4

Below is an annotated screenshot of the logs showing that the plugin is doing exactly what we want.

Here's another bug that occurred using the old logic. Previous builds expected the chat to be sent before the popup, and if the inverse occurred, a race condition would occur and the plugin would not record the reward, as seen in a previous comment.

This is gonna kill me. Race condition. Probably threaded.

Now, here's an screenshot of the logs showing what happens if the popup happens before the chat:

Feeling SUPER confident in this iteration. Absolutely ready for this to be tested in production on Thursday. Will merge in with v0.0.0.5.

[Azure-Agst]

Just for posterity, I want to theorycraft as to how this bug could reappear. Two points of failure must be met within a 10s timespan:
1.) a player must get gil from an alternate source (i.e. challenge log)
2.) we must get a re-showing of a fate popup for the same amount of gil

The chances of that happening are pretty slim, but that might be an edge case we want to program for. Thoughts: Upon reading a "Challenge complete" message, ignore the next gil message if possible.