Trinitycore: [3.3.5] - Random equipped items disappears

[Jildor]

Description:

I'm not sure what happens, but I have a lot of players reports months ago, the equipped items disappears when log in or log out.
Not related with crash or rollback.
The item disappear in DB from character_inventory but still in item_instance and not appear in mail_items

Anyone know anything about this problem??

In this rev the problem does not happen: d92d5c0d17c7bd3b03522c6146ba91d3adaea223

And here I nothiced the problem appear: 73ec3a1d3b34b31ae67ea4215ce3d25a2adf392b

Steps to reproduce the problem:

By the moment I don't know how to reproduce it.
Happens when players logout or login, I don't know

Branch(es): 3.3.5

TC rev. hash/commit: 445c5a00e8

TDB version: TDB335.63

Operating system: Debian

[Demonid]

I got this issue too, really annoying, from time to time items start to disappear from the inventory, i didn't check the DB, but this issue is for real.

[Keader]

I'm having the same issue too.

[Jildor]

Yep, I don't know what is the cause...no idea...but I think this need priority

[Takenbacon]

Log the output of the sql.sql logger in case it's some sort of database error.

https://github.com/TrinityCore/TrinityCore/blob/master/src/server/database/Database/MySQLConnection.cpp#L230

[Mack36]

Try to enable(if not yet) some worldserver logs, AFAIK there should be smth related to items loading in those:

• #Logger.entities.player.items
• #Logger.entities.player.loading
• #Logger.entities.player.character

[Jildor]

I found a lot Deadlocks related with character_inventory in the server.log
example

2017-08-06_00:56:33 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (138847, 14517911, 3, 267840328)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2017-08-06_00:56:33 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (138847, 14517911, 5, 267840390)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2017-08-06_00:56:33 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (138847, 14517911, 4, 267840362)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2017-08-06_00:56:34 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (138847, 14517911, 6, 267840420)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2017-08-06_01:24:08 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (400969, 267693315, 4, 267851505)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction

But these Deadlocks not are related with lost itemguids

grep -rin --color "ItemGuid" *.*

When a player change a item in a different slot in game, the core make a REPLACE in origin and destination.
Then, can be possible when a Deadlock occurs, the destination don't make a REPLACE??

And, why happens these Deadlocks??

[Jildor]

Does anybody know anything about this?
:S

[Solzz]

Quick update on this bug, I also got this issue but eventually got some Mail with the items in and the message in the mail was "there was an error equipping your items"

[Killyana]

Can you provide this values used in worldserver.conf
CharacterDatabase.WorkerThreads = ?
CharacterDatabase.SynchThreads = ?

[Solzz]

CharacterDatabase.WorkerThreads = 1
CharacterDatabase.SynchThreads = 2

The defaults

[Killyana]

We changed this config to:
CharacterDatabase.WorkerThreads =2
CharacterDatabase.SynchThreads =3

And we got a lot of Deadlooks and 4 or 5 players (at least) lost items (this items was looted after the config change)

Once we reverted the change no Deadlooks happen, and until now no item disappears.

[Rochet2]

It may be that there are two things here, one caused by changing the thread counts and another caused by the core code not being able to for example equip the item on the player for some reason.

I dont think changing worker threads from 1 is a good idea as I think this could possibly cause an item insert and delete to switch places so that an item is deleted and then inserted. This could cause crashes or incoherence. (In fact if this is the case, maybe the config option should be disabled or documented to warn about it?)

@Solzz Was the error "There were problems with equipping item(s)." or was it "There were problems with equipping one or several items"? I could not find other errors matching what you say.

The first error message should trigger entities.player to log an error message. Could you enable it and if this happens again then post the information what it logged to logs?
The log should have Player::_LoadInventory: Player '%s' (%s) has item (%s, entry: %u) which can't be loaded into inventory (Bag %u, slot: %u) by reason %u. Item will be sent by mail."

The second error message may also log something for example if you enable entities.player.items logging. But it doesnt seem to consistently log an error or warning when it occurs.

[Jildor]

ops, sorry, I had not noticed of the last comments.
I have:

CharacterDatabase.WorkerThreads = 12
CharacterDatabase.SynchThreads = 14

@Rochet2 here is the log xD
Edit: Deleted, not necessary ;)

@Shauren Do you know anything about this?
Any idea to find the problem?

[Killyana]

@Jildor This happen when your inventory is full and you're using the equipment manager, it's not an issue and the player will get this items back via the mail.

[Jildor]

