Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Server crash after "Invalid float vector dimension range" returned by get_pos() #5135

Open
jhcole opened this issue Jan 28, 2017 · 12 comments
Labels

Comments

@jhcole
Copy link

@jhcole jhcole commented Jan 28, 2017

Since updating to Minetest 0.4.15-dev-59fdf571 (Linux) 5 days ago (January 24th, 2017) my server has crashed 11 times with the following error.

2017-01-28 14:27:31: ERROR[Main]: ServerError: AsyncErr: environment_Step: Runtime error from mod '' in callback environment_Step(): Invalid float vector dimension range 'x' (expected -2.14748e+06 < x < 2.14748e+06 got -2.14748e+06).
2017-01-28 14:27:31: ERROR[Main]: stack traceback:                               
2017-01-28 14:27:31: ERROR[Main]:   [C]: in function 'get_objects_inside_radius' 
2017-01-28 14:27:31: ERROR[Main]:   /home/foz/.minetest/mods/item_drop/init.lua:10: in function 'func'
2017-01-28 14:27:31: ERROR[Main]:   /usr/local/share/minetest/builtin/game/misc.lua:34: in function </usr/local/share/minetest/builtin/game/misc.lua:11>
2017-01-28 14:27:31: ERROR[Main]:   /usr/local/share/minetest/builtin/game/register.lua:412: in function </usr/local/share/minetest/builtin/game/register.lua:392>
2017-01-28 14:27:31: ERROR[Main]: stack traceback:

For reference, the first 10 lines of item_drop/init.lua are as follows:

local function do_step()                                                         
  for _,player in pairs(minetest.get_connected_players()) do                     
    local pname = player:get_player_name()                                        
    if minetest.get_player_privs(pname).interact                                  
    and player:get_hp() > 0                                                       
    and not player:get_player_control().sneak then                               
      local pos = player:getpos()                                                
      pos.y = pos.y+0.5                                                          
      local inv                                                                  
      for _,object in pairs(minetest.get_objects_inside_radius(pos, 1)) do

My best guess is that under the right conditions, player:getpos() is returning invalid positions. I will add a check in item_drop to catch the problem, but there may be a minetest bug here.

Anyone have ideas?

@jhcole

This comment has been minimized.

Copy link
Author

@jhcole jhcole commented Jan 29, 2017

After further review I noticed that there is a list of messages like this before each crash.

2017-01-28 14:27:30: ACTION[Server]: Leonts leaves game. List of players:        
2017-01-28 14:27:30: ACTION[Server]: JoiJoi leaves game. List of players:        
2017-01-28 14:27:30: ACTION[Server]: Selviam leaves game. List of players:       
2017-01-28 14:27:30: ACTION[Server]: lola00 leaves game. List of players:        
2017-01-28 14:27:30: ACTION[Server]: theDragon leaves game. List of players:     
2017-01-28 14:27:30: ACTION[Server]: Lola10 leaves game. List of players:        
2017-01-28 14:27:30: ACTION[Server]: XFreakiiDiamondX leaves game. List of players:
2017-01-28 14:27:30: ACTION[Server]: ElMehdiBen leaves game. List of players:    
2017-01-28 14:27:30: ACTION[Server]: laurinluic leaves game. List of players:    
2017-01-28 14:27:30: ACTION[Server]: wenxin leaves game. List of players:        
2017-01-28 14:27:30: ACTION[Server]: owlgirl300 leaves game. List of players:    
2017-01-28 14:27:30: ACTION[Server]: livey leaves game. List of players:

ALL the players that were connected are listed there, and 'left' one second before the crash. I think the call in item_drop that led to the crash is just a symptom of some other mysterious problem.

@jhcole jhcole changed the title Is get_pos() returning invalid positions? All players leave then mysterious crash Jan 29, 2017
@sofar

This comment has been minimized.

Copy link
Member

@sofar sofar commented Jan 29, 2017

Note: item_drop/init.lua isn't a builtin or minetest_game thing.

@jhcole

This comment has been minimized.

Copy link
Author

@jhcole jhcole commented Jan 29, 2017

I know, but I'm fairly sure this bug is not in the item_drop mod for two reasons. The first is that I've been using it for years, but the crashes only started after updating minetest to 0.4.15. The second is that I've carefully reviewed its code.

My problem is that, if he error messages are a red herring, I'm not sure where to look, and I'm wondering if anyone has experienced similar problems.

@sfan5

This comment has been minimized.

Copy link
Member

@sfan5 sfan5 commented Jan 29, 2017

Try adding print(dump(pos)) before the for loop and see what it prints when it crashes again.

@jhcole

This comment has been minimized.

Copy link
Author

@jhcole jhcole commented Jan 29, 2017

To catch, and try to handle the errors, I've added the following to item_drop/init.lua

       local pos = player:get_pos()                                               
