Trinitycore: Character Rollback to Previous Location upon Logout

[WOW-Reborn]

While playing a pally this error will randomly popup and when it does once you log out of your character and log back in you are teleported to an entirely different place.

[ERROR]: [1062] Duplicate entry '85-85-63514-2' for key 'PRIMARY' SQL(p): INSERT INTO character_aura (guid, casterGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (85, 85, 63514, 2, 2, 1, 0, 6, 0, 0, -1, 0, -1, -1, 0, 0, 1)

This situation appears from my searching to be very similar to an old issue #21486.

CHANGEME Description of the problem or issue here.

Paladin being rolled back on logout after receiving this database error.

CHANGEME Tell us what happens.
If this is a crash, post the crashlog (upload to https://gist.github.com/).

Should be able to log out and log back in and be in the same spot.

CHANGEME Tell us what should happen instead.

The problem is hard for me to replicate. It almost seems to be random. But when I least expect it I will log out of my pally and log into another character once I decide to go back to my pally to play my toon has rolled back his location. This doesn't happen all the time usually twice a day on average.

1. CHANGEME Step 1 include entries of affected creatures / items / quests with a link to the relevant wowhead page.
2. Step 2
3. Step 3

3.3.5

CHANGEME 3.3.5, master or both

e5b8b1e99a4e+

CHANGEME Copy the result of server debug command (if you need to run it from client get prat addon)

Windows Server 2012

[illfated]

The only character location rollback I have experienced is that the 3.3.5 worldserver fails to save last location when logging out soon after a flight path has ended and moving a medium distance (taxi_path character field fails to reset after arrival at destination node #22089). Then again, I don't usually play the paladin class and it looks like you might have a real issue with auras. (This issue needs extra confirmations from other paladin players, along with their TC core rev. hash from their server.)

[pedroevil51]

What is your mysql version? i had that problem on 8.0 but i downgraded to 5.7 and never more

[illfated]

I only use 5.6 (currently on 5.6.38, but upgrading to 5.6.41 now or "Real Soon Now™ ". ;-)

[pedroevil51]

Try this on your mysql .ini config

autocommit=1
innodb_flush_log_at_trx_commit = 1

[illfated]

innodb_flush_log_at_trx_commit=1

is already in C:\ProgramData\MySQL\MySQL Server 5.6\my.ini (Line 214),
but autocommit was not found, not even in the comments.

Not sure where to put it or why I should try it, since most Google searches comes up with rollback scenarios when I search for autocommit=1

[pedroevil51]

Autocommit needs to be 1 if innodb_flush_log_at_trx_commit = 1

[Gooyeth]

It is not something new: https://github.com/TrinityCore/TrinityCore/issues/21486

[Aokromes]

also, it's totally unrelated to mysql version.

[WOW-Reborn]

Correct Gooyeth this isn't a new issue thats why I made sure i specified where it was previously posted but there have been no comments since April and I figured it was best to show what I am seeing on my end verses doing a stupid bump. I will say no characters on my server experience rollbacks except for paladins so I can safely say this is something that appears to only affect them.

[Gooyeth]

@WOW-Reborn: Of course, I mentioned it to rule out possibilities, I did not realize that you put it in the issue 🤣

[TerrorBringer]

This issue happens to my paladin aswell.

Rev 073ba8e

[ghost]

Confirm

SQL(p): INSERT INTO character_aura (guid, casterGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (3743, 3743, 59620, 3, 3, 1, 400, -5, 0, 399, -6, 0, 15000, 13895, 0, 0, 1)

SQL(p): INSERT INTO character_aura (guid, casterGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (3743, 3743, 59620, 3, 3, 1, 400, -5, 0, 399, -6, 0, 15000, 10486, 0, 0, 1)

SQL(p): INSERT INTO character_aura (guid, casterGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (3743, 3743, 59620, 3, 3, 1, 400, -5, 0, 399, -6, 0, 15000, 3550, 0, 0, 1)

SQL(p): INSERT INTO character_aura (guid, casterGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (3743, 3743, 59620, 3, 3, 1, 400, -5, 0, 399, -6, 0, 15000, 11374, 0, 0, 1)

SQL(p): INSERT INTO character_aura (guid, casterGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (3743, 3743, 59620, 3, 3, 1, 400, -5, 0, 399, -6, 0, 15000, 6957, 0, 0, 1)

SQL(p): INSERT INTO character_aura (guid, casterGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (3743, 3743, 59620, 3, 3, 1, 400, -5, 0, 399, -6, 0, 15000, 4938, 0, 0, 1)

[Aokromes]

test after be47254

[jackpoz]

does this still happen ?

[Aokromes]

yes, at least 5d ago.

[jackpoz]

Do you have a SQL error log ?

[Aokromes]

db_errors/db_errors_2019-01-28_09-47-46.log:2019-01-28_22:21:44 ERROR [sql.sql] SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (1810, 1810, 0, 63514, 2, 2, 1, 0, 6, 0, 0, -1, 0, -1, -1, 0, 0, 1)

[jackpoz]

@ariel- could you take a look at this since you fixed https://github.com/TrinityCore/TrinityCore/issues/21486 ?

[Aokromes]

all the auras i see on the recent duplicate thing

db_errors/db_errors_2019-03-12_17-22-57.log:2019-03-14_07:10:27 ERROR [sql.sql] SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (181751, 181751, 0, 63514, 2, 2, 1, 0, 6, 0, 0, -1, 0, -1, -1, 0, 0, 1)
db_errors/db_errors_2019-03-18_09-21-13.log:2019-03-18_22:06:39 ERROR [sql.sql] SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (172964, 172964, 0, 63510, 6, 6, 1, 0, -30, -30, 0, -1, -1, -1, -1, 0, 0, 1)
db_errors/db_errors_2019-03-21_13-28-01.log:2019-03-21_21:50:40 ERROR [sql.sql] SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (181750, 181750, 0, 63531, 6, 6, 1, 0, 3, 3, 0, -1, -1, -1, -1, 0, 0, 1)

[jackpoz]

so in a way we could add some logs just for those 3 auras

[Shauren]

Tried tracing what could possibly lead to a situation where m_ownedAuras contains two auras that would cause this save error

APPLY 1 | LEARN 31869 (Sanctified Retribution)
APPLY 2 | LEARN (Swift Retribution)
REMOVE 1 | spell_pal_improved_aura_AuraScript::HandleEffectApply calls Unit::RemoveOwnedAura directly
APPLY 3 | LoadFromDB - this one does not trigger any removals, no AuraApplication happens until later
--- TIME GAP
REMOVE 2 | Map::Update, _RemoveNoStackAurasDueToAura

Notice time gap, if SaveToDB is called there, we get this error. It is possible there there is something else that would also cause 2nd aura to appear there without removing the previous one (but it would need to trigger a different code path than through spell_pal_improved_aura_AuraScript)

Here is a (hack?) that could possibly fix this issue

diff --git a/src/server/game/Entities/Player/Player.cpp b/src/server/game/Entities/Player/Player.cpp
index ae20632637..c2d9f6d594 100644
--- a/src/server/game/Entities/Player/Player.cpp
+++ b/src/server/game/Entities/Player/Player.cpp
@@ -17874,6 +17874,14 @@ void Player::_LoadAuras(PreparedQueryResult result, uint32 timediff)
                     continue;
                 }

+                // HACK, hopefully temporary - experiment to check if we should be saving area auras at all (or at least not the triggered ones)
+                // checking here if we already have this aura from a triggered spell somewhere earlier (like in _LoadSpells)
+                if (aura->IsArea() && GetOwnedAura(aura->GetId(), caster_guid, itemGuid, 0, aura))
+                {
+                    aura->Remove();
+                    continue;
+                }
+
                 aura->SetLoadedState(maxduration, remaintime, remaincharges, stackcount, recalculatemask, critChance, applyResilience, &damage[0]);
                 aura->ApplyForTargets();
                 TC_LOG_DEBUG("entities.player", "Player::_LoadAuras: Added aura (SpellID: %u, EffectMask: %u) to player '%s (%s)",

Proper solution that would prevent triggered area auras to be saved is quite a bit more complex than just these few lines to verify my theory

[jackpoz]

Confirm using 1b095811b82e7bf390e3a3e522e768fc2b42d2b0 https://gist.github.com/jackpoz/e7a9035115920ec39f10efba8dce4c97

Guid 43 in the log is a paladin

[Shauren]

.pdump? What did you do with that paladin? Any spell learns? Talent resets? Spec changes?

[Aokromes]

we did:

https://github.com/TrinityCore/TrinityCore/issues/23751#issuecomment-527656689

[jackpoz]

@Aokromes could you get a pdump and upload it ?

[Aokromes]

still a thing

[gtestdev]

I see those logs too

2020-07-30_21:30:48 SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (40580, 40580, 0, 63510, 6, 6, 1, 0, -10, -10, 0, -1, -1, -1, -1, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '40580-40580-0-63510-6' for key 'PRIMARY'
2020-07-30_21:30:48 Transaction aborted. 34 queries not executed.

2020-07-31_06:04:43 SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (27168, 27168, 0, 63514, 2, 2, 1, 0, 4, 0, 0, -1, 0, -1, -1, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '27168-27168-0-63514-2' for key 'PRIMARY'
2020-07-31_06:04:43 Transaction aborted. 40 queries not executed.

2020-07-31_07:05:31 SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (1667, 1667, 0, 63531, 6, 6, 1, 0, 3, 3, 0, -1, -1, -1, -1, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '1667-1667-0-63531-6' for key 'PRIMARY'

2020-07-31_07:40:23 SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (18760, 18760, 0, 63514, 2, 2, 1, 0, 6, 0, 0, -1, 0, -1, -1, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '18760-18760-0-63514-2' for key 'PRIMARY'
2020-07-31_07:40:23 Transaction aborted. 35 queries not executed.

2020-07-31_07:56:51 SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (18760, 18760, 0, 63514, 2, 2, 1, 0, 6, 0, 0, -1, 0, -1, -1, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '18760-18760-0-63514-2' for key 'PRIMARY'
2020-07-31_07:56:51 Transaction aborted. 31 queries not executed.
2020-07-31_07:57:57 SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (18760, 18760, 0, 63514, 2, 2, 1, 0, 6, 0, 0, -1, 0, -1, -1, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '18760-18760-0-63514-2' for key 'PRIMARY'
2020-07-31_07:57:57 Transaction aborted. 31 queries not executed.
2020-07-31_07:58:52 SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (18760, 18760, 0, 63514, 2, 2, 1, 0, 6, 0, 0, -1, 0, -1, -1, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '18760-18760-0-63514-2' for key 'PRIMARY'
2020-07-31_07:58:52 Transaction aborted. 31 queries not executed.

all seem SPELL_EFFECT_APPLY_AREA_AURA_RAID from paladin

[CraftedRO]

Ok I had made a video step by step about how to reproduce those linked issues , if someone interested : https://youtu.be/sM9VBDqZGvo

[Faq]

@CraftedRO could you upload also .pdump result? https://github.com/TrinityCore/TrinityCore/issues/22234#issuecomment-528791719

[CraftedRO]

Sure : original dump.zip and txt converted one dump1.txt.

[Shauren]

awesome, maybe finally ill get this fixed

[jackpoz]

could someone please convert the 6 minutes video to some written steps ? thanks

[Aokromes]

enter icc with one paladin (protection paly, idk if relevant) there is no need to enter with more persons inside raid.
die (taking damage from mobs, idk if .die gm command can do the trick to)
kick player (with gm command to remove player from world)
relog
rev player (with gm command)

TC> TC> SQL(p): INSERT INTO character_aura (guid, casterGuid, itemGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (2467, 2467, 0, 63514, 2, 2, 1, 0, 6, 0, 0, -1, 0, -1, -1, 0, 0.0, 1)

[CraftedRO]

yes you have to be paladin for the SQL error and not sure how relevant is but I used those Retribution talents (yes , only 57 talent points used) in video .

[illfated]

There must be something fundamentally wrong with how GUIDs are generated for those auras, seeing that the GUID is reused without making sure that the existing GUID is removed. What makes it even more surprising is that the Primary key contains an additional GUID as well as 2 more values, making the key consist of 5 values in total, which should be more than enough to make it unique, but that seems to be messed up in the current implementation.

[jackpoz]

@illfated the issue is that the player has 2 auras with the same spell id and same caster, which shouldn't happen as there new aura should replace the old one instead. That's why the primary key has 5 columns (different casters can apply the same aura to the same player and that's ok)

[Jildor]

well, you don't need enter inside instance to reproduce it, just set any of those three talents:

// 63510 - Improved Concentration Aura (Area Aura)
// 63514 - Improved Devotion Aura (Area Aura)
// 63531 - Sanctified Retribution (Area Aura)

cast paladin aura (by example 54043 Retribution Aura (Rank 7))
die (.damage 99999999)
logout and login
revive (.revive)

seems this script cast spell:
https://github.com/TrinityCore/TrinityCore/blob/a32b6b8ac4c81128a56b282f20837fb085bdd9e7/src/server/scripts/Spells/spell_paladin.cpp#L1212-L1217

and for some reason (it need more reseach, I have not had time to see much more) maybe from loadauras, when you revive I think you do a savetodb and insert the aura two times?

those auras only save in DB for owner: https://github.com/TrinityCore/TrinityCore/blob/3.3.5/src/server/game/Spells/Auras/SpellAuras.cpp#L1112

a temp solution can be don't save in DB those three auras at all.

[jackpoz]

GetTarget()->RemoveOwnedAura(_spellId, GetCasterGUID());

Probably this is not removing it.

[illfated]

Very good, thanks for the detailed follow-up.

[jackpoz]

cast paladin aura (by example 54043 Retribution Aura (Rank 7))
die (.damage 99999999)
logout and login
revive (.revive)

actually instead of revive one can just ".save" (in the Guild chat as one is dead) and repro the issue at every ".save"

[jackpoz]

@Jildor

    _LoadSpells(holder.GetPreparedResult(PLAYER_LOGIN_QUERY_LOAD_SPELLS));

    _LoadGlyphs(holder.GetPreparedResult(PLAYER_LOGIN_QUERY_LOAD_GLYPHS));
    _LoadAuras(holder.GetPreparedResult(PLAYER_LOGIN_QUERY_LOAD_AURAS), time_diff);

_LoadSpells() casts the talent that adds the aura and the RemoveOwnedAura() does nothing as auras are not loaded yet. Then _LoadAuras() adds the aura that was saved in the db without any check on "but I have already that aura"

void Unit::_AddAura(UnitAura* aura, Unit* caster)
{
    ASSERT(!m_cleanupDone);
    m_ownedAuras.emplace(aura->GetId(), aura);
    _RemoveNoStackAurasDueToAura(aura);

_RemoveNoStackAurasDueToAura checks only m_appliedAuras , not m_ownedAuras , so m_ownedAuras has 2 auras with same id and caster and target

[Jildor]

I don't know what commit could cause this problem, in rev about 2017 I can't reproduce it.
it must be caused near the date of this issue I suppose: #21486

[jackpoz]

Update: this works fine when being alive because the next update tick after both auras are added (from talent and from db load), _RemoveNoStackAurasDueToAura() kicks in and removes 1 of the 2.
What doesn't work when being dead is that the auras are in m_ownedAuras but not in m_appliedAuras (as the player is dead) and _RemoveNoStackAurasDueToAura() checks only m_appliedAuras, so it will never notice that m_ownedAuras contains duplicates.

One workaround could be to check m_ownedAuras too, either always or only when being dead