0.4.13 server crash: assertion failed in serialize.h:265

[zzantozz]

Is the bug reproducible?
Not so far.

How can you reproduce the bug?

What is your operating system?
Ubuntu 15.04 64-bit
Except one client is a running LXDE, an Ubuntu 14 variant, but it wasn't connected the last time the server crashed.

What is your version of Minetest?
0.4.13

What game do you use? (e.g. minetest_game, MiniTest, dwarves)
minetest_game

I started running a minetest server for my kids (well... mostly...) a couple weeks ago. I started out with a vanilla 0.4.11 server on an ubuntu machine. I added some simple mods a few at a time, and everything was working fine. Yesterday, I upgraded the server and all clients to 0.4.13 via the PPA because some mods needed it. With that change and some new mods, I'm getting the below crash. It's happened 3 times in the past day, always the same-ish message, or at least an assertion error on the same line. The last time it happened, I was running the server with --trace, and I've included a handful of lines preceding the crash from the log. Is this the same level of detail as the "debug_log_level = 4" mentioned in the bug reporting guide? I can add that setting to the server.

I know that the next logical troubleshooting steps would be to start removing mods and see what's causing the problem, but I'm hoping someone can help me narrow down the problem and/or make it more repeatable because the crash is unpredictable. Sometimes the game will run fine for hours. The last time, it crashed within a minute.

Your phone or window isn't wide enough to display the code box. If it's a phone, try rotating it to landscape mode.

Code: Select all

2015-09-07 11:23:04: VERBOSE[ConnectionSend]: con(5/1)   channel: 1, peer quota:512
2015-09-07 11:23:04: VERBOSE[ConnectionSend]:                   reliables on wire: 0, waiting for ack for 0
2015-09-07 11:23:04: VERBOSE[ConnectionSend]:                   incoming_reliables: 0, next reliable packet: 65517, next queued: 0
2015-09-07 11:23:04: VERBOSE[ConnectionSend]:                   reliables queued : 0
2015-09-07 11:23:04: VERBOSE[ConnectionSend]:                   queued commands  : 0
2015-09-07 11:23:04: VERBOSE[ConnectionSend]: con(5/1)   channel: 2, peer quota:512
2015-09-07 11:23:04: VERBOSE[ConnectionSend]:                   reliables on wire: 0, waiting for ack for 0
2015-09-07 11:23:04: VERBOSE[ConnectionSend]:                   incoming_reliables: 0, next reliable packet: 746, next queued: 0
2015-09-07 11:23:04: VERBOSE[ConnectionSend]:                   reliables queued : 0
2015-09-07 11:23:04: VERBOSE[ConnectionSend]:                   queued commands  : 0
5 <- 192.168.1.135:b37b, size=2e, data= 4f45 7403 0003 0001 0023 fff7 1cf1 0000 4844 0004...
2015-09-07 11:23:04: VERBOSE[ConnectionReceive]: con(5/1)RETURNING TYPE_ORIGINAL to user
2015-09-07 11:23:04: VERBOSE[ConnectionReceive]: con(5/1) ProcessPacket from peer_id: 3,channel: 0, returned 38 bytes
2015-09-07 11:23:04: VERBOSE[ServerThread]: con(5/1): Receive: got event: CONNEVENT_DATA_RECEIVED
minetest: /build/minetest-xOOHPg/minetest-0.4.13/src/util/serialize.h:265: void writeF1000(irr::u8*, irr::f32): Assertion `i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))' failed.


[zzantozz]

It has become somewhat reproducible. It crashed again while fighting a fireball-hurling mob underground. It crashed during the fight, and now it crashes immediately when a player joins. It seems to me like it's trying to assign fire damage to something, and then it crashes. It's happened several times in a row just like this:

Your phone or window isn't wide enough to display the code box. If it's a phone, try rotating it to landscape mode.

Code: Select all

2015-09-07 12:44:46: ACTION[main]: WARNING: Mod name conflict detected: "beds"
2015-09-07 12:44:46: ACTION[main]: Will not load: /usr/share/minetest/games/minetest_game/mods/beds
2015-09-07 12:44:46: ACTION[main]: Overridden by: /home/ryan/.minetest/mods/beds
2015-09-07 12:44:46: ACTION[main]: [MOD]craft_guide -- loaded from /home/ryan/.minetest/mods/craft_guide
[Gems] Loaded!
[Mod]Bees Loaded!
[Mod]Beeswax Candles Loaded!
2015-09-07 12:44:46: ACTION[main]:         .__               __                   __   
2015-09-07 12:44:46: ACTION[main]:   _____ |__| ____   _____/  |_  ____   _______/  |_
2015-09-07 12:44:46: ACTION[main]:  /     \|  |/    \_/ __ \   __\/ __ \ /  ___/\   __\
2015-09-07 12:44:46: ACTION[main]: |  Y Y  \  |   |  \  ___/|  | \  ___/ \___ \  |  | 
2015-09-07 12:44:46: ACTION[main]: |__|_|  /__|___|  /\___  >__|  \___  >____  > |__| 
2015-09-07 12:44:46: ACTION[main]:       \/        \/     \/          \/     \/       
2015-09-07 12:44:46: ACTION[main]: World at [/home/ryan/.minetest/worlds/server]
2015-09-07 12:44:46: ACTION[main]: Server for gameid="minetest" listening on 0.0.0.0:30000.
2015-09-07 12:45:15: ACTION[ServerThread]: ryan [192.168.1.134] joins game.
2015-09-07 12:45:15: ACTION[ServerThread]: ryan joins game. List of players: ryan
2015-09-07 12:45:17: ACTION[ServerThread]: ryan leaves game. List of players:
2015-09-07 12:45:17: ACTION[ServerThread]: LuaEntitySAO at (16,-116.5,-233) punched by LuaEntitySAO at (16.2,-116.2,-233.2), damage 4 hp, health now 25 hp
minetest: /build/minetest-xOOHPg/minetest-0.4.13/src/util/serialize.h:265: void writeF1000(irr::u8*, irr::f32): Assertion `i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))' failed.


