terminate called without an active exception #4306
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#4306
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 crashed us the server three times now, all since the 1.1.118 update. There was no timestamp, no nothing around
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:coal_lump" dropped at (2232,-26952,1314) by , 916.49 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "caverealms:glow_obsidian_2 15" dropped at (2246,-26951,1317) by , 850.39 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "caverealms:glow_obsidian_2 3" dropped at (2251,-26949,1324) by , 838.26 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:iron_lump 4" dropped at (2253,-26949,1324) by , 837.89 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:tin_lump 2" dropped at (2249,-26951,1316) by , 850.39 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "caverealms:glow_obsidian 22" dropped at (2246,-26947,1340) by , 849.62 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "caverealms:glow_obsidian 3" dropped at (2251,-26948,1330) by , 837.12 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:dirt" dropped at (2249,-26946,1342) by , 849.62 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:copper_lump 3" dropped at (2251,-26948,1330) by , 837.12 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:cobble 27" dropped at (2247,-26946,1337) by , 837.50 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:copper_lump 4" dropped at (2249,-26946,1336) by , 830.82 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:gravel 29" dropped at (2254,-26948,1330) by , 792.38 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:copper_lump" dropped at (2249,-26946,1341) by , 849.48 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] preparing to unload "default:iron_lump 20" dropped at (2251,-26949,1328) by , 830.82 seconds ago
2023-04-27 15:31:16: ACTION[Server]: [yl_commons] [builtin] about to remove "default:coal_lump" dropped by
2023-04-27 15:31:17: ACTION[Main]: Server: Shutting down
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:iron_lump 20" dropped at (2251,-26949,1328) by , 831.01 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:copper_lump" dropped at (2249,-26946,1341) by , 849.67 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:gravel 29" dropped at (2254,-26948,1330) by , 792.57 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:copper_lump 4" dropped at (2249,-26946,1336) by , 831.01 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:cobble 27" dropped at (2247,-26946,1337) by , 837.69 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:copper_lump 3" dropped at (2251,-26948,1330) by , 837.31 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:dirt" dropped at (2249,-26946,1342) by , 849.81 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "caverealms:glow_obsidian 3" dropped at (2251,-26948,1330) by , 837.31 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "caverealms:glow_obsidian 22" dropped at (2246,-26947,1340) by , 849.81 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:tin_lump 2" dropped at (2249,-26951,1316) by , 850.58 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "default:iron_lump 4" dropped at (2253,-26949,1324) by , 838.08 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "caverealms:glow_obsidian_2 3" dropped at (2251,-26949,1324) by , 838.45 seconds ago
2023-04-27 15:31:17: ACTION[Main]: [yl_commons] [builtin] preparing to unload "caverealms:glow_obsidian_2 15" dropped at (2246,-26951,1317) by , 850.58 seconds ago
terminate called without an active exception
2023-04-27 15:30:05: ACTION[Server]: [yl_commons] lua is using 867.3 MB
2023-04-27 15:30:15: ACTION[Server]: [yl_commons] lua is using 835.2 MB
2023-04-27 15:30:25: ACTION[Server]: [yl_commons] lua is using 787.6 MB
2023-04-27 15:30:35: ACTION[Server]: [yl_commons] lua is using 741.2 MB
2023-04-27 15:30:45: ACTION[Server]: [yl_commons] lua is using 695.5 MB
2023-04-27 15:30:55: ACTION[Server]: [yl_commons] lua is using 601.2 MB
2023-04-27 15:31:05: ACTION[Server]: [yl_commons] lua is using 523.5 MB
2023-04-27 15:31:14: ACTION[Server]: [yl_commons] lua is using 1068.4 MB
Those are the lines and timestamps (of the line before) when the error occurred:
There are various occurrences in the minetest issues that deal with a similar problem: https://github.com/minetest/minetest/issues?q=terminate+called+without+an+active+exception
https://github.com/minetest/minetest/issues/11731
https://github.com/minetest/minetest/issues/1413
https://irc.minetest.net/minetest/2021-02-14
The IRC link speaks of
"Hi there error: terminate called without an active exception, when copying the minetest.format_chat_message and redefining it."
Do we do that? Yes:
https://github.com/fluxionary/minetest-builtin_overrides/blob/main/fix_capitalization.lua#L35
Is this used anywhere? Yes:
arena_lib/src/chat.lua
arena_lib/src/commands.lua
Is this a new thing that changed between 1.1.117.1 and 1.1.118? Yes. We switched out arena_lib as a whole and started following upstream again.
There's also someone on discord with a similar problem
GreenXenith — 04/11/2022 04:18
Im trying to debug on_deactivate but its not being consistent
ok yeah
Apparently entity callbacks fail to pass exceptions through or something to that effect
GreenXenith — 04/11/2022 04:25
maybe only during load/unload
or freaking not
only in on_deactivate
I think this is reproducable:
If you manually deactivate it (punch it), youll get the foo error but also a segfault.
If you leave the game, it will segfault without the foo error
GreenXenith — 04/11/2022 04:34
which is super fun because I was testing the static props by leaving the game so it didnt tell me my boolean concat was invalid
anyway, I digress
Midnight — 04/11/2022 04:38
terminate called without an active exception
Is that what it's giving you too?
GreenXenith — 04/11/2022 04:38
yeah
I think on_deactivate is just buggy in general and I dont trust it >:(
wsor — 04/11/2022 04:39
sourcerykid code i think?
Midnight — 04/11/2022 04:39
I didn't test manually deactivating it, only leaving the game.
Midnight — 04/11/2022 04:40
who?
GreenXenith — 04/11/2022 04:40
it shouldnt segfault either way, but the fact that it doesnt give you lua error output on leave is just misleading 😩
Thank you luatic :D
Suggests to add this PR: https://github.com/minetest/minetest/pull/13468/files
So I did:
And another despite the bugfix:
Could be coincidence, but I keep seeing those:
[yl_commons] [builtin] preparing to unload "rainbow_source:black_water_source" dropped at (11662,29728,-11670) by <UNKNOWN>, 785.36 seconds agoevery time the server shuts down with this message.I changed this code recently, did I make a mistake?
93c9ab189ethese are both expected. as long as the crash isn't too severe, the server will disconnect all players, unload all entities, save the map, etc.. we've added logging about when dropped items are unloaded, hence all the logs about unloading them when the server is shutting down. what would be interesting to see is what appears above those lines.
https://github.com/minetest/minetest/pull/13468 is certainly one locus of bugs like this, the more general issue for discussing places where mods modify objects that c++ expects to have control over them is https://github.com/minetest/minetest/issues/13471
Ofc they are expected. What I meant is that the issue happens only after 1.1.118. For this milestone I changed something about the code logging the drops. The code you wrote before (1.1.117.1) for the logging didn't cause the issue. The code I wrote (1.1.118) might.
There were no similarities between all of those crashes in the "actions before", going back to 10 seconds before the crash.
we changed a lot of things w/ 1.1.118, i suppose it's worth reviewing though.
this code has several possible problems and is redundant. for one,
selfandself.object:get_luaentity()will always be the same table (as long asself.objectexists and hasn't been deactivated).self.namewill always just be"__builtin:item".self.objectshould exist, but then again, you'renil-checking it just a few lines above. this code also doesn't guarantee thatsisn'tnilor"".reading through the builtin code again, it appears that
self.itemstringis always set to""when the item is about to be removed (beforeself.object:remove()), which happens whenignorenode (e.g. the code that tries to move items out of a wall has pushed it into an unloaded area)also, it seems like this logging code logically belongs in the
on_deactivatecallback, instead ofget_staticdata- that's my fault, i wasn't aware ofon_deactivateuntil recently, though it's been in the engine since 5.4.0.i'm trying to update this logic according to the issues i've outlined, but at the moment i've found something interesting: the same error:
debug.txt:
console log:
this is the relevant upstream issue https://github.com/minetest/minetest/issues/8352
i reworked the log_item_despawn logic:
4f132a5958changes:
on_deactivateinstead ofget_staticdata, the latter is only used when unloading an item, not when removing ititemstringvalue will often be""for "legitimate" reasons when an object is being removed, grab the value ofself.object:get_properties().wield_itemin those casesxpcall, which will prevent any exceptions from crashing the server w/ an incomprehensible error messageexample log messages:
IMO important enough to warrant an early 1.1.119, wiht all the bugfixes we have so far.
Do we have a repro for testing purposes?
hmm. i can generate same the error, but i'm not 100% certain why it was occurring before. the issue is that an exception happens inside
on_deactivateorget_staticdata- we don't even know if the modifications to the builtin dropped items is the issue. we don't know what entity is triggering this, because the engine logging is terrible. i outlined a few possible causes but i never observed them in my own testing, i had to manually trigger the issue by e.g. usingerror()inside those callbacks.After the fix this has never surfaced again. Vote Close as fixed. Other opinions?
i say we close, we can always re-open or create a new issue if it occurs again.
something possibly related got fixed in the engine recently: https://github.com/minetest/minetest/pull/13635