@Killyana You're right, only I put the log that asks @Rochet2
(I'm going to edit the log, I think there are too many lines xD )

[Killyana]

Here some example of Deadlocks, but there's noting related to items: https://gist.github.com/Killyana/bba47d58a87d03be4fb1e73dd5f95b4b

[Solzz]

@Rochet2 Sorry I don't remember the error exactly but this wasn't an error in TC console or any logs this was what I got in the mail.

The mail body said basically I had issues equipping items along with the items that were missing (which was some legs)

The item that went missing wasn't in my bag but on my character and I just logged in and had seen it went missing and got that in game mail later.

[Rochet2]

@Jildor I was asking from solzz because you probably had more threads set and thus the likelihood of errors like this was higher for different reasons than what I was interested in.

I looked earlier and the deadlock handling in TC is basically just "try 6 times and forget", which means that if every time you get a deadlock then after all attempts the SQL query is not executed and core doesnt crash etc. This means no saving of an item for example. This is what I understood at least.
For example in Killyana's log item guid 473485 was probably never updated.

@Solzz The errors dont show up in logs because by default logs are disabled. Even if there is a mail, its probably not intended to mail items on a regular basis.
However it seems Killyana suggested that its a normal issue in https://github.com/TrinityCore/TrinityCore/issues/20106#issuecomment-332890876

[Solzz]

@Rochet2 I didn't have a full inventory and it was an item that I currently had equipped that was removed, also no addons completely clean client.

All I remember is I logged in and had the item equipped and then I shut the server down, later I booted TC back up and logged in and the item (legs) was gone.

A few restarts later I got an in-game mail saying that basically I had trouble equipping the item and here is your item back and within the mail was the legs item that was removed earlier.

[sirikfoll]

I'm also having this problems, if there are any logs to be add or patch that I can apply to help track down possible causes, just let me know :)

[Rochet2]

@sirikfoll Set all WorkerThreads to 1 and enable logging for player items and actions regarding items (like Logger.entities.player and Logger.entities.player.items).
See if the issue persists and in what way (are items mailed to the player, do items disappear on relog only?) and report back what the logs say and if issues persist and in what way and what you changed exactly if the situation got better.

The commit range given by Jildor is huge. There are almost 3000 commits between where he did not notice and where he noticed the problem. Narrowing this range down could be helpful.

[Killyana]

@Rochet2 we activated this logs and set WorkerThreads to 1 after that a player just lost 2 items ( via quest=12701 and quest=12706)
He equipped the 2 items and some minutes after that it disappears.
Nothing in the log about this player or the items.
We have an armory that confirm he get this items and nothing else.

[Keader]

Hmm it's happening even before 73ec3a1d3b34b31ae67ea4215ce3d25a2adf392b
I have a server running with last commit applied in 2017/03/23 and this happens too.

[Killyana]

A player lost an achievement, 1 hour after he get it the server crashs and once connected It was gone, it was the only player from the party other ones didn't lost it.

So probably the issue is not about items but insertion into the DB not done correctly.

[sirikfoll]

Could be totally unrelated, but there is some random issues that actually could be due to some more generic DB problem, like improper arena points distibution, disappearing instance cooldowns, disappearing learned recipes, and so forth..

[Jildor]

what can we do to find the problem?
it's frustrating.

btw I think this needs priority hight.

[Mack36]

Maybe there's smth in common with those disappeared items? For example, probably they all are 2H weapons, plate/mail type etc.

[Jildor]

Happens with any equipped item

[Killyana]

Interesting situation:
On gunship battle the 3 items were taken by the loot master (placed in his inventory), then distributed to 3 players, after the end of the raid this 3 items disappears. (Absolutely nothing appears in the logs)
We have just an armory and we can see this 3 players exchange this items:
Rastatouille a échangé l'objet : Protège-bras de chasseur du Fléau. Samedi 04 Novembre 2017 - 21h56
But in this case the loot master must also have the same log on his armory, but it's not the case.

Every time that an item disappear, this situation happens.

[Reforge-Mark]

this item disappearing issue has been going on for a few months now, but still no fix..

[Jildor]

I just ask (please do not kill me 😄)

Could it be possible that any of the following commits is related to this issue?

@Shauren commits about async query callback api (cherry-pick from master branch by @ariel- )
https://github.com/TrinityCore/TrinityCore/commit/b879a6cae5e31ef382a5b52fa19a726a061e9aca#diff-36cc11dd969eb02fb8677939f96c9cee
https://github.com/TrinityCore/TrinityCore/commit/8af3cccc83aa7fbda348a784e36f45331c091c9a#diff-36cc11dd969eb02fb8677939f96c9cee
https://github.com/TrinityCore/TrinityCore/commit/4c27203c8f36dd2a5df0a4ae69fbdc4c9140b29d#diff-36cc11dd969eb02fb8677939f96c9cee
https://github.com/TrinityCore/TrinityCore/commit/580f46693d4477cb4191137e6c1571d571f23b31#diff-36cc11dd969eb02fb8677939f96c9cee
https://github.com/TrinityCore/TrinityCore/commit/d7b02a0624682c36c79afbbe91742a52b79f193b#diff-36cc11dd969eb02fb8677939f96c9cee

@xinef1 Few small optimizations here and there
https://github.com/TrinityCore/TrinityCore/commit/b955456008191e60b6bda1f22e3486a3792b08db#diff-36cc11dd969eb02fb8677939f96c9cee
and Core/Loot: implement Loot Item Storage
https://github.com/TrinityCore/TrinityCore/commit/9dc3de10f0044c35a95e9b72e7b874f4b5b8e867#diff-c59edca94cdcc9d6c7296674c932be16

[Aokromes]

^^ I have seen items to disappear long time before 2016.

[Jildor]

@Aokromes, I can't confirm that, as I say in first comment in rev about feb 2016 the problem doesn't happen.

Maybe you see another problem.

I have all days players with this problem

[Killyana]

Also this issue is related to how looted item are stored or handled, players always loses looted items after the raid (Disconnect/reconnect)

[Keader]

Also this issue is related to how looted item are stored or handled, players always loses looted items after the raid (Disconnect/reconnect)

Players complain in my server that items looted years ago, vanishing too.
But 90% of complain is about new items.

[ariel-]

I dont think changing worker threads from 1 is a good idea as I think this could possibly cause an item insert and delete to switch places so that an item is deleted and then inserted

This is why you wrap deletions and insertions inside a transaction, so the relative order is respected (maybe what is missing here)

[Rochet2]

This is why you wrap deletions and insertions inside a transaction, so the relative order is respected (maybe what is missing here)

@ariel-
It is possible the code is missing transactions somewhere. But using multiple workerthreads and transactions are not related in my mind.

Consider two different transactions.
One that inserts a row. And one that deletes a row. They must be different transactions due to their nature (insert, delete). If they would be in a transaction the row would basically never really get saved to the database (insert and instantly delete the row).

When using 2 or more workers either of the transactions can execute first due to asynchronous nature. This means it is possible to delete the row first (does nothing) and then insert it. Result is that a row that was supposed to be deleted was not deleted.

[Jildor]

Sorry @Rochet2 (I don't understand very well) but what happens when is a REPLACE?, like my comment: https://github.com/TrinityCore/TrinityCore/issues/20106#issuecomment-320527788

[ariel-]

They must be different transactions due to their nature (insert, delete)

Not necessarily, most of the times this is used to cleanup data before saving new one. So the order must be precisely delete first, insert later.

If they would be in a transaction the row would basically never really get saved to the database (insert and instantly delete the row).

Transactions ensure relative order of the queries contained in it, even in a multithreaded environment.

So, deletions that must be done before insertions shall be on the same transaction, not different ones to prevent data problems (like in 569c64625d3778ee85516b897d2ac74272a6dd27)

[ghost]

What would happen if i change the number of the tries from 5 to 15 (for example)?
..\Transaction.cpp

bool TransactionTask::Execute()
{
    int errorCode = m_conn->ExecuteTransaction(m_trans);
    if (!errorCode)
        return true;

    if (errorCode == ER_LOCK_DEADLOCK)
    {
        // Make sure only 1 async thread retries a transaction so they don't keep dead-locking each other
        std::lock_guard<std::mutex> lock(_deadlockLock);
        uint8 loopBreaker = 15 /*5*/ ;  // Handle MySQL Errno 1213 without extending deadlock to the core itself
        for (uint8 i = 0; i < loopBreaker; ++i)
            if (!m_conn->ExecuteTransaction(m_trans))
                return true;
    }

    // Clean up now.
    m_trans->Cleanup();

    return false;
}

Could it minimize the problem of the deadlocks?

[Keader]

@Jildor : https://github.com/TrinityCore/TrinityCore/commit/b955456008191e60b6bda1f22e3486a3792b08db is a possibility

https://github.com/TrinityCore/TrinityCore/commit/9dc3de10f0044c35a95e9b72e7b874f4b5b8e867 <- was happening before this commit

[Jildor]

Yep, someone can put the core before this commit https://github.com/TrinityCore/TrinityCore/commit/b955456008191e60b6bda1f22e3486a3792b08db
Or atleast revert this commit and test ??

[ariel-]

1) please make PR
2) we don't usually use the 'using' keyword, and prefer fully scoped names
3) static analysis tools will complain for sleeping (and with reason!) with a locked mutex