+      if pos.x < -4500  or 4500  < pos.x                                         
+      or pos.z < -4500  or 4500  < pos.z                                         
+      or pos.y < -31000 or 31000 < pos.y then                                    
+        minetest.log("error", "[item_drop] "..pname.." is out of bounds at "..   
+          core.pos_to_string(pos))                                               
+        minetest.after(60, do_step) -- Stop auto pick up for a bit.              
+        return                                                                   
+      end
       pos.y = pos.y+0.5

Note that I've restricted x and z travel to +- 4500 in a separate mod.

This has been running for about 16 hours now and has produced the following errors so far.

2017-01-29 08:27:53: ERROR[Server]: [item_drop] lola00 is out of bounds at (-2147483.75,6.4410004615784,2035.7971191406)
2017-01-29 14:53:38: ERROR[Server]: [item_drop] Leonts is out of bounds at (-2147483.75,21.5,2230.1789550781)
2017-01-29 15:33:20: ERROR[Server]: [item_drop] Leonts is out of bounds at (-2147483.75,19.5,2228.833984375)

Somehow get_pos() is periodically returning an x position of -2147483.75!

@sfan5 sfan5 added Bug and removed Unconfirmed bug labels Jan 30, 2017
@jhcole

This comment has been minimized.

Copy link
Author

@jhcole jhcole commented Feb 3, 2017

The latest errors.

2017-01-31 11:49:38: ERROR[Server]: [item_drop] Leonts is out of bounds at (-2147483.75,17.5,2236.1188964844)
2017-01-31 11:55:40: ERROR[Server]: [item_drop] Leonts is out of bounds at (-2147483.75,17.5,2230.4382324219)
2017-01-31 12:22:59: ERROR[Server]: [item_drop] Leonts is out of bounds at (-2147483.75,17.5,2233.0949707031)
2017-01-31 15:04:07: ERROR[Server]: [item_drop] lola00 is out of bounds at (-2147483.75,11.47500038147,2022.9539794922)
2017-02-01 09:44:19: ERROR[Server]: [item_drop] Leonts is out of bounds at (-2147483.75,14.5,2244.9370117188)
2017-02-02 07:08:18: ERROR[Server]: [item_drop] Leonts is out of bounds at (-2147483.75,-15.5,2211.0270996094)
2017-02-02 07:47:39: ERROR[Server]: [item_drop] Leonts is out of bounds at (-2147483.75,-35.5,2211.8830566406)
2017-02-02 12:32:29: ERROR[Server]: [item_drop] lola00 is out of bounds at (-2147483.75,6.3520002365112,2034.0689697266)

It is odd that it only seems to effect two players. Could it be a bug in their client?

@00c

This comment has been minimized.

Copy link

@00c 00c commented Feb 5, 2017

I get same error, they are very rare but start to appear in 0.4.15-dev

2017-02-05 16:54:39: ERROR[Main]: ServerError: AsyncErr: environment_Step: Invalid float vector dimension range 'x' (expected -2.14748e+06 < x < 2.14748e+06 got -2.14748e+06).
2017-02-05 16:54:39: ERROR[Main]: stack traceback:
2017-02-05 16:54:39: ERROR[Main]: [C]: in function 'func'
2017-02-05 16:54:39: ERROR[Main]: /home/mt/bin/../builtin/game/deprecated.lua:40: in function 'get_objects_inside_radius'
2017-02-05 16:54:39: ERROR[Main]: .../bin/../games/Liberty Land/mods/item_drop/init.lua:18: in function '?'
2017-02-05 16:54:39: ERROR[Main]: /home/mt/bin/../builtin/game/register.lua:412: in function </home/mt/bin/../builtin/game/register.lua:392>
2017-02-05 16:54:39: ERROR[Main]: [C]: in function 'func'
2017-02-05 16:54:39: ERROR[Main]: /home/mt/bin/../builtin/game/deprecated.lua:40: in function 'get_objects_inside_radius'
2017-02-05 16:54:39: ERROR[Main]: .../bin/../games/Liberty Land/mods/item_drop/init.lua:18: in function '?'
2017-02-05 16:54:39: ERROR[Main]: /home/mt/bin/../builtin/game/register.lua:412: in function </home/mt/bin/../builtin/game/register.lua:392>

@00c

This comment has been minimized.

Copy link

@00c 00c commented Feb 5, 2017

What happen just before crash