[Morn76]

Already dicussed here: viewtopic.php?f=6&t=13177

[zzantozz]

Oops, sorry I missed that in my search. Thanks for the pointer. Is there a conventional way to mark this solved?

[TenPlus1]

type: /teleport 90000,10,90000 and it'll bring up the same error, so the updatelistener bug which drops a player through the world will cause this error to appear also...

[est31]

can you try to run minetest in gdb? e.g. gdb minetest --verbose? gdb has an according ubuntu package, just install it. If it crashes, you can type "bt" or "bt full", and it gives you a backtrace, which is very useful for development. You can quit gdb with "q"

[zzantozz]

can you try to run minetest in gdb? e.g. gdb minetest --verbose? gdb has an according ubuntu package, just install it. If it crashes, you can type "bt" or "bt full", and it gives you a backtrace, which is very useful for development. You can quit gdb with "q"

Sure, I'll give that a shot.

[TenPlus1]

Does this help (would not let me run with --verbose though):

Your phone or window isn't wide enough to display the code box. If it's a phone, try rotating it to landscape mode.

Code: Select all

Command name abbreviations are allowed if unambiguous.
(gdb) run
Starting program: /usr/bin/minetest
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7fffd67fc700 (LWP 3109)]
[Thread 0x7fffd67fc700 (LWP 3109) exited]
2015-09-10 21:02:05: ACTION[Main]: WARNING: Mod name conflict detected: "sethome"
2015-09-10 21:02:05: ACTION[Main]: Will not load: /usr/share/minetest/games/minetest_game/mods/sethome
2015-09-10 21:02:05: ACTION[Main]: Overridden by: /home/john/.minetest/mods/sethome
2015-09-10 21:02:05: ERROR[Main]: The following mods could not be found: "crafting"
[MOD] Mobs Redo loaded
2015-09-10 21:02:06: ACTION[Main]:         .__               __                   __   
2015-09-10 21:02:06: ACTION[Main]:   _____ |__| ____   _____/  |_  ____   _______/  |_
2015-09-10 21:02:06: ACTION[Main]:  /     \|  |/    \_/ __ \   __\/ __ \ /  ___/\   __\
2015-09-10 21:02:06: ACTION[Main]: |  Y Y  \  |   |  \  ___/|  | \  ___/ \___ \  |  | 
2015-09-10 21:02:06: ACTION[Main]: |__|_|  /__|___|  /\___  >__|  \___  >____  > |__| 
2015-09-10 21:02:06: ACTION[Main]:       \/        \/     \/          \/     \/       
2015-09-10 21:02:06: ACTION[Main]: World at [/home/john/.minetest/worlds/v7]
2015-09-10 21:02:06: ACTION[Main]: Server for gameid="minetest" listening on 0.0.0.0:58043.
2015-09-10 21:02:09: ACTION[Server]: singleplayer [127.0.0.1] joins game.
2015-09-10 21:02:09: ACTION[Server]: singleplayer joins game. List of players: singleplayer
minetest: /build/minetest-eSLhgt/minetest-201509101902/src/util/serialize.h:265: void writeF1000(irr::u8*, irr::f32): Assertion `i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))' failed.
[New Thread 0x7fffe4f6a700 (LWP 3115)]
[New Thread 0x7fffbddf3700 (LWP 3121)]
[New Thread 0x7fffbe5f4700 (LWP 3120)]
[New Thread 0x7fffbedf5700 (LWP 3119)]
[New Thread 0x7fffbf7fe700 (LWP 3118)]
[New Thread 0x7fffbffff700 (LWP 3117)]
[New Thread 0x7fffd4ff0700 (LWP 3116)]
[New Thread 0x7fffd7fff700 (LWP 3114)]
[New Thread 0x7fffd77fe700 (LWP 3113)]
[New Thread 0x7fffe586c700 (LWP 3112)]
[New Thread 0x7fffd6ffd700 (LWP 3111)]

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffe4f6a700 (LWP 3115)]
0x00007ffff4fd6267 in __GI_raise (sig=sig@entry=6)
    at ../sysdeps/unix/sysv/linux/raise.c:55
55   ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  0x00007ffff4fd6267 in __GI_raise (sig=sig@entry=6)
    at ../sysdeps/unix/sysv/linux/raise.c:55
#1  0x00007ffff4fd7eca in __GI_abort () at abort.c:89
#2  0x00007ffff4fcf03d in __assert_fail_base (
    fmt=0x7ffff5131028 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
    assertion=assertion@entry=0x84baa0 "i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))",
    file=file@entry=0x84ba58 "/build/minetest-eSLhgt/minetest-201509101902/src/util/serialize.h", line=line@entry=265,
    function=function@entry=0x84bb60 "void writeF1000(irr::u8*, irr::f32)")
    at assert.c:92
#3  0x00007ffff4fcf0f2 in __GI___assert_fail (
    assertion=0x84baa0 "i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))",
    file=0x84ba58 "/build/minetest-eSLhgt/minetest-201509101902/src/util/serialize.h", line=265, function=0x84bb60 "void writeF1000(irr::u8*, irr::f32)")
    at assert.c:101
#4  0x00000000004edd23 in NetworkPacket::operator<<(float) ()
#5  0x00000000004edd75 in NetworkPacket::operator<<(irr::core::vector3d<float>)
    ()
#6  0x00000000007c8c05 in Server::SendMovePlayer(unsigned short) ()
#7  0x000000000054751f in ObjectRef::l_setpos(lua_State*) ()
#8  0x000000000050f836 in script_exception_wrapper(lua_State*, int (*)(lua_State---Type <return> to continue, or q <return> to quit---q
Quit
(gdb) bt
#0  0x00007ffff4fd6267 in __GI_raise (sig=sig@entry=6)
    at ../sysdeps/unix/sysv/linux/raise.c:55
#1  0x00007ffff4fd7eca in __GI_abort () at abort.c:89
#2  0x00007ffff4fcf03d in __assert_fail_base (
    fmt=0x7ffff5131028 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
    assertion=assertion@entry=0x84baa0 "i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))",
    file=file@entry=0x84ba58 "/build/minetest-eSLhgt/minetest-201509101902/src/util/serialize.h", line=line@entry=265,
    function=function@entry=0x84bb60 "void writeF1000(irr::u8*, irr::f32)")
    at assert.c:92
#3  0x00007ffff4fcf0f2 in __GI___assert_fail (
    assertion=0x84baa0 "i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))",
    file=0x84ba58 "/build/minetest-eSLhgt/minetest-201509101902/src/util/serialize.h", line=265, function=0x84bb60 "void writeF1000(irr::u8*, irr::f32)")
    at assert.c:101
#4  0x00000000004edd23 in NetworkPacket::operator<<(float) ()
#5  0x00000000004edd75 in NetworkPacket::operator<<(irr::core::vector3d<float>)
    ()
#6  0x00000000007c8c05 in Server::SendMovePlayer(unsigned short) ()
#7  0x000000000054751f in ObjectRef::l_setpos(lua_State*) ()
#8  0x000000000050f836 in script_exception_wrapper(lua_State*, int (*)(lua_State---Type <return> to continue, or q <return> to quit---
*)) ()
#9  0x00007ffff6721b0e in ?? ()
   from /usr/lib/x86_64-linux-gnu/libluajit-5.1.so.2
#10 0x00007ffff6764f90 in lua_pcall ()
   from /usr/lib/x86_64-linux-gnu/libluajit-5.1.so.2
#11 0x0000000000514f93 in ScriptApiBase::runCallbacksRaw(int, RunCallbacksMode, char const*) ()
#12 0x00000000005229d2 in ScriptApiServer::on_chat_message(std::string const&, std::string const&) ()
#13 0x00000000004f78a1 in Server::handleCommand_ChatMessage(NetworkPacket*) ()
#14 0x00000000007d28f6 in Server::ProcessData(NetworkPacket*) ()
#15 0x00000000007d2e9e in Server::Receive() ()
#16 0x00000000007dd174 in ServerThread::run() ()
#17 0x000000000055c79d in Thread::theThread(void*) ()
#18 0x00007ffff62f96aa in start_thread (arg=0x7fffe4f6a700)
    at pthread_create.c:333
#19 0x00007ffff50a7eed in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
(gdb)

[est31]

Yes, alot, this is the kind of info we need! Many thanks.

[zzantozz]

I finally got around to running a gdb session, and I captured four crashes in quick succession. They appear almost identical, so I'll just post one:

Your phone or window isn't wide enough to display the code box. If it's a phone, try rotating it to landscape mode.

Code: Select all

minetest: /build/minetest-xOOHPg/minetest-0.4.13/src/util/serialize.h:265: void writeF1000(irr::u8*, irr::f32): Assertion `i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))' failed.
[New Thread 0x7fffea9df700 (LWP 3931)]
[New Thread 0x7fffeb1e0700 (LWP 3930)]
[New Thread 0x7fffe3fff700 (LWP 3929)]
[New Thread 0x7fffeb9e1700 (LWP 3928)]

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffeb1e0700 (LWP 3930)]
0x00007ffff4fd6267 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
55   ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  0x00007ffff4fd6267 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
#1  0x00007ffff4fd7eca in __GI_abort () at abort.c:89
#2  0x00007ffff4fcf03d in __assert_fail_base (fmt=0x7ffff5131028 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
    assertion=assertion@entry=0x849990 "i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))",
    file=file@entry=0x849950 "/build/minetest-xOOHPg/minetest-0.4.13/src/util/serialize.h", line=line@entry=265,
    function=function@entry=0x86f260 "void writeF1000(irr::u8*, irr::f32)") at assert.c:92