[Langerz82]

hopefully Ive done the PR correct.

edit: closed PR - reason too many issues.

[jackpoz]

What would happen if i change the number of the tries from 5 to 15 (for example)?

increasing the counter (or the time allowed to deal with dead-locks) sounds like the right way to go, for example allowing max 60 seconds of retries before giving up.

Please keep in mind that a log about deadlock doesn't mean the transaction wasn't successfully executed later on next retry.

[Langerz82]

Try this patch and see how it goes, if all good ill do a PR.

See:
https://gist.github.com/Langerz82/56e9569617c4af871e2f1944f028ca6a

edit: @Jildor updated, thanks.
edit2: minor change:

+        uint32 loopDuration = 0;

[Jildor]

@Langerz82 I will try it, give me a few days for test it.

btw, here you forgot header:

diff --git src/server/database/Database/Transaction.cpp src/server/database/Database/Transaction.cpp
index 02c08f4b70..75d5c1e07f 100644
--- src/server/database/Database/Transaction.cpp
+++ src/server/database/Database/Transaction.cpp
@@ -19,9 +19,12 @@
 #include "MySQLConnection.h"
 #include "PreparedStatement.h"
 #include <mysqld_error.h>
+#include <Timer.h>

 std::mutex TransactionTask::_deadlockLock;

need #include "Log.h" for TC_LOG_*

[Langerz82]

PR: https://github.com/TrinityCore/TrinityCore/pull/21296

[ghost]

Deadlocks were not reported for missing items, or any of the other things. It's still an improvement though.

[Langerz82]

hopefully the logs will detect the deadlocks better and we will find some correlation to missing stuff.

[jackpoz]

does anyone know any addon that rearranges items in bags ?

[jackpoz]

