Crash after player leaves game (async callback involved)

[BluebirdGreycoat]

Issue type

• Bug report

Minetest version

Minetest 5.1.0-dev-ad75dba8 (Linux)

Summary

2019-04-05 17:55:39: ACTION[Server]: leBarbu joins game. List of players: StarNinjas Ferald MustTest leBarbu
2019-04-05 17:55:39: ACTION[Server]: leBarbu leaves game. List of players: StarNinjas Ferald MustTest
2019-04-05 17:55:39: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-05 17:55:39: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-05 17:55:39: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-05 17:55:39: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-05 17:55:39: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-05 17:55:39: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-05 17:55:39: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-05 17:55:39: ACTION[Server]: leBarbu initiates teleport to (-197,-7,2)
2019-04-05 17:55:39: WARNING[Emerge-0]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-05 17:55:39: ACTION[Emerge-0]: executing teleport callback for leBarbu!
2019-04-05 17:55:39: ACTION[Emerge-0]: could not find data for player leBarbu when updating realm info

Since this caused the server to crash without any Lua exception reported in debug.txt, I'd say it's certainly a bug. It looks like Minetest is giving Lua a non-nil player-ref to my code instead of pushing nil!

Sequence of events as nearly as I can tell:

1. player joins game
2. player triggers an asynchronous teleport callback (which normally works even if player leaves suddenly ....)
3. player leaves game
4. Minetest shoves a player-ref into the game code when it should be pushing nil.
5. server crashes without explanation, SIGSEGV maybe?

Example code

I'm using code like this in a lot of places to determine if it is safe to run some function:

local player = minetest.get_player_by_name(pname)
if not player or not player:is_player() then
	return -- Or abort or whatever.
end

Apparently this 'safety check' isn't working anymore ...

[SmallJoker]

I don't see any Segmentation Fault message or error in your logs. Could you please provide more information - and - if possible: a tiny mod to reproduce this issue?

[BluebirdGreycoat]

The output is from debug.txt. There isn't any Segmentation Fault message, the log just ends there. The next lines are from the server restarting.

I'm not sure if I'll be able to make a mod to reliably reproduce this, I haven't even been able to provoke it again (yet) on the live server.

[BluebirdGreycoat]

Alright, I think I can reproduce the problem on my server.

2019-04-06 21:30:59: ACTION[Server]: MustTest joins game. List of players: StarNinjas Ferald MustTest
2019-04-06 21:30:59: ACTION[Server]: MustTest leaves game. List of players: StarNinjas Ferald
2019-04-06 21:30:59: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-06 21:30:59: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-06 21:30:59: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-06 21:30:59: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-06 21:30:59: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-06 21:31:00: ERROR[Server]: Better HUD[error]: Not enough parameters given to change HUD item
2019-04-06 21:31:00: ERROR[Server]: 3d_armor: Player position is nil [set_player_armor]
2019-04-06 21:31:00: ERROR[Server]: Better HUD[error]: Not enough parameters given to change HUD item

Steps:

1. Initiate connection from the client's menu.
2. Wait for "loading nodes" or somesuch loading message, then close/crash client (I used alt+F4).
3. Notice that Pushing ObjectRef to removed/deactivated object, this is probably a bug is printed in debug.txt.

In this case the trailing error messages are triggered as a result. The server did not crash this time.

[BluebirdGreycoat]

I've discovered that trying the same thing using a completely new account actually does provoke the crash. Next step I guess is to see if this happens on an unmodified server running Minetest Game ...

Edit: and yes basically the same series of messages is printed as in the first post.

[BluebirdGreycoat]

Alright, here's a test code I cooked up:

minetest.register_on_joinplayer(function(player)
	local pname = player:get_player_name()
	minetest.after(0.1, function()
		local player = minetest.get_player_by_name(pname)
		if not player then
			minetest.log("failed to get player")
			return
		else
			minetest.log("got player")
		end
		local pos = player:get_pos()
		if pos then
			minetest.log("got position")
		else
			minetest.log("failed to get position")
		end
	end)
end)

And here is a sample session from debug.txt:

2019-04-06 17:16:03: ACTION[Server]: crasher [127.0.0.1] joins game.
2019-04-06 17:16:03: ACTION[Server]: crasher joins game. List of players: crasher
2019-04-06 17:16:03: ACTION[Server]: crasher leaves game. List of players:
2019-04-06 17:16:03: WARNING[Server]: ScriptApiBase::objectrefGetOrCreate(): Pushing ObjectRef to removed/deactivated object, this is probably a bug.
2019-04-06 17:16:03: [Server]: got player
2019-04-06 17:16:03: [Server]: got position
^C2019-04-06 17:16:09: [Main]: INFO: signal_handler(): Ctrl-C pressed, shutting down.
2019-04-06 17:16:09: ACTION[Main]: Server: Shutting down

Steps:

1. Start local server with the above code and Minetest Game.
2. Start client connection.
3. Close client using your favorite keyboard shortcut before connection is fully completed.
4. Observe strange log output.

You may need to try several times depending on how fast your computer is.

I cannot make the server crash in these tests. I guess that's a unique behavior of the live server, which is quite heavily modded. But minetest.get_player_by_name should definitely not be returning non-nil.

[rubenwardy]

I see this as a high priority bug if it confirmed. It is very weird behaviour, and explains why there are lots of Pushing ObjectRef to removed/deactivated object, this is probably a bug. messages in 5.0.0

[sfan5]

Still happening?

[paramat]

@BluebirdGreycoat ^

[BluebirdGreycoat]

I can't reproduce this anymore with latest development version.
Pushing ObjectRef to removed/deactivated object no longer appears in logs after I upgraded my server on Aug 12.