#3  0x00007ffff4fcf0f2 in __GI___assert_fail (assertion=0x849990 "i >= ((float)(s32)((-0x7FFFFFFF - 1) / 1000.0f)) && i <= ((float)(s32)((0x7FFFFFFF) / 1000.0f))",
    file=0x849950 "/build/minetest-xOOHPg/minetest-0.4.13/src/util/serialize.h", line=265, function=0x86f260 "void writeF1000(irr::u8*, irr::f32)") at assert.c:101
#4  0x0000000000499dd7 in ?? ()
#5  0x00000000006a9f72 in gob_cmd_update_position(irr::core::vector3d<float>, irr::core::vector3d<float>, irr::core::vector3d<float>, float, bool, bool, float) ()
#6  0x000000000062742a in LuaEntitySAO::sendPosition(bool, bool) ()
#7  0x0000000000629b07 in LuaEntitySAO::step(float, bool) ()
#8  0x0000000000677366 in ServerEnvironment::step(float) ()
#9  0x00000000007d88c7 in Server::AsyncRunStep(bool) ()
#10 0x00000000007db02b in ServerThread::Thread() ()
#11 0x00000000004c4503 in JThread::TheThread(void*) ()
#12 0x00007ffff62f96aa in start_thread (arg=0x7fffeb1e0700) at pthread_create.c:333
#13 0x00007ffff50a7eed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109


