Snapshot bug
ShmooDude opened this issue ยท 2 comments
Snapshots from auras that are used when applying the ability don't always apply correctly.
Example: I use Rake from Prowl. Prowl is removed by Rake. The multiplier should increase by a factor of 2.
The problem occurs when events are not occurring in the expected order (I had exact /ovale debug
posts in the old ticket system on curseforge). The events in question:
UNIT_SPELLCAST_SENT
- Action is innitiated by player
UNIT_SPELLCAST_SUCCEEDED
- Acknowledgement that ability cast succeeded (as opposed to failed).
UNIT_AURA
- Aura is removed
Most of the time all of these occur at the same time (on my computer according to Ovale's debug timestamps). However, sometimes there's a slight delay (15-30 ms) in the UNIT_SPELLCAST_SUCCEEDED
but the UNIT_AURA
event will fire at the same time as the UNIT_SPELLCAST_SENT
.
OvaleAura has a function to check if an aura was removed within a short enough time period: function IsWithinAuraLag(time1, time2, factor)
But this will only be used if Ovale considers an aura to be "consumed." To determine if a spell is consumed, Ovale checks if the aura ended early and if it did, check the if the OvaleFuture:LastInFlightSpell()
consumed it. This is all done in function OvaleAura:LostAuraOnGUID(guid, atTime, auraId, casterGUID)
The problem is that OvaleFuture:LastInFlightSpell()
returns the last ability to send a UNIT_SPELLCAST_SUCCEEDED
event. But since that event sometimes fires after the UNIT_AURA
event does, the function checks the wrong spellcast and doesn't consider the aura "consumed."
The easy "quick fix" is to stop checking against the most recent spellcast and simply mark any aura that ended early as "consumed." https://github.com/ShmooDude/Ovale-1/pull/1 is what I did on my local copy. I did 30 tests at 700 Aura Lag setting and 10 at 100 and all got the correct snapshot.
The probably more correct method would be to check against both the most recent successful spellcast and any spellcasts sent, but not yet succeeded or failed.
Doesn't seem to have completely fixed the problem but certainly makes it less prevalent. Will investigate more as there's probably yet another, more rare, cause.
It seems that sometimes rake is being expired early in OvaleFuture which causes the damage multiplier to be dropped.
OvaleFuture: 211818.426000 UNIT_SPELLCAST_SENT player Rake Raider's Training Dummy 3-3136-1159-17718-1822-00001F9FA1
OvaleFuture: Queueing (1) spell Rake to Raider's Training Dummy (Creature-0-3136-1159-17718-87320-00001F7E4E).
OvaleFuture: Saving information from 211818.426 to the spellcast for Rake.
OvaleFuture: 211818.426000 UNIT_SPELLCAST_SUCCEEDED player Rake 3-3136-1159-17718-1822-00001F9FA1 1822
OvaleFuture: Found spellcast for Rake to Raider's Training Dummy queued at 211818.426000.
OvaleFuture: Instant-cast spell Rake (1822): start = 211818.426 (+0).
OvaleFuture: Spell Rake (1822) will finish after updating aura 155722 on Creature-0-3136-1159-17718-87320-00001F7E4E.
OvaleFuture: Saving information from 211818.426 to the spellcast for Rake.
OvaleFuture: Caching spell Rake (1822) as most recent GCD spellcast.
OvaleFuture: 211818.426000 CLEU SPELL_CAST_SUCCESS Lolaan Player-5-09EB03D6 Raider's Training Dummy Creature-0-3136-1159-17718-87320-00001F7E4E 1822 Rake
OvaleFuture: Found spellcast for Rake to Raider's Training Dummy queued at 211818.426000.
OvaleFuture: PLAYER_REGEN_DISABLED Entering combat.
OvaleAura: UNIT_AURA: player
OvaleAura: 211818.426000 Scanning auras on Player-5-09EB03D6 (player)
OvaleAura: Advancing age of auras for Player-5-09EB03D6 (player) to 175.
OvaleAura: Adding HELPFUL Agility (60233) to Player-5-09EB03D6 at 211818.426000, aura.serial=175
OvaleFuture: Updating to snapshot from 211818.426 for spell Rake to Raider's Training Dummy (Creature-0-3136-1159-17718-87320-00001F7E4E) queued at 211818.426.
OvaleAura: Expiring HELPFUL Prowl (5215) from Player-5-09EB03D6 at 211818.426000.
OvaleAura: Consuming HELPFUL Prowl (5215) on Player-5-09EB03D6 at 211818.426000.
OvaleAura: End scanning of auras on Player-5-09EB03D6 (player).
OvaleAura: UNIT_AURA: nameplate3
OvaleAura: 211818.426000 Scanning auras on Creature-0-3136-1159-17718-87320-00001F7E4E (nameplate3)
OvaleAura: Advancing age of auras for Creature-0-3136-1159-17718-87320-00001F7E4E (nameplate3) to 134.
OvaleAura: Adding HARMFUL Rake (155722) to Creature-0-3136-1159-17718-87320-00001F7E4E at 211818.426000, aura.serial=134
OvaleAura: Snapshot stats for HARMFUL Rake (155722) on Creature-0-3136-1159-17718-87320-00001F7E4E applied by Rake (1822) from 211818.426000, now=211818.426000, aura.serial=134
OvaleAura: Rake (155722) is a periodic aura.
OvaleAura: End scanning of auras on Creature-0-3136-1159-17718-87320-00001F7E4E (nameplate3).
OvaleAura: UNIT_AURA: target
OvaleAura: 211818.426000 Scanning auras on Creature-0-3136-1159-17718-87320-00001F7E4E (target)
OvaleAura: Advancing age of auras for Creature-0-3136-1159-17718-87320-00001F7E4E (target) to 135.
OvaleAura: End scanning of auras on Creature-0-3136-1159-17718-87320-00001F7E4E (target).
OvaleAura: 211820.451000 SPELL_PERIODIC_DAMAGE: Creature-0-3136-1159-17718-87320-00001F7E4E
OvaleAura: Updating Rake (155722) on Creature-0-3136-1159-17718-87320-00001F7E4E, tick=2.01, lastTickTime=nil
OvaleAura: 211822.464000 SPELL_PERIODIC_DAMAGE: Creature-0-3136-1159-17718-87320-00001F7E4E
OvaleAura: Updating Rake (155722) on Creature-0-3136-1159-17718-87320-00001F7E4E, tick=2.0130000114441, lastTickTime=1470078882.868
OvaleFuture: 211822.664000 UNIT_SPELLCAST_FAILED_QUIET player Ysera's Gift 3-3136-1159-17718-145110-00001F9FA5 145110
OvaleFuture: Warning: no queued spell Ysera's Gift (145110) found to end casting.
OvaleFuture: Warning: removing active spell Rake (1822) to Raider's Training Dummy (Creature-0-3136-1159-17718-87320-00001F7E4E) that should have finished.
OvaleAura: 211824.466000 SPELL_PERIODIC_DAMAGE: Creature-0-3136-1159-17718-87320-00001F7E4E
OvaleAura: Updating Rake (155722) on Creature-0-3136-1159-17718-87320-00001F7E4E, tick=2.0019998550415, lastTickTime=1470078884.881
OvaleFuture: PLAYER_REGEN_ENABLED Leaving combat.
OvaleAura: UNIT_AURA: player
OvaleAura: 211825.396000 Scanning auras on Player-5-09EB03D6 (player)
OvaleAura: Advancing age of auras for Player-5-09EB03D6 (player) to 176.
OvaleAura: End scanning of auras on Player-5-09EB03D6 (player).
OvaleAura: 211826.458000 SPELL_PERIODIC_DAMAGE: Creature-0-3136-1159-17718-87320-00001F7E4E
OvaleAura: Updating Rake (155722) on Creature-0-3136-1159-17718-87320-00001F7E4E, tick=1.9920001029968, lastTickTime=1470078886.883
OvaleFuture: 211827.654000 UNIT_SPELLCAST_FAILED_QUIET player Ysera's Gift 3-3136-1159-17718-145110-00001F9FAA 145110
OvaleFuture: Warning: no queued spell Ysera's Gift (145110) found to end casting.
OvaleAura: 211828.481000 SPELL_PERIODIC_DAMAGE: Creature-0-3136-1159-17718-87320-00001F7E4E
OvaleAura: UNIT_AURA: nameplate1
OvaleAura: 211828.481000 Scanning auras on Creature-0-3136-1159-17718-87320-00001F7E4E (nameplate1)
OvaleAura: Advancing age of auras for Creature-0-3136-1159-17718-87320-00001F7E4E (nameplate1) to 136.
OvaleAura: Expiring HARMFUL Rake (155722) from Creature-0-3136-1159-17718-87320-00001F7E4E at 211828.481000.
It's possible this is an artifact of me dropping combat and wouldn't happen in a normal encounter (seems to happen about that time, though don't have a good notification up to watch that). It also seems to be fairly rare as it usually takes me a couple minutes to get it to happen.