2017-08-06_00:56:33 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (138847, 14517911, 3, 267840328)
[ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2017-08-06_00:56:33 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (138847, 14517911, 5, 267840390)
[ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction

I wonder how is that 2 different threads try to save the inventory of the same player at same time. It's like if Player::SaveToDb() got triggered twice in a very short time.

Edit: AH handler is a mess, HandleAuctionSellItem() for example queues multiple transactions on the same db/table in the same method (instead of queueing only ONE transaction). Addons that create actions of 1 stack with multistacks items will most likely cause a lot of character_inventory transactions and cause deadlocks.

[jackpoz]

Please note that because of the nature of how async queries are processed by multiple threads there is no guarantee the transactions will actually be executed in the correct order. It's possible that, give Save A and Save B in the queue and 2 async threads managing them, Save A could be executed after Save B, setting the DB to a different state than the ingame one.
I would strongly suggest to have a single async characters thread until a proper solution has been found (I had an idea long time ago to have queues for common "groups" instead of whole dbs, like items/instances/pets/etc)

[ghost]

does anyone know any addon that rearranges items in bags ?

I am using a discontinued simple 3.3.5a addon named BagSorter (could not find it in some simple Google searches).
Do you want gists of the Lua/TOC/XML files?

[jackpoz]

https://github.com/TrinityCore/TrinityCore/commit/54b0b8f5ead41f936b12e97d1b4fbacd9b89ab53 is supposed to handle better deadlocks

[Jildor]

The problem remains the same, I do not know if this can be helpful

2018-02-23_22:44:57 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (465748, 382642312, 10, 407960533)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-23_22:44:57 Transaction aborted. 11 queries not executed.
2018-02-23_22:44:57 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (465748, 382642312, 14, 407983222)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-23_22:44:57 Transaction aborted. 11 queries not executed.
2018-02-23_22:44:58 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (465748, 382642312, 14, 407983222)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-23_22:44:58 Transaction aborted. 11 queries not executed.
2018-02-23_22:44:58 Deadlocked SQL Transaction, retrying. Loop timer: 0 ms, Thread Id: 114518562297600

2018-02-25_14:20:25 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (502049, 452681495, 2, 461520535)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-25_14:20:25 Transaction aborted. 7 queries not executed.
2018-02-25_14:20:26 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (502049, 452681495, 3, 461521229)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-25_14:20:26 Transaction aborted. 7 queries not executed.
2018-02-25_14:20:26 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (502049, 452681495, 7, 461517325)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-25_14:20:26 Transaction aborted. 7 queries not executed.
2018-02-25_14:20:27 Transaction aborted. 7 queries not executed.
2018-02-25_14:20:27 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (502049, 452681495, 12, 461518335)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-25_14:20:27 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (502049, 452681495, 15, 461519952)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-25_14:20:27 Transaction aborted. 7 queries not executed.
2018-02-25_14:20:28 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (502049, 452682892, 6, 461519203)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-25_14:20:28 Transaction aborted. 7 queries not executed.
2018-02-25_14:20:29 SQL(p): REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (502049, 452682892, 6, 461519203)
 [ERROR]: [1213] Deadlock found when trying to get lock; try restarting transaction
2018-02-25_14:20:29 Transaction aborted. 7 queries not executed.
2018-02-25_14:20:29 Deadlocked SQL Transaction, retrying. Loop timer: 0 ms, Thread Id: 122850371286784

[jackpoz]

is that the full log ? if you look at https://github.com/TrinityCore/TrinityCore/commit/54b0b8f5ead41f936b12e97d1b4fbacd9b89ab53 you'll see it's not the same, I don't see any "Fatal deadlocked SQL Transaction, it will not be retried anymore" in your log but only "Deadlocked SQL Transaction, retrying." which means the transaction got retried and completed successfully.

[Jildor]

Fatal deadlocked SQL Transaction, it will not be retried anymore

This not appears in logs by the moment

[Jildor]

Definitely the message does not appear.

So, the problem can be caused when retries transaction, replace another value and item dissapear?
or is it not related with deadlock problem?

[Rochet2]

@Jildor From what killyana already said in https://github.com/TrinityCore/TrinityCore/issues/20106#issuecomment-333338887 to me it seems deadlocks are not the root cause. Worker threads 1 should cause a lot fewer deadlocks (though not eliminate them) as well as remove "happened before" problem from the async transactions.

Maybe we should try track down:

• if the item is ever saved
• if the item is ever deleted and from where in code
• if the item is ever modified and from where in code

Then when an item disappears we can see what all operations were done regarding it. For example, if the item is clearly deleted from DB through an SQL from a specific core method, we will know why the item went missing and have a lot smaller area of code to inspect.

Try enabling the sql.sql logging. Though I think it may be better to add a separate logging for this specific issue as the normal SQL log will get bloated from all not so relevant queries.
If the full SQL log is slow, then maybe Log.Async.Enable set to 1 helps with that.

[Jildor]

Try enabling the sql.sql logging. Though I think it may be better to add a separate logging for this specific issue as the normal SQL log will get bloated from all not so relevant queries.
If the full SQL log is slow, then maybe Log.Async.Enable set to 1 helps with that.

both are activated, but obviously, I can't enable in debug level, it's very heavy

[Rochet2]

Try using

#include "CharacterDatabase.h"
    if (m_connectionInfo.database == "<characters database name here>")
    {
        switch (stmt->m_index)
        {
            case CHAR_DEL_ITEM_INSTANCE:
            case CHAR_DEL_ITEM_INSTANCE_BY_OWNER:
            case CHAR_REP_ITEM_INSTANCE:
            case CHAR_UPD_ITEM_OWNER:
            case CHAR_UPD_ITEM_INSTANCE:

            case CHAR_DEL_CHAR_INVENTORY_BY_BAG_SLOT:
            case CHAR_DEL_CHAR_INVENTORY_BY_ITEM:
            case CHAR_DEL_CHAR_INVENTORY:
            case CHAR_REP_INVENTORY_ITEM:
            case CHAR_UPD_CHAR_INVENTORY_FACTION_CHANGE:
                TC_LOG_DEBUG("sql.debug", "[SQL] %s", m_mStmt->getQueryString().c_str());
            default:
                break;
        }
    }

next to TC_LOG_DEBUG("sql.sql", "[%u ms] SQL(p): %s" (there should be two of these).
It should log only relevant info and should thus be a lot lighter. Don't forget to enable the sql.debug logger.

[Jildor]

Ok, I will try it asap, give me a few days for try it

[Jildor]

Only a doubt, the main issue is the item not appears in character_inventory, but appears in item_instance, what about CHAR_INVENTORY* ??

[Rochet2]

Only a doubt, the main issue is the item not appears in character_inventory, but appears in item_instance, what about CHAR_INVENTORY* ??

I see. Then need to log those as well. Probably better get both. Edited the code above.

[Jildor]

thx, while I test the logs, can you verify that this change is correct? I have always had the doubt 😄
https://github.com/TrinityCore/TrinityCore/commit/b955456008191e60b6bda1f22e3486a3792b08db#diff-5589ee47b3a7ad220cff105a8fe7eac3R4095

[Shauren]

that part is only for sending SMSG_DESTROY_OBJECT when logging out, it has nothing to do with saving

[jackpoz]

@Rochet2 I would suggest database triggers to store in another table the history of items table

[Jildor]

Here I put a case:

The item appear in item_instance, but not in character_inventory or mail_items

PlayerGuid = 344930
ItemEntry = 50798
ItemGuid = 438052454

I have copied the important parts of the log, because it weighs more than 1 Gb 😄
https://gist.github.com/Jildor/ba5e37214fca1bec136f9298deaf6ece

As you can see, the item is equipped and unequipped several times, then maybe logout and ... I do not know

Edit: The player says, he used the equipment manager to enter the Bg, then left the Bg and changed his items again with the equipment manager, then he realized that an item was missing

[ghost]

@Jildor : Not to discourage you from using <Details> as a means of shortening any of your messages,
but that piece of code/text is not necessary to shorten (I removed <details> from your comment).
If you had added any of the gist logs in your comment, that would be worthy of shortening.

[Killyana]

@Jildor ask the player 344930 how he got the item, normal rand, or trade with another player.
Because almost all cases I got happens on raid items traded between players.

[Jildor]

@Killyana the item was obtained 2018-02-02 01:58:46
and here relevant info about item

     guid  itemEntry  owner_guid  creatorGuid  giftCreatorGuid  playedTime  
---------  ---------  ----------  -----------  ---------------  ------------
438052454      50798      344930            0                0       4420230

[ghost]

Ramaladni's Blade of Culling

• https://woehead.way-of-elendil.fr/?item=50798#contained-in-object
• https://woehead.way-of-elendil.fr/?object=202239 (Deathbringer's Cache)

So it is a raid reward from Icecrown Citadel (raid), Deathbringer's Cache.

[Rochet2]

@Jildor any possibility to get the full log? (Or one starting from the first occurrence of the item guid)
As it seems it was added to DB, the log must contain what deleted or replaced the item by GUID or playerguid+bag+slot combination.

[Jildor]

Yep, here is the full log (compressed in .rar)
https://mega.nz/#!DY8RRDxT!iMCzZlzRsaB3fWAMCk-w8c0VX8Qwp4llbkM2rhVjpdE

[Rochet2]

Here are the parts that I would consider to be relevant to the item that disappeared, hope it is useful.

The lines in the log that match to 344930, 207768363, 15, which is the guid, bag, slot combination that can be used for replacing or deleting the item:

Line 2846663: 2018-03-02_00:33:03 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 207768363, 15, 463929912)
Line 2974891: 2018-03-02_00:55:20 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 207768363, 15, 438052454)
Line 3764253: 2018-03-02_03:11:58 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 207768363, 15, 466002897)

The lines in the log that match the item guid 438052454:

Line 2683663: 2018-03-02_00:02:27 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 0, 16, 438052454)
Line 2683664: 2018-03-02_00:02:27 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454
Line 2775864: 2018-03-02_00:19:48 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 207768171, 4, 438052454)
Line 2775865: 2018-03-02_00:19:48 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454
Line 2868716: 2018-03-02_00:36:50 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 0, 16, 438052454)
Line 2868717: 2018-03-02_00:36:50 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454
Line 2891750: 2018-03-02_00:41:20 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 207768363, 16, 438052454)
Line 2891751: 2018-03-02_00:41:20 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454
Line 2900835: 2018-03-02_00:42:50 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 0, 16, 438052454)
Line 2900836: 2018-03-02_00:42:50 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454
Line 2910277: 2018-03-02_00:44:20 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 0, 16, 438052454)
Line 2910278: 2018-03-02_00:44:20 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454
Line 2918789: 2018-03-02_00:45:50 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 207768363, 16, 438052454)
Line 2918790: 2018-03-02_00:45:50 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454
Line 2928731: 2018-03-02_00:47:20 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 0, 16, 438052454)
Line 2928732: 2018-03-02_00:47:20 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454
Line 2974891: 2018-03-02_00:55:20 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 207768363, 15, 438052454)
Line 2974892: 2018-03-02_00:55:20 [SQL] UPDATE item_instance SET itemEntry = 50798, owner_guid = 344930, creatorGuid = 0, giftCreatorGuid = 0, count = 1, duration = 0, charges = '0 0 0 0 0 ', flags = 1, enchantments = '3789 0 0 0 0 0 3525 0 0 3525 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', randomPropertyId = 0, durability = 120, playedTime = 4420230, text = '' WHERE guid = 438052454

Lines matching the item guid 466002897 which replaced the missing item:

Line 3764253: 2018-03-02_03:11:58 [SQL] REPLACE INTO character_inventory (guid, bag, slot, item) VALUES (344930, 207768363, 15, 466002897)
Line 3764254: 2018-03-02_03:11:58 [SQL] REPLACE INTO item_instance (itemEntry, owner_guid, creatorGuid, giftCreatorGuid, count, duration, charges, flags, enchantments, randomPropertyId, durability, playedTime, text, guid) VALUES (47006, 344930, 0, 0, 1, 0, '0 0 0 0 0 ', 1, '0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ', 0, 0, 0, '', 466002897)

From the second log above, we can see that at 00:55:20 the item was lastly placed in the slot 344930, 207768363, 15.
From the first log above we can see that at 03:11:58 to the same slot the item GUID 466002897 is replaced.
This means that:

• The original item has been lost in this replace action.
• The timestamps are hours apart, so it is not likely that this has anything to do with SQL transactions being executed in wrong order.
• If the fix for deadlocks was in place, then it is not likely that deadlock causing SQL to never execute is the issue.

We can also see that:

• The missing item only uses UPDATE for item_instance, so the item existed before logging started, so issue not probably related to receiving an item.
• The item that replaced the missing item uses only REPLACE for item_instance and is thus a new item.
• The new item that replaced the missing item is http://www.wowhead.com/item=47006/kvaldir-war-horn so it is given when starting a quest.

Conclusion: core code has logic that allows a new item to replace an existing item - at least in DB.
The replace may happen because an item being moved around is not having its new location saved to the database or because new (quest) items consider filled slots empty.

If the issue has only occurred after relogging, the issue is likely only related to updating information to the database and the logic in core should otherwise be fine. _This would limit the issue only to moving items not having the new position saved to the database_.

[Jildor]

So, what should we do now?

Do you need more cases about missing items to search in the log?

Another case:
You can find in the same log put above ( https://mega.nz/#!DY8RRDxT!iMCzZlzRsaB3fWAMCk-w8c0VX8Qwp4llbkM2rhVjpdE )

the player says he lost the items on 02/03/2018 (yesterday) about 04:00h - 05:00h
the player does not know how it has been
PlayerGuid = 492901
The items appear in item_instance, but not in character_inventory or mail_items

     guid  itemEntry  owner_guid  
---------  ---------  ------------
301547503      50020        492901
427444171      40790        492901
427444179      40884        492901
427444201      40829        492901
427444214      40810        492901
427444216      42483        492901
427444219      40850        492901
427444223      40883        492901

[Rochet2]

So, what should we do now?

Any way to try confirm what causes the issue is good.
Also analyzing data we have and what we could gather more is good.

From the items you posted I can see that all items have been in a bag or just moved into a bag from an equipment slot. All of the items were armor or similar equipable items. All of the lost items seem to have been there on the last login before they went missing (not looted/created).

I tried tracing functions and containers to see if there was something missing, but all seems correct to me. Checked the usage of m_Items, FSetState, m_bagslot, SetSlot, SetContainer, SetState.

Not quite sure what exactly would be good to try to inspect.
Do you have "entities.player" logged (error level)? It seems that it has some good logs for example for when items cannot be loaded properly from DB.
Adding some log/assert to when items are saved in _SaveInventory could be good. For example, code that goes through all player's items and makes sure they are in the slots the items say they are in. And another check that I think could be very good is to go through all player's items and check that if their state is ITEM_CHANGED or ITEM_NEW they are in m_itemUpdateQueue of the player as otherwise they are not saved.

Example:

void Player::_SaveInventory(SQLTransaction& trans)
{
    auto notinupdatequeue = [&](Item* item) {
        if (item->IsBag())
            return false;
        if (item->GetState() != ITEM_NEW && item->GetState() != ITEM_CHANGED)
            return false;
        for (Item* queued : m_itemUpdateQueue)
            if (queued == item)
                return false;
        return true;
    };
    auto notcorrectslot = [&](Item* item) {
        return item != GetItemByPos(item->GetPos());
    };
    for (Item* item : m_items)
    {
        if (!item)
            continue;
        if (notinupdatequeue(item))
            ; // log something
        if (notcorrectslot(item))
            ; // log something

        if (Bag* bag = item->ToBag())
            for (uint32 slot = 0; slot < bag->GetBagSize(); ++slot)
                if (Item* bagitem = bag->GetItemByPos(slot))
                {
                    if (notinupdatequeue(bagitem))
                        ; // log something
                    if (notcorrectslot(bagitem))
                        ; // log something
                }
    }

[Jildor]

        if (notinupdatequeue(item))

when you logout with a bag (not default bag) with items, this check print log message about bag guid and entry, maybe needs better check auto notinupdatequeue ?

log example:

2018-03-04_10:30:34 Player::_SaveInventory: Player 'Jildor' (GUID Full: 0x00000000000d6e37 Type: Player Low: 880183) with values (Bag: 255, Slot: 19) for the item (ItemGuid: GUID Full: 0x4000000053498e89 Type: Item Low: 1397329545, ItemEntry: 23162, State: 1). notinupdatequeue
2018-03-04_10:31:43 Player::_SaveInventory: Player 'Jildor' (GUID Full: 0x00000000000d6e37 Type: Player Low: 880183) with values (Bag: 255, Slot: 19) for the item (ItemGuid: GUID Full: 0x4000000053498e89 Type: Item Low: 1397329545, ItemEntry: 23162, State: 1). notinupdatequeue
2018-03-04_10:31:43 Player::_SaveInventory: Player 'Jildor' (GUID Full: 0x00000000000d6e37 Type: Player Low: 880183) with values (Bag: 255, Slot: 19) for the item (ItemGuid: GUID Full: 0x4000000053498e89 Type: Item Low: 1397329545, ItemEntry: 23162, State: 1). notinupdatequeue (item->ToBag())
2018-03-04_10:31:43 Player::_SaveInventory: Player 'Jildor' (GUID Full: 0x00000000000d6e37 Type: Player Low: 880183) with values (Bag: 255, Slot: 19) for the item (ItemGuid: GUID Full: 0x4000000053498e89 Type: Item Low: 1397329545, ItemEntry: 23162, State: 1). notinupdatequeue (item->ToBag())
2018-03-04_10:32:09 Player::_SaveInventory: Player 'Jildor' (GUID Full: 0x00000000000d6e37 Type: Player Low: 880183) with values (Bag: 255, Slot: 19) for the item (ItemGuid: GUID Full: 0x4000000053498e89 Type: Item Low: 1397329545, ItemEntry: 23162, State: 1). notinupdatequeue
2018-03-04_10:32:27 Player::_SaveInventory: Player 'Jildor' (GUID Full: 0x00000000000d6e37 Type: Player Low: 880183) with values (Bag: 255, Slot: 20) for the item (ItemGuid: GUID Full: 0x4000000053498e8a Type: Item Low: 1397329546, ItemEntry: 23162, State: 1). notinupdatequeue
2018-03-04_10:32:27 Player::_SaveInventory: Player 'Jildor' (GUID Full: 0x00000000000d6e37 Type: Player Low: 880183) with values (Bag: 255, Slot: 20) for the item (ItemGuid: GUID Full: 0x4000000053498e8a Type: Item Low: 1397329546, ItemEntry: 23162, State: 1). notinupdatequeue (item->ToBag())
2018-03-04_10:32:27 Player::_SaveInventory: Player 'Jildor' (GUID Full: 0x00000000000d6e37 Type: Player Low: 880183) with values (Bag: 255, Slot: 20) for the item (ItemGuid: GUID Full: 0x4000000053498e8a Type: Item Low: 1397329546, ItemEntry: 23162, State: 1). notinupdatequeue (item->ToBag())

[Rochet2]

when you logout with a bag (not default bag) with items, this check print log message about bag guid and entry, maybe needs better check auto notinupdatequeue ?

Seems when player logs in we do not add items to update queue but we do set their state.
When an item is added to a bag on login it changes bag state to changed, but the bag is not added to the queue.
Since bags are not the focus of being missing I guess we could just exclude them from being logged.
I changed the code above to exclude bags and fixed it to log bagitem instead of item in the lowest for loop.

[Jildor]

Thanks, give me a few days to try

Just one question, the previous log about sql.debug is still necessary?

[Rochet2]

Just one question, the previous log about sql.debug is still necessary?

Not really for now. (at least for me)
But it could be good to have the entities.player and or entities.player.items logged. At least on the error level.

[Jildor]

Another case:

     guid  itemEntry  owner_guid  
---------  ---------  ------------
361678186      50991        137951
371642399      49997        137951
371642400      51216        137951
371642402      51901        137951

log is a appender combined with:
entities.player
entities.player.items
and your Player::_SaveInventory log
(Loglevel error)

https://mega.nz/#!uF81xQjR!_Vj5vHXMk4zwq95fMewKHLBSxZyfKfFqtn4b2BtWj1s

I do not see anything in the log

[Killyana]

I got some items that disappear when they are equipped, not only in bags.

[Foereaper]

This just happened to one of our players as well, item still exists in item_instance but not in the players inventory and not showing on .list item, this was item 52019, the player had the item equipped, it disappeared after a random core crash and subsequent login

[illfated]

I have not noticed this issue myself, but maybe those of you who mostly only lose items from the bags want to test this addon, BagSorter. It consists of 5 text files and works at least for the 3.3.5a game client:

• https://gist.github.com/illfated/825dc7e70eeb71161c799fc54a5bdbbc#file-bagsorter-lua
• https://gist.github.com/illfated/63b266df4c5a15d22748001b57609208#file-bagsorter-toc
• https://gist.github.com/illfated/e4a1c482dfd95995d95c231af63d5003#file-bagsorter-xml
• https://gist.github.com/illfated/7b17d20e5725b52911295c86684ee68a#file-bagsortinit-lua
• https://gist.github.com/illfated/84f9b032573e85481cf63d6c5406486f#file-sortfunctions-lua

The main command to sort bag items is /bs (operates both on player bank and player bags) - maybe it helps for some users.
I have not seen it on web lately, but maybe it could be found in the Curse client (I have not checked since 2015).

[Jildor]

Anyone know anything about this?
Can you think of anything else to try?

[illfated]

Sorry, I don't have any suggestions. I only play alone on my own PC and I have not seen this issue lately, so I have not been concerned about it. I update my core almost every time there are new commits, so I have not thought about this issue since April.

[jackpoz]

Unless anyone wants to properly debug this issue, I guess we can blame it on the item PR merged some time ago and revert it (and see what happens)

[Jildor]

@jackpoz
What PR do you mean?

[sanctum32]

Hello, in my own server, there was issues with character_aura table, for example, we have fury warrior and he applied berserker enchant on his weapons. If both procs are active, on logout, core will try to save them both, but KEYs returns queries transaction and others queries because of its dublicate entry error. actually just used REPLACE INTO statement instead of DELETE + INSERT there. After this change, most of item loss issues was gone

[illfated]

Interesting point. Would be nice to verify if the issue is caused by DB transactions.

[Jildor]

jummm, funny.
So, you are saying if make this change:

diff --git a/src/server/database/Database/Implementation/CharacterDatabase.cpp b/src/server/database/Database/Implementation/CharacterDatabase.cpp
index b83be67c109e..bf2bb872652c 100644
--- a/src/server/database/Database/Implementation/CharacterDatabase.cpp
+++ b/src/server/database/Database/Implementation/CharacterDatabase.cpp
@@ -497,6 +497,7 @@ void CharacterDatabaseConnection::DoPrepareStatements()
     PrepareStatement(CHAR_DEL_CHARACTER, "DELETE FROM characters WHERE guid = ?", CONNECTION_ASYNC);
     PrepareStatement(CHAR_DEL_CHAR_ACTION, "DELETE FROM character_action WHERE guid = ?", CONNECTION_ASYNC);
     PrepareStatement(CHAR_DEL_CHAR_AURA, "DELETE FROM character_aura WHERE guid = ?", CONNECTION_ASYNC);
+    PrepareStatement(CHAR_REP_CHAR_AURA, "REPLACE INTO character_aura (guid, casterGuid, spell, effectMask, recalculateMask, stackCount, amount0, amount1, amount2, base_amount0, base_amount1, base_amount2, maxDuration, remainTime, remainCharges, critChance, applyResilience) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)", CONNECTION_ASYNC);
     PrepareStatement(CHAR_DEL_CHAR_GIFT, "DELETE FROM character_gifts WHERE guid = ?", CONNECTION_ASYNC);
     PrepareStatement(CHAR_DEL_CHAR_INSTANCE, "DELETE FROM character_instance WHERE guid = ?", CONNECTION_ASYNC);
     PrepareStatement(CHAR_DEL_CHAR_INVENTORY, "DELETE FROM character_inventory WHERE guid = ?", CONNECTION_ASYNC);
diff --git a/src/server/database/Database/Implementation/CharacterDatabase.h b/src/server/database/Database/Implementation/CharacterDatabase.h
index b314014c9882..7d238eadd175 100644
--- a/src/server/database/Database/Implementation/CharacterDatabase.h
+++ b/src/server/database/Database/Implementation/CharacterDatabase.h
@@ -421,6 +421,7 @@ enum CharacterDatabaseStatements : uint32
     CHAR_DEL_CHARACTER,
     CHAR_DEL_CHAR_ACTION,
     CHAR_DEL_CHAR_AURA,
+    CHAR_REP_CHAR_AURA,
     CHAR_DEL_CHAR_GIFT,
     CHAR_DEL_CHAR_INSTANCE,
     CHAR_DEL_CHAR_INVENTORY,
diff --git a/src/server/game/Entities/Player/Player.cpp b/src/server/game/Entities/Player/Player.cpp
index 7f37550b0f9b..e28b12f4635f 100644
--- a/src/server/game/Entities/Player/Player.cpp
+++ b/src/server/game/Entities/Player/Player.cpp
@@ -19492,10 +19492,6 @@ void Player::_SaveActions(SQLTransaction& trans)

 void Player::_SaveAuras(SQLTransaction& trans)
 {
-    PreparedStatement* stmt = CharacterDatabase.GetPreparedStatement(CHAR_DEL_CHAR_AURA);
-    stmt->setUInt32(0, GetGUID().GetCounter());
-    trans->Append(stmt);
-
     for (AuraMap::const_iterator itr = m_ownedAuras.begin(); itr != m_ownedAuras.end(); ++itr)
     {
         if (!itr->second->CanBeSaved())
@@ -19525,7 +19521,7 @@ void Player::_SaveAuras(SQLTransaction& trans)
         }

         uint8 index = 0;
-        stmt = CharacterDatabase.GetPreparedStatement(CHAR_INS_AURA);
+        stmt = CharacterDatabase.GetPreparedStatement(CHAR_REP_CHAR_AURA);
         stmt->setUInt32(index++, GetGUID().GetCounter());
         stmt->setUInt64(index++, itr->second->GetCasterGUID().GetRawValue());
         stmt->setUInt32(index++, itr->second->GetId());

the problem dissapears?

[Shauren]

No, failing to save auras like that would fail entire save transaction, implying a rollback to previous state. Thats different than what you described in this issue (vanishing only from character_inventory)

Yes, auras should be fixed but it won't fix this issue

[Jildor]

then it does not seem to be the cause 😢

anyway, change del+ins to rep, it's better and should be added there?

[Shauren]

No, because for the case described in this comment https://github.com/TrinityCore/TrinityCore/issues/20106#issuecomment-437315125 it would mean losing one of the auras - and that is not a good thing

[Keader]

Why it need be unique anyway?

[Jildor]

Player::_SaveAuras is executed in Player::SaveToDB
So, can be possible when occurs PlayerSaveInterval (every 90 seconds), if happens the problem with dupe aura KEY, can occurs the issue?

[Keader]

if has no dupicated key, issue will not happen ^^

[sanctum32]

@Jildor i want to correct myself, no, keep delete statement, realised that data still needs to be cleared before pushing data or old data would cause issues... there also was similar issue to groups tables too. For example, player joins to raid group (doesn't enters to raid dungeons or etc actually, but just raid group) and he meanwhile wents to bg. That player isn't removed from first raid but he is in new bg group already. At this points, he has two raid groups and primal keys again gives errors when plr logouts at bg (2x groups at same time).
After all guys, just do such tests as i mentioned and you should reproduce this issue

[Jildor]

So, you are saying, when one those of two errors happens, has a chance to occur a lose item issue?

Maybe we need create two issues, one for character_aura duplicate key and another issue for the problem of group, can be a group_member duplicate key issue? I'm not sure about this.

@sanctum32 can you create the two issue, please?

[sanctum32]

uhm, well, i'm not familar with trinitycore issue report standarts but will do later, i'm still busy with other stuff. When one of these transaction queries fails there, whole transaction is returned, so imagine, items data query was after these queries which failed, so old data is kept and new data is gone because of errors...

[TheWinchesters]

I have this problem too, randomly as everyone else.
But, I have a weird issue related to this: If some event is active (Halloween as example) and the core, for some reason I do not know (Maybe a crash or server restart during the event), tries to insert duplicated entries in the character_queststatus_seasonal. Sometimes with the correct event_id, sometimes with event_id = 0.
Characters who have entries in that table with event_id "0" start losing items.

[Shauren]

Auras should be fixed now by be47254a4f7ac9fd0497477a597e2a09019561e9

[jackpoz]

@sanctum32 could you post a log of the error ? Do you have clean TC (or repro'ed the issue on clean TC) ?

[Jildor]

Is easy to reproduce @jackpoz get a fury warrior with titan grip, equip 2 weapons and enchant with berserker, go to dummies and Spam whirlwind with .cheat cooldown and .mod rage 1000
When you have 2 auras, logout and see dblog error

[Killyana]

This log is before shauren commit:

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 (52, 52, 59620, 3, 3, 1, 400, -5, 0, 399, -6, 0, 15000, 14899, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '52-52-0-59620-3' 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 (52, 52, 59620, 3, 3, 1, 400, -5, 0, 399, -6, 0, 15000, 9908, 0, 0, 1)
 [ERROR]: [1062] Duplicate entry '52-52-0-59620-3' for key 'PRIMARY'

EDIT: No errors after shauren's commit

[Killyana]

A player bought 13 Primordial Saronite he put one on the Auction House and disconnected with 12 on his bags, once reconnected the 12 Primordial Saronite disappears, they still visible on item_instance:

[Jildor]

@Killyana could you check your dberror log?
Maybe it has a error duplicate entry in some auctionhouse table like old character_aura error?

[Killyana]

Already did, there's absolutely nothing on server.log and dberror.log

The player has only one free slot on his bag, don't know if it's related

[TheWinchesters]

I do not know if it is useful, but to those players who from time to time have an item disappear from their character, I have given them a copy of their character (pdump) and since they use that copy, they have not reported any more loss of items.

[jackpoz]

if someone has time please check different commit versions to see when the issue started happening

[Killyana]

It's weird that in the last 4 months no one complains about this issue, generally it happen when it's fixed or a hack is posted somewhere.

[Jildor]

Fixing the aura item problem by Shauren the issue has been reduce a lot, maybe the problem described by @killyana is related with 2286da2

[Aokromes]

nope, your ticket is before that commit.

[Jildor]

And maybe the issue that describes @killyana appear after that commit, what is the problem? You can't evade it xD

[Killyana]

No, there's 4 commits that could be the cause of the issue if it still happens:
https://github.com/TrinityCore/TrinityCore/commit/2412886ef69d305df1bd6e6422ca3134c0ab1449
https://github.com/TrinityCore/TrinityCore/commit/ae9d01a3245c59a8a8d50516a79b79250337450d
https://github.com/TrinityCore/TrinityCore/commit/14dfc377b48bc909894396e65d4e4ce89d9708b6
https://github.com/TrinityCore/TrinityCore/commit/9dc3de10f0044c35a95e9b72e7b874f4b5b8e867

[jackpoz]

do the items have anything in common ?
The issue description has

The item disappear in DB from character_inventory but still in item_instance and not appear in mail_items

does this still apply ? that makes it easy to spot items with a simply query

[Aokromes]

maybe this is related to this bug https://github.com/TrinityCore/TrinityCore/issues/22234

[Killyana]

This issue happen generally for items looted on raid, the item will disappear from the bag when the player disconnects but it will remains on item_instance table as long as the bag slot is not used by an other item.

But this could also happen when a player move some items in the bag like explained here https://github.com/TrinityCore/TrinityCore/issues/20106#issuecomment-441394642

[jackpoz]

do they disappear only until first logout after looting them in the raid ?

[Killyana]

Only after first logout, also the item could disappear even if it's equipped.

[boom8866]

Replacement character lost items,This happens on servers where the data is too large

[Keader]

I dont get any new report in wow br, after fix aura save issue (auras like 2 berserk)

[Jildor]

The problems with items that disappear in DB from character_inventory but still in item_instance has been fixed by shauren fix aura saves.

But continue another unknown problem that disapear equiped items without any data in any db table about item, like @killyana say

[Killyana]

No I didn't noticed any issue about items disappearing since Shauren's fix.
My comment was just a precision about the issue, that even if the item is equipped it could disappear.
I think we could close this issue as it no longer happen since Shauren's fix.

[Jildor]

Well, if someone finds any way of how to reproduce any problem about loss items, can create a new issue, I will close this, since the main problem described in the issue was solved

[jackpoz]

Riztazz> jackpoz: https://github.com/TrinityCore/TrinityCore/issues/20106
you can do that by splitting items and then putting one stack of it on ah
probably anything that changes states and then item save is called will make the item disappear after relog

[calaluis]

Hello dears,

Through this channel, I would like to report an anomaly similar to that reported, with reliable evidence of what happened. It was not easy to locate the event causing the anomaly, to reproduce it and create a demonstration video.

I hope it works, because if you don't have enough space with inventory bags, the item is lost.

Link: https://youtu.be/Evlr2hPFF2k

[Killyana]

@calaluis this is a different issue, better to open a new ticket

[calaluis]

@calaluis this is a different issue, better to open a new ticket

Thanks for the guidance. Ticket created.

https://github.com/TrinityCore/TrinityCore/issues/24941