2017-02-05 16:54:33: INFO[Server]: ServerMap: Unloaded 138 blocks from memory, of which 104 were written, 3673 blocks in memory.
2017-02-05 16:54:33: INFO[Server]: ServerMap: Blocks modified by:
2017-02-05 16:54:33: INFO[Server]: setTimestamp: - - - - - - - - - - - - - - 2
2017-02-05 16:54:33: INFO[Server]: setTimestamp, Timestamp expired (step): - 102
2017-02-05 16:54:34: ACTION[Server]: TheDarkWolf activates default:torch
2017-02-05 16:54:35: INFO[Server]: collisionMoveSimple: maximum step interval exceeded, lost movement details!
2017-02-05 16:54:35: ACTION[Server]: [Spawn Plus] Moving Sires to (3418.0, 13.0, -2315.0)
2017-02-05 16:54:35: ACTION[Server]: Qntn damaged by 1 hp at (3152.17,18.552,-3108.53)
2017-02-05 16:54:35: ACTION[Server]: TheDarkWolf places node default:torch at (-958,-158,711)
2017-02-05 16:54:35: INFO[Server]: Sending 1985 files to [id=295]
2017-02-05 16:54:35: INFO[Main]: Players:

2017-02-05 16:54:35: INFO[Main]: Server destructing
2017-02-05 16:54:35: INFO[Main]: Server: Saving players
2017-02-05 16:54:35: INFO[Main]: Server: Kicking players
2017-02-05 16:54:35: INFO[Main]: Server: Saving environment metadata
2017-02-05 16:54:35: INFO[Main]: Server: Stopping and waiting threads
2017-02-05 16:54:35: INFO[Server]: Server::ProcessData(): Canceling: peer 3 not found
2017-02-05 16:54:35: INFO[Main]: Server: Threads stopped
2017-02-05 16:54:38: INFO[Main]: ServerMap: Written: 0 sector metadata files, 2625 block files, 3690 blocks in memory.
2017-02-05 16:54:38: INFO[Main]: ServerMap: Blocks modified by:
2017-02-05 16:54:38: INFO[Main]: Timestamp expired (step): - - - - - - - - 663
2017-02-05 16:54:38: INFO[Main]: addActiveObjectRaw, removeRemovedObjects/remove: 5
2017-02-05 16:54:38: INFO[Main]: removeRemovedObjects/deactivate: - - - - 2
2017-02-05 16:54:38: INFO[Main]: setNodeNoCheck: - - - - - - - - - - - - - 26
2017-02-05 16:54:38: INFO[Main]: setNodeNoCheck, addActiveObjectRaw, removeRemovedObjects/remove: 2
2017-02-05 16:54:38: INFO[Main]: setNodeNoCheck, deactivateFarObjects: Static data changed considerably: 2
2017-02-05 16:54:38: INFO[Main]: setTimestamp: - - - - - - - - - - - - - - 11
2017-02-05 16:54:38: INFO[Main]: setTimestamp, Timestamp expired (step): - 1914

@numberZero

This comment has been minimized.

Copy link
Contributor

@numberZero numberZero commented Feb 17, 2017

Interesting...

  1. -2147483.75 is 0x80000066 in MT network format.
  2. Leonts Y has the form xx.5; lola00 Y is xx.xxx000xxxxx
  3. Z values don’t change significantly, Leonts has 2211–2244 and lola00 has 2022–2035

That looks really strange. I think their clients send something wrong, maybe it’s hacked patched.

But the server should not crash anyway; perhaps it needs to sanitize the data got from the network?

@BluebirdGreycoat

This comment has been minimized.

Copy link
Contributor

@BluebirdGreycoat BluebirdGreycoat commented Feb 17, 2017

I'd like to add an important point. The title of this issue is misleading. This crash happens on my server while players are still online. It is not related to all players leaving. (My server is up-to-date with the Git repository as of a few days ago, so quite a new build.)

So, my server crashed again quite recently, this time in another part of the Lua code (since I had added range checks to the code that I previously reported was crashing). However, despite the crash moving to a new location, the basic problem is the same: player:getpos() returns an invalid vector, and passing it to minetest.get_objects_inside_radius() provokes a shutdown with a message about an invalid float vector range.

Interestingly, before this crash happened, the chatlog shows that one of my players was mysteriously and unexpectedly teleported far outside the world boundaries. He complained about it in chat, and apparently one of the components of his position was inf. Not simply a large number, but inf! Fortunately he did not die there, else he would have lost a lot of stuff.

I really think that player:getpos() should never under any circumstances return an invalid vector, especially given the number of places it is used without any protective range-checks following.

@jhcole

This comment has been minimized.

Copy link
Author

@jhcole jhcole commented Feb 18, 2017

I agree, the title was a poor choice. I'll change it.

@jhcole jhcole changed the title All players leave then mysterious crash Server crash after "Invalid float vector dimension range" returned by get_pos() Feb 18, 2017
@numberZero

This comment has been minimized.

Copy link
Contributor

@numberZero numberZero commented Feb 18, 2017

@jhcole @BluebirdGreycoat player:get_pos()can’t return an invalid value unless the server has an invalid value (or pointer) already. So I suggest adding a check in ServerActiveObject::setBasePosition; if it gets anything insane, it should complain loudly and let you get the backtrace somehow.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
6 participants
You can’t perform that action at this time.