[TenPlus1]

est31: is it possible to tell what causes this error in general ???

[Krock]

est31: is it possible to tell what causes this error in general ???

When an LuaEntity contains a value which is either >= 2147483.648 or <= -2147483.648.
The error happened with a writeF1000() call in gob_cmd_update_position, so it's either a wrong yaw or update interval value.

Something messed up one (or both) of those numbers and caused an instant crash.

[zzantozz]

When an LuaEntity contains a value which is either >= 2147483.648 or <= -2147483.648.
The error happened with a writeF1000() call in gob_cmd_update_position, so it's either a wrong yaw or update interval value.

Something messed up one (or both) of those numbers and caused an instant crash.

This is on a server I'm running at home for my kids, and it seemed to mostly clear up the issue to shut down the server, remove the worlds/<world>/players/<player> file, and let them spawn fresh again. If I start seeing the crash again, is there more info I could give to help narrow down the issue? I forgot to run with --verbose, so I only posted the crash and stack trace. I can use --verbose next time if that will provide the needed info.

[est31]

zzantozz, Thanks for the backtrace, this helps alot.

Krock, I don't think its a wrong yaw or something else, I think the call between the stack elements writeF1000 and gob_cmd_update_position is a writeV3F1000, and its an out of bounds position or velocity. But for the case its an invalid position, I really wonder how it could be the reason, because usually entities get unloaded if they are in invalid blocks.

[TenPlus1]

I've checked any mods that use entities to make sure no value's go over the limit or object out of bounds and we still get these errors on server... Am running out of things to check, would be handy if the error message displayed the entity name as a clue :p