NPCs sometimes ported to (0, 0, 0) on opening in-game menu

[jdrueckert]

General Info

Started from source while testing Terasology/Behaviors#92

What you were trying to do

I was debugging NPC behavior and movement and entered the in-game menu to switch into intellij, to check my breakpoint condition before continuing to debug.

What actually happened

On entering the in-game menu I saw the NPC I was observing and whose behavior I was debugging disappear.
In my debug logs I noticed the following:

• a lot of Can't update Trigger entity with a non-finite position/rotation?! Entity: EntityRef{id = 3380, netId = 0, prefab = 'WildAnimals:deer'} while the entity tries moving to its current destination
• shortly: current position of the NPC (NaN, NaN, NaN)
• afterwards: current position of the NPC (0, 0, 0)

This is how it looks in-game (if you don't know where the entities are going):

Peek_2022-01-18_23-11.mp4

How to reproduce

1. Check out fix: FlexiblePathfinding migration follow-ups Terasology/Behaviors#92 and related
2. Start Terasology from source
3. Select gameplay 'CoreGameplay'
4. Add module 'WildAnimals' and its dependencies
5. Start game
6. Open the in-game console and do 'spawnPrefab deer'
7. Try opening the in-game menu a couple of times and see whether the NPC is still there or vanishes

Additional Infos / Context

This seems to be a sporadic issue. My guess is that it only happens while we're in the process of moving the NPC along the previously computed path and it somehow ends up in an "invalid" state resulting in the engine logic (potentially something about character prediction or movement) to run into some failing check and porting the NPC to (0, 0, 0) to "fix" it? As (0, 0, 0) is somewhere below the surface, this doesn't really fix things, though.

@pollend can you explain to me in "simple words" what running into this code path means for an entity? Or rather, what it tells us about the entity' state / position / ...?

Log details

[...]
15:08:52.660 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - Actor 3380: in move_to Action
15:08:52.660 [main] DEBUG o.t.m.b.plugin.WalkingMovementPlugin - --> [3380] 038 move: walking - current: (-3.305E+1  3.231E+1  1.895E+1) - destination: (-3.200E+1  3.200E+1  1.900E+1)
15:08:52.660 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - Actor 3380: in move_along_path Action
15:08:52.677 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - Actor 3380: in move_to Action
15:08:52.677 [main] DEBUG o.t.m.b.plugin.WalkingMovementPlugin - --> [3380] 039 move: walking - current: (-3.304E+1  3.231E+1  1.895E+1) - destination: (-3.200E+1  3.200E+1  1.900E+1)
15:08:52.677 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - Actor 3380: in move_along_path Action
15:08:52.709 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - Actor 3380: in move_to Action
15:08:52.709 [main] DEBUG o.t.m.b.plugin.WalkingMovementPlugin - --> [3380] 040 move: walking - current: (-3.304E+1  3.231E+1  1.895E+1) - destination: (-3.200E+1  3.200E+1  1.900E+1)
15:08:52.709 [main] WARN  o.t.e.physics.bullet.BulletPhysics - Can't update Trigger entity with a non-finite position/rotation?! Entity: EntityRef{id = 3380, netId = 0, prefab = 'WildAnimals:deer'}
15:08:52.709 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - Actor 3380: in move_along_path Action
[...]
15:08:54.676 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - Actor 3380: in move_to Action
15:08:54.676 [main] DEBUG o.t.m.b.plugin.WalkingMovementPlugin - --> [3380] 159 move: walking - current: (-3.304E+1  3.231E+1  1.895E+1) - destination: (-3.200E+1  3.200E+1  1.900E+1)
15:08:54.676 [main] WARN  o.t.e.physics.bullet.BulletPhysics - Can't update Trigger entity with a non-finite position/rotation?! Entity: EntityRef{id = 3380, netId = 0, prefab = 'WildAnimals:deer'}
15:08:54.677 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - Actor 3380: in move_along_path Action
15:08:54.693 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - Actor 3380: in move_to Action
15:08:54.693 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - ... [3380]: Movement plugin returned null - falling back to WalkingMovementPlugin
15:08:54.693 [main] DEBUG o.t.m.b.plugin.WalkingMovementPlugin - --> [3380] 160 move: walking - current: (      NaN       NaN       NaN) - destination: (-3.200E+1  3.200E+1  1.900E+1)
15:08:54.694 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - Actor 3380: in move_along_path Action
[...]
15:08:56.886 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - Actor 3380: in move_to Action
15:08:56.886 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - ... [3380]: Movement plugin returned null - falling back to WalkingMovementPlugin
15:08:56.886 [main] DEBUG o.t.m.b.plugin.WalkingMovementPlugin - --> [3380] 201 move: walking - current: (      NaN       NaN       NaN) - destination: (-3.200E+1  3.200E+1  1.900E+1)
15:08:56.886 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - Actor 3380: in move_along_path Action
15:08:56.903 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - Actor 3380: in move_to Action
15:08:56.904 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - Actor 3380: in move_along_path Action
15:08:56.920 [main] DEBUG o.t.m.behaviors.actions.LogAction - Actor 3380: ---- critter ----
15:08:56.920 [main] DEBUG o.t.m.behaviors.actions.LogAction - Actor 3380: in stray Behavior
15:08:56.920 [main] DEBUG o.t.m.behaviors.actions.LogAction - Actor 3380: in doRandomMove Behavior
15:08:56.920 [main] DEBUG o.t.m.b.a.SetTargetToNearbyBlockNode - Actor 3380: in set_target_nearby_block Action
15:08:56.920 [main] DEBUG o.t.m.b.a.SetTargetToNearbyBlockNode - ... [3380]  start position: ( 0.000E+0  0.000E+0  0.000E+0)
15:08:56.920 [main] DEBUG o.t.m.b.a.SetTargetToNearbyBlockNode - ... [3380] target position: ( 0.000E+0  0.000E+0  0.000E+0) - distance: 0.0
15:08:56.920 [main] DEBUG o.t.m.behaviors.actions.LogAction - Actor 3380: in naiveMoveTo Behavior
15:08:56.920 [main] DEBUG o.t.m.b.actions.FindPathToNode - Actor 3380: construct find_path Action
15:08:56.929 [main] DEBUG o.t.m.b.actions.FindPathToNode - ... [3380]: compute path between ( 0.000E+0  0.000E+0  0.000E+0) -> ( 0.000E+0  0.000E+0  0.000E+0)
15:08:56.929 [main] DEBUG o.t.m.b.actions.FindPathToNode - Actor 3380: in find_path Action
15:08:56.929 [main] DEBUG o.t.m.b.actions.FindPathToNode - ... [3380]: ... still searching for path
15:08:56.930 [PathfinderWorker-0] DEBUG o.t.flexiblepathfinding.JPSImpl - Starting JPS search: ( 0.000E+0  0.000E+0  0.000E+0) -> ( 0.000E+0  0.000E+0  0.000E+0)
15:08:56.933 [PathfinderWorker-0] DEBUG o.t.flexiblepathfinding.JPSImpl - Start and goal are within line of sight
15:08:56.940 [main] DEBUG o.t.m.b.actions.FindPathToNode - Actor 3380: in find_path Action
15:08:56.940 [main] DEBUG o.t.m.b.actions.FindPathToNode - ... [3380]: pathfinding done: [( 0.000E+0  0.000E+0  0.000E+0)]
15:08:56.940 [main] DEBUG o.t.m.behaviors.actions.MoveToAction - Actor 3380: in move_to Action
15:08:56.940 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - Actor 3380: in move_along_path Action
15:08:56.940 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - ... [3380]: advance path
15:08:56.940 [main] DEBUG o.t.m.b.actions.MoveAlongPathNode - ... [3380]: finished
15:08:57.388 [main] WARN  o.t.e.physics.bullet.BulletPhysics - Can't update Trigger entity with a non-finite position/rotation?! Entity: EntityRef{id = 3380, netId = 0, prefab = 'WildAnimals:deer'}
15:08:57.403 [main] WARN  o.t.e.physics.bullet.BulletPhysics - Can't update Trigger entity with a non-finite position/rotation?! Entity: EntityRef{id = 3380, netId = 0, prefab = 'WildAnimals:deer'}
15:08:57.419 [main] WARN  o.t.e.physics.bullet.BulletPhysics - Can't update Trigger entity with a non-finite position/rotation?! Entity: EntityRef{id = 3380, netId = 0, prefab = 'WildAnimals:deer'}
[...]

[jdrueckert]

Release Candidate 5.3.0-rc.1

[Cervator]

That's an interesting bug! One thing that comes to mind: single player vs multiplayer may well work differently here. In single player the game client attempts to "pause" the game on the in-game menu, yet as far as I recall that pausing is not actually total so it may well lead to weird behavior like that. Server-side never pauses since it is its own process, but single tries to freeze everything, but then not really because some UI bits etc still need to work etc ...