StaticObjectList::insert(): id already exists #2716
Labels
No Label
1. kind/balancing
1. kind/breaking
1. kind/bug
1. kind/construction
1. kind/documentation
1. kind/enhancement
1. kind/griefing
1. kind/invalid
1. kind/meme
1. kind/node limit
1. kind/other
1. kind/protocol
2. prio/controversial
2. prio/critical
2. prio/elevated
2. prio/good first issue
2. prio/interesting
2. prio/low
3. source/art
3. source/client
3. source/engine
3. source/ingame
3. source/integration
3. source/lag
3. source/license
3. source/mod upstream
3. source/unknown
3. source/website
4. step/approved
4. step/at work
4. step/blocked
4. step/discussion
4. step/help wanted
4. step/needs confirmation
4. step/partially fixed
4. step/question
4. step/ready to deploy
4. step/ready to QA test
4. step/want approval
5. result/cannot reproduce
5. result/duplicate
5. result/fixed
5. result/maybe
5. result/wontfix
ugh/petz
ugh/QA main
ugh/QA NOK
ugh/QA OK
No Milestone
No project
No Assignees
2 Participants
Notifications
Due Date
No due date set.
Dependencies
No dependencies set.
Reference: your-land/bugtracker#2716
Loading…
Reference in New Issue
No description provided.
Delete Branch "%!s(<nil>)"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
this is really weird, i have no real theory, this should be reported upstream
Yes, it should, however MT core devs don't appear interested or encouraging:
There was no answer to my question, so I assume they can't do much with the little info I have.
i haven't done a thorough audit of the code, but i can't figure out how this would even happen. let's worry if it happens again.
It does:
2022-09-24 17:26:42: [Server]: ERROR: StaticObjectList::insert(): id already exists
2022-09-24 17:26:42: ERROR[Server]: In thread 7fd80e994640:
2022-09-24 17:26:42: ERROR[Server]: /home/mt/5.5.1/Minetest_live/src/staticobject.h:3f: void StaticObjectList::insert(irr::u16, const StaticObject&): A fatal error occurred: StaticObjectList::insert()
i'm guessing there's again a line like
2022-09-19 08:54:57: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=32251 on inactive block (277,1837,-1865)
just above; can you grep for whatever the object id is in the log and paste the results here?Looks like there were plenty, even more in the whole log.
i'm interested in the history of that specific ID during that specific running of the minetest(server) binary, not which other objects were saved to disk. i'm curious if we can see anything more about that specific object, including whether it was saved to disk earlier and somehow not removed. i don't think it's logged, but it'd be great if we could even learn what kind of object it was.
i may decide to refocus my energy onto engine stuff; improving the usability of logs is on my radar, there's not much we can do w/ just an id # from an ephemeral process.
2022-10-15 07:01:31: [Server]: ERROR: StaticObjectList::insert(): id already exists
2022-10-15 07:01:31: ERROR[Server]: In thread 7f8420e6b640:
2022-10-15 07:01:31: ERROR[Server]: /home/mt/5.6.1/Minetest_live/src/staticobject.h:3f: void StaticObjectList::insert(irr::u16, const StaticObject&): A fatal error occurred: StaticObjectList::insert()
given that object IDs are 16 bit, i wonder if the issue is that they eventually get re-used... though how likely is a collision within a specific mapblock?
out of curiosity, i ran a small script:
which returned
3441 65446
and2785 65462
on a couple runs. ids are definitely being re-used, but there should never be a case that multiple objects have the same ID, unless there's a bug. and i'd expect to see Problems well before things are being unloaded...2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43359 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43359
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43262 on inactive block (131,1,69)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43262
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43262 is known by clients; not deleting yet
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43261 on inactive block (131,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43261
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43261 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43261
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43260 on inactive block (131,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43260
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43260 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43260
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43259 on inactive block (131,0,69)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43259
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43259 is known by clients; not deleting yet
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43253 on inactive block (131,0,69)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43253
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43253 is known by clients; not deleting yet
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43252 on inactive block (131,0,69)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43252
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43252 is known by clients; not deleting yet
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43251 on inactive block (130,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43251
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43251 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43251
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43250 on inactive block (130,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43250
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43250 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43250
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43249 on inactive block (130,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43249
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43249 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43249
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43248 on inactive block (130,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43248
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43248 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43248
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43247 on inactive block (130,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43247
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43247 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43247
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43246 on inactive block (130,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43246
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43246 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43246
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43245 on inactive block (130,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43245
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43245 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43245
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): deactivating object id=43244 on inactive block (130,1,68)
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_deactivate: id=43244
2022-10-20 14:22:14: VERBOSE[Server]: ServerEnvironment::deactivateFarObjects(): object id=43244 is not known by clients; deleting
2022-10-20 14:22:14: VERBOSE[Server]: scriptapi_luaentity_rm: id=43244
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: VERBOSE[Server]: virtual void LuaEntitySAO::getStaticData(std::string*) const
2022-10-20 14:22:14: [Server]: ERROR: StaticObjectList::insert(): id already exists
2022-10-20 14:22:14: ERROR[Server]: In thread 7f5de7e88640:
2022-10-20 14:22:14: ERROR[Server]: /home/mt/5.6.1/Minetest_live/src/staticobject.h:3f: void StaticObjectList::insert(irr::u16, const StaticObject&): A fatal error occurred: StaticObjectList::insert()
Let's see what 43244 did ...
The place (130,1,68) hints at Haven, near the event area. There are no entities to be deleted??
However, when I tried to "remove objects" from this mapblock, 11 objects were removed
And again:
2022-10-20 16:06:09: [Server]: ERROR: StaticObjectList::insert(): id already exists
2022-10-20 16:06:09: ERROR[Server]: In thread 7f36fc959640:
2022-10-20 16:06:09: ERROR[Server]: /home/mt/5.6.1/Minetest_live/src/staticobject.h:3f: void StaticObjectList::insert(irr::u16, const StaticObject&): A fatal error occurred: StaticObjectList::insert()
The error happens here?
https://github.com/minetest/minetest/blob/master/src/staticobject.h#L63
In the function, the id is KNOWN: Why the duck do they not add it to the error message?
Would something like this work?
https://github.com/minetest/minetest/issues/12883
interesting. would be interesting to have a log of which mapblock was being unloaded. it sounds like the items that were being unloaded were drops spawned by enemies dying in the nether.
So, object with id 39117 is the culprit? Let's see what this obejct did. Oh. Ther are plenty with this same id?
two ideas:
change the config so that
active_block_range >= active_object_send_range_blocks
. increasingactive_block_range
(currently 1) will increase the costs of ABMs, while decreasingactive_object_send_range_blocks
will have a variety of effects.move this 1 line after the check of whether someone's still looking at the mob. markForDeactivation is what calls on_deactivate, there shouldn't be a problem.
If this is a programmatic problem, then why are we the only ones to have that error?
Do we have a repro?
What's the lifecycle stage the error happens? We could try to mass-create entities and let them despawn, if that's where it happens?
i have no idea, but i suspect it has something to do w/ how popular the server is and the quantity of entities we have, as well as the values we have for things like
active_block_range
andactive_object_send_range_blocks
. the real question is, why was this only started happening now? no-one has touched this code since before 5.4.0 was released.no, though i've got some ideas i'll try to enact on the test server.
basically, what's going on, is that every so often, the server checks to see which entities should be unloaded. the rules for that are complicated, but basically, entities get unloaded if they are (1) not inside of an active block, and (2) not visible to any players - within
active_object_send_range_blocks
and in the direction they are looking.as part of that process, the engine first checks to make sure that the entity's data is stored in the mapblock where it is located. however, somehow, the entity is already inside of that mapblock, which triggers the crash. the object itself doesn't seem to think it's stored there, which is confusing.
after reviewing things more, there's no chance that it's a separate entity w/ the same ID - entities are stored in a table indexed by ID, which is what's being iterated here.
@AliasAlreadyTaken upstream got closed because you didn't reply. not sure if you have time to take a look or even if the issue is still happening, which i presume it is.
I commented the upstream issue:
I'm not gone. I added the suggested logging statement to the server, but ofc the problem refused to happen ever since.
https://github.com/minetest/minetest/issues/12883
2023-01-14 21:56:34: [Server]: ERROR: StaticObjectList::insert(): id already exists, id=15613
2023-01-14 21:56:34: ERROR[Server]: In thread 7f5eb48aa6c0:
2023-01-14 21:56:34: ERROR[Server]: /home/mt/5.6.1/Minetest_live/src/staticobject.h:42: void StaticObjectList::insert(irr::u16, const StaticObject&): A fatal error occurred: StaticObjectList::insert()
2023-01-28 04:43:55: ERROR[Server]: In thread 7f5e4e4666c0:
2023-01-28 04:43:55: ERROR[Server]: /home/mt/5.6.1/Minetest_live/src/staticobject.h:42: void StaticObjectList::insert(irr::u16, const StaticObject&): A fatal error occurred: StaticObjectList::insert()
notes to self:
2023-06-08 21:31:56: [Server]: ERROR: StaticObjectList::insert(): id already exists
2023-06-08 21:31:56: ERROR[Server]: In thread 7fc42aca26c0:
2023-06-08 21:31:56: ERROR[Server]: /home/mt/5.7.0/Minetest_live/src/staticobject.h:3b: void StaticObjectList::insert(irr::u16, const StaticObject&): A fatal error occurred: StaticObjectList::insert()
put this code just below the
#include
s in "staticobject.h":in the same file, replace
StaticObjectList::insert
with the following:this should give us some extra information to use the next time this happens.
also, possibly, we can just log the error, ignore the duped item, and not crash?
@flux Could you please push the code to the yl_stable-5 branch of https://gitea.your-land.de/your-land/minetest/src/branch/yl_stable-5 , so that we can try it on the testserver and build to main?
done
c4ca8d53b6
i've compiled it and run it.
Testserver rebuilt with this fix. How do we test that?
we don't have a replication, so we wait. the server shouldn't crash w/ the change i pushed, so you should grep for that log message maybe like once a month or something.
Apparently I overlooked this issue after I rebuilt the testserver. As of today, the engine on main is rebuilt with this code
Ever since the introduction of the code, the error did not reoccurr.
hm. object IDs absolutely get re-used over the life of a single launch of the server. the max number of entities i've ever seen active at once has been less than 14 bits worth. i've read the code, and it should be deeply impossible to repeat IDs, but it's c++, so voodoo can't be excluded.
i'm wondering if entities that are loaded but not active can mess this counter up somehow? i've recently discovered that e.g. y_bows arrows don't get removed if everyone leaves the area - if you come back within a certain period of time, they're still there, even though static saving is entirely disabled,
let's give it until the next release (1.1.124?) before we close this.