[SOLVED] SimEthereal object not being updated in the current frame

asser_fahrenholz · January 1, 2021, 10:09am

Hello users of SimEthereal

Happy new year, hope you all got through it safely.

I’m trying to track down a bug that I hope you can help me with. As I’m flying through my game world adding forces to my avatar body, suddenly my avatar ship is removed from view. I’m thinking, what the… It seemingly happens at random, I can’t seem to find a pattern when re-trying, but it does happen ever game session at some point - trying to track this down, I work my way backwards and find that the reason it disappears from view is that the BodyPosition is null - This is weird, because I’m moving about, adding forces to the body etc.

I switch on DEBUG level logging for SimEthereal and I get this out in the console just before my ModelViewState removes the avatar:

10:08:46,362 DEBUG [com.simsilica.ethereal.NetworkStateListener] Object no longer in active zones, marking removed:3
10:08:46,312 DEBUG [com.simsilica.ethereal.SharedObject] applyNetworkState(37547218300, com.simsilica.ethereal.net.ObjectState[id=10, positionBits=244402b555017c])
10:08:46,312 DEBUG [com.simsilica.ethereal.net.StateReceiver] ** frame begin:37563884900
10:08:46,312 DEBUG [com.simsilica.ethereal.SharedObject] applyNetworkState(37563884900, com.simsilica.ethereal.net.ObjectState[id=10, positionBits=2437b2b555025b])
10:08:46,362 DEBUG [com.simsilica.ethereal.NetworkStateListener] Object no longer in active zones, marking removed:3
10:08:46,362 DEBUG [com.simsilica.ethereal.net.RemoteTimeSource] ======== Time delta:-43,808,844,000,100 nanos (-43,808,844 ms) drift:-43,808,844,080,715 nanos (-43,808,844.08 ms) windowSize:100
10:08:46,362 DEBUG [com.simsilica.ethereal.net.RemoteTimeSource] === oldDrift:-43808844081522 drift change:807 nanos (0 ms)
10:08:46,362 DEBUG [com.simsilica.ethereal.net.StateReceiver] Update state:ObjectStateMessage[id=652, time=37616485800, size=116]
10:08:46,362 DEBUG [com.simsilica.ethereal.net.StateReceiver] State:SentState[messageId=652, created=43846460593100, acked=[[IntRange[651:651]]], frames=[FrameState[time=37580551600, legacySequence=37580551424, columnId=1, states=[com.simsilica.ethereal.net.ObjectState[id=10, positionBits=242b32b555033c]]], FrameState[time=37597218200, legacySequence=37597218048, columnId=2097151, states=[com.simsilica.ethereal.net.ObjectState[id=10, REMOVED, positionBits=242b32b555033c]]], FrameState[time=37613885000, legacySequence=37613884928, columnId=2097151, states=[com.simsilica.ethereal.net.ObjectState[id=10, REMOVED, positionBits=242b32b555033c]]]]]
10:08:46,362 DEBUG [com.simsilica.ethereal.net.StateReceiver] Updating baseline for message:651
10:08:46,362 DEBUG [com.simsilica.ethereal.net.StateReceiver] ** frame begin:37580551600
10:08:46,362 DEBUG [com.simsilica.ethereal.SharedObject] applyNetworkState(37580551600, com.simsilica.ethereal.net.ObjectState[id=10, positionBits=242b32b555033c])
10:08:46,362 DEBUG [com.simsilica.ethereal.net.StateReceiver] ** frame begin:37597218200
10:08:46,362 DEBUG [com.simsilica.ethereal.SharedObject] applyNetworkState(37597218200, com.simsilica.ethereal.net.ObjectState[id=10, REMOVED, positionBits=242b32b555033c])
10:08:46,362 DEBUG [infinity.client.SharedObjectUpdater] ****** Object removed[t=37597218200]:3 netId:10
10:08:46,363 DEBUG [infinity.client.SharedObjectUpdater] Setting entity to invisible for:3
10:08:46,363 DEBUG [com.simsilica.ethereal.net.StateReceiver] ** frame begin:37613885000
10:08:46,363 DEBUG [com.simsilica.ethereal.SharedObject] applyNetworkState(37613885000, com.simsilica.ethereal.net.ObjectState[id=10, REMOVED, positionBits=242b32b555033c])
Dec 31, 2020 10:08:46 AM infinity.systems.ContactSystem newContact
INFO: Collided: RigidBody{id=EntityId[3], position=Vec3d[17.105671480493076, 0.5, 204.04641399952402], orientation=Quatd[0.0, -0.9664444674277064, 0.0, -0.25687563406905156], linearVelocity=Vec3d[10.02710515014478, 0.0, -9.3764282165319], rotationalVelocity=Vec3d[0.0, 0.0, 0.0], rawTemperature=1.0, temperature=1.0, shape=MBlockShape{part=CellArrayPart{name=cellArray, type=Sphere, center=Vec3d[0.0, 0.0, 0.0], radius=1.0, bodyMass=BodyMass{inverseMass=1.0, inverseMassTensor=Matrix3d[{2.5, 0.0, 0.0}, {0.0, 2.5, 0.0}, {0.0, 0.0, 2.5}], cog=Vec3d[0.0, 0.0, 0.0], radius=1.0}}}} with null
10:08:46,414 DEBUG [com.simsilica.ethereal.NetworkStateListener] State entry is removed for:3
10:08:46,414 DEBUG [com.simsilica.ethereal.net.RemoteTimeSource] ======== Time delta:-43,808,844,041,600 nanos (-43,808,844.04 ms) drift:-43,808,844,080,327 nanos (-43,808,844.08 ms) windowSize:100
10:08:46,414 DEBUG [com.simsilica.ethereal.net.RemoteTimeSource] === oldDrift:-43808844080715 drift change:388 nanos (0 ms)
10:08:46,414 DEBUG [com.simsilica.ethereal.net.StateReceiver] Update state:ObjectStateMessage[id=653, time=37668025600, size=36]
10:08:46,414 DEBUG [com.simsilica.ethereal.net.StateReceiver] State:SentState[messageId=653, created=43846512190100, acked=[[IntRange[652:652]]], frames=[FrameState[time=37630551900, legacySequence=37630551808, columnId=2097151, states=[com.simsilica.ethereal.net.ObjectState[id=10]]]]]
10:08:46,414 DEBUG [com.simsilica.ethereal.net.StateReceiver] Updating baseline for message:652
10:08:46,414 DEBUG [com.simsilica.ethereal.net.StateReceiver] ** frame begin:37630551900
10:08:46,414 DEBUG [com.simsilica.ethereal.SharedObject] applyNetworkState(37630551900, com.simsilica.ethereal.net.ObjectState[id=10])
10:08:46,426 INFO [infinity.server.BodyVisibility] done collectChanges() []
10:08:46,428 INFO [infinity.client.view.ModelViewState] remove mob for:EntityId[3], e:Entity[EntityId[3], values=[null, ShapeInfo[shape=0, scale=1.0]]]
10:08:46,428 WARN [infinity.client.view.ModelViewState] Releasing avatar!
10:08:46,428 INFO [infinity.client.view.ModelViewState] Updating relative position for model from (20.0, 0.5, 20.0)
10:08:46,428 INFO [infinity.client.view.ModelViewState] – to (20.0, 0.5, -172.0)

For some reason, the zone of my entity is being marked inactive. Now, from here I’m not sure where to go. If you have any idea where I should look I’d be grateful. I can’t remember setting zones decidedly inactive/active in my code - that I leave for SimEthereal (I think)

I’ll try to work out how SimEthereal keeps track of active zones

This is where the log message comes from:

github.com

Simsilica/SimEthereal/blob/349f0b05b0a4ea911351db3555a464650d362f31/src/main/java/com/simsilica/ethereal/NetworkStateListener.java#L334


// Besides, I think in the current situation we might leak some stuff
// in that it looks outwardly like we've removed the object while internally
// we are still tracking it in the global structures.  
//
// Here we only care about the version and not whether it actually
// moved or not.  So as long as the zones update the version of objects
// that aren't moving we are clear here.  (And we avoid redoing processing
// per-client that's perhaps best done globally.) 
if( !so.isMarkedRemoved() && so.getVersion() < time ) {
    if( log.isDebugEnabled() ) {
        log.debug("Object no longer in active zones, marking removed:" + so.getEntityId() );
    }
    so.markRemoved(time);
}
    
stateWriter.addState(so.getDelta());

if( so.isFullyMarkedRemoved() ) {
    if( log.isDebugEnabled() ) {
        log.debug("State entry is removed for:" + so.getEntityId() ); //+ "  zone:" + e.zone + "  parent:" + e.parentId );
    }

Cheers

pspeed · January 1, 2021, 10:16am

Don’t be too focused on the zone part of the message. That log message is just trying to guess how we got there.

Without looking any deeper:

so.getVersion() < time

…to me says “this object wasn’t updated this frame”. I thought I fixed that problem, though.

What version of SimEtheral are you using?

asser_fahrenholz · January 1, 2021, 10:24am

I am on 1.6.0-SNAPSHOT. Thats what I have in my build.gradle at least. I’ll verify to make sure.

asser_fahrenholz · January 1, 2021, 10:27am

Yea, gradle install version of SimEthereal is 1.6.0-SNAPSHOT, and the files are up-to-date with github.

pspeed · January 1, 2021, 10:49am

If it’s always the same object then you might try logging it’s position/orientation to see if it goes wonky right before that.

…NaN position could cause weird issues, for example.

asser_fahrenholz · January 1, 2021, 11:38am

Its always the same mob (my avatar of the player) - I only have one active mob besides some static objects.

Physical body, BodyPosition and spatial info looks to be okay up till the point:

12:35:08,182 DEBUG [infinity.sim.PlayerDriver] Body sleepy:false, orientation:Quatd[0.0, 0.9872010898269944, 0.0, -0.15948043216769414], position: Vec3d[14.93689330925394, 0.5, 201.77839011517253]
12:35:08,182 DEBUG [infinity.sim.PlayerDriver] Body bodyPosition:BodyPosition[TransitionBuffer[ h:0, t:3, array:[PositionTransition3d[ t:52221304000, pos:Vec3d[14.93689330925394, 0.5, 201.77839011517253], rot:Quatd[0.0, 0.9872010898269944, 0.0, -0.15948043216769414], vis:true -> t:52237970700, pos:Vec3d[14.93689330925394, 0.5, 201.77839011517253], rot:Quatd[0.0, 0.9872010898269944, 0.0, -0.15948043216769414], vis:true ], PositionTransition3d[ t:52237970700, pos:Vec3d[14.93689330925394, 0.5, 201.77839011517253], rot:Quatd[0.0, 0.9872010898269944, 0.0, -0.15948043216769414], vis:true -> t:52254637400, pos:Vec3d[14.93689330925394, 0.5, 201.77839011517253], rot:Quatd[0.0, 0.9872010898269944, 0.0, -0.15948043216769414], vis:true ], PositionTransition3d[ t:52254637400, pos:Vec3d[14.93689330925394, 0.5, 201.77839011517253], rot:Quatd[0.0, 0.9872010898269944, 0.0, -0.15948043216769414], vis:true -> t:52271304200, pos:Vec3d[14.93689330925394, 0.5, 201.77839011517253], rot:Quatd[0.0, 0.9872010898269944, 0.0, -0.15948043216769414], vis:true ], null]]]
12:35:08,183 DEBUG [infinity.client.view.ModelViewState] Mob[EntityId[3]] LOCAL: position:(14.502165, 0.49987793, 10.482956), rotation:(2.4425983E-4, 0.9926741, 2.4425983E-4, -0.122344255)
12:35:08,183 DEBUG [infinity.client.view.ModelViewState] Mob[EntityId[3]] WORLD: position:(0.018608093, 0.49987793, -0.025909424), rotation:(2.4425983E-4, 0.9926741, 2.4425983E-4, -0.122344255)
12:35:08,186 DEBUG [infinity.client.view.ModelViewState] Mob[EntityId[3]] LOCAL: position:(14.520932, 0.49987793, 10.455765), rotation:(2.4425983E-4, 0.9926741, 2.4425983E-4, -0.122344255)
12:35:08,186 DEBUG [infinity.client.view.ModelViewState] Mob[EntityId[3]] WORLD: position:(0.018767357, 0.49987793, -0.027191162), rotation:(2.4425983E-4, 0.9926741, 2.4425983E-4, -0.122344255)
12:35:08,189 DEBUG [infinity.client.view.ModelViewState] Mob[EntityId[3]] LOCAL: position:(14.539163, 0.49987793, 10.429352), rotation:(2.4425983E-4, 0.9926741, 2.4425983E-4, -0.122344255)
12:35:08,189 DEBUG [infinity.client.view.ModelViewState] Mob[EntityId[3]] WORLD: position:(0.018230438, 0.49987793, -0.026412964), rotation:(2.4425983E-4, 0.9926741, 2.4425983E-4, -0.122344255)
12:35:08,192 DEBUG [infinity.client.view.ModelViewState] Mob[EntityId[3]] LOCAL: position:(14.557638, 0.49987793, 10.402588), rotation:(2.4425983E-4, 0.9926741, 2.4425983E-4, -0.122344255)
12:35:08,193 DEBUG [infinity.client.view.ModelViewState] Mob[EntityId[3]] WORLD: position:(0.018475533, 0.49987793, -0.026763916), rotation:(2.4425983E-4, 0.9926741, 2.4425983E-4, -0.122344255)
12:35:08,193 DEBUG [com.simsilica.ethereal.NetworkStateListener] Object no longer in active zones, marking removed:3

asser_fahrenholz · January 1, 2021, 12:25pm

Here’s a bit of logging with TRACE level for SimEthereal

13:18:59,609 TRACE [com.simsilica.ethereal.zone.ZoneManager] beginUpdate(49606698300)
13:18:59,609 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:beginUpdate(49606698300)
13:18:59,609 TRACE [com.simsilica.ethereal.zone.ZoneManager] updateEntity(3, true, Vec3d[54.69467220590133, 0.5, 221.12484144946868])
13:18:59,609 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:update(3, Vec3d[54.69467220590133, 0.5, 221.12484144946868])
13:18:59,609 TRACE [com.simsilica.ethereal.zone.ZoneManager] endUpdate()
13:18:59,609 TRACE [com.simsilica.ethereal.zone.ZoneManager] No-updates for keys:[]
13:18:59,609 TRACE [com.simsilica.ethereal.zone.ZoneManager] writing history
13:18:59,609 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:commitUpdate() empty:false   children:[3]
13:18:59,609 TRACE [com.simsilica.ethereal.zone.ZoneManager] done writing history
13:18:59,625 TRACE [com.simsilica.ethereal.zone.ZoneManager] beginUpdate(49623365000)
13:18:59,625 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:beginUpdate(49623365000)
13:18:59,625 TRACE [com.simsilica.ethereal.zone.ZoneManager] updateEntity(3, true, Vec3d[54.930319761419454, 0.5, 220.91893865302774])
13:18:59,625 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:update(3, Vec3d[54.930319761419454, 0.5, 220.91893865302774])
13:18:59,625 TRACE [com.simsilica.ethereal.zone.ZoneManager] endUpdate()
13:18:59,625 TRACE [com.simsilica.ethereal.zone.ZoneManager] No-updates for keys:[]
13:18:59,625 TRACE [com.simsilica.ethereal.zone.ZoneManager] writing history
13:18:59,625 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:commitUpdate() empty:false   children:[3]
13:18:59,625 TRACE [com.simsilica.ethereal.zone.ZoneManager] done writing history
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] collect()
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] publishFrame()
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:beginFrame(49590032000) selfPosition:Vec3d[0.047527313232421875, 40.4998779296875, -0.03924560546875]
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:stateChanged(StateBlock[time=49590032000, zone=0:0:1, updates=[StateEntry[3, Vec3d[54.45916419612827, 0.5, 221.3283845222499], Quatd[0.0, -0.963170754325055, 0.0, -0.2688904944636476]]]])
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] stateChanged() zone:0:0:1 updates:[StateEntry[3, Vec3d[54.45916419612827, 0.5, 221.3283845222499], Quatd[0.0, -0.963170754325055, 0.0, -0.2688904944636476]]] removals:null
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:endFrame(49590032000) selfPosition:Vec3d[54.45916419612827, 0.5, 221.3283845222499]
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] endFrame() acked queue size:1
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter] ackSentState(926)
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter]   sentStates.size():1  recAcks.size():1
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter] updating mostRecentAckedMessageId to:926
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter]   checking:926 and 926
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter]      found:926
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter]        removed recvd acks:IntRange[925:925]
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter]        adding recvd ack:926
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter] startMessage() frameTime:49573364900
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter] startMessage() -> receivedAcks.size():1 mostRecentAckedMessageId:926  nextMessageID:927 difference:1  max diff:1
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] end publishFrame()
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] publishFrame()
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(1:0:2, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(1:0:1, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(0:0:2, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(0:0:1, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(-1:0:2, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(-1:0:1, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-1:0:-2, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(0:0:-2, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(1:0:-2, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-1:0:-1, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(0:0:-1, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(1:0:-1, com.simsilica.ethereal.NetworkStateListener@1536020c)
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:beginFrame(49606698300) selfPosition:Vec3d[0.05916595458984375, 40.4998779296875, -0.0488433837890625]
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:endFrame(49606698300) selfPosition:Vec3d[0.05916595458984375, 40.4998779296875, -0.0488433837890625]
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] endFrame() acked queue size:0
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter] frame in size remaining.  Messages per frame:1
13:18:59,640 DEBUG [com.simsilica.ethereal.NetworkStateListener] Object no longer in active zones, marking removed:3
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] end publishFrame()
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] publishFrame()
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:beginFrame(49623365000) selfPosition:Vec3d[0.05916595458984375, 40.4998779296875, -0.0488433837890625]
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:endFrame(49623365000) selfPosition:Vec3d[0.05916595458984375, 40.4998779296875, -0.0488433837890625]
13:18:59,640 TRACE [com.simsilica.ethereal.NetworkStateListener] endFrame() acked queue size:0
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter] frame in size remaining.  Messages per frame:0
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] end publishFrame()
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter] frame in size remaining.  Messages per frame:0
13:18:59,640 TRACE [com.simsilica.ethereal.net.StateWriter] Sending message ID:927
13:18:59,640 TRACE [com.simsilica.ethereal.zone.StateCollector] end collect()
13:18:59,640 DEBUG [com.simsilica.ethereal.net.RemoteTimeSource] ======== Time delta:-83,780,079,508,300 nanos (-83,780,079.51 ms)  drift:-83,780,079,512,051 nanos (-83,780,079.51 ms)  windowSize:100
13:18:59,640 DEBUG [com.simsilica.ethereal.net.RemoteTimeSource] === oldDrift:-83780079512089  drift change:38 nanos (0 ms)
13:18:59,640 DEBUG [com.simsilica.ethereal.net.StateReceiver] Update state:ObjectStateMessage[id=927, time=49638234600, size=116]
13:18:59,640 DEBUG [com.simsilica.ethereal.net.StateReceiver] State:SentState[messageId=927, created=83829717820100, acked=[[IntRange[926:926]]], frames=[FrameState[time=49590032000, legacySequence=49590031872, columnId=1, states=[com.simsilica.ethereal.net.ObjectState[id=10, positionBits=29c6a2b555cd1d]]], FrameState[time=49606698300, legacySequence=49606698240, columnId=2097151, states=[com.simsilica.ethereal.net.ObjectState[id=10, REMOVED, positionBits=29c6a2b555cd1d]]], FrameState[time=49623365000, legacySequence=49623364864, columnId=2097151, states=[com.simsilica.ethereal.net.ObjectState[id=10, REMOVED, positionBits=29c6a2b555cd1d]]]]]
13:18:59,641 DEBUG [com.simsilica.ethereal.net.StateReceiver] Updating baseline for message:926
13:18:59,641 TRACE [com.simsilica.ethereal.NetworkStateListener] received message:927
13:18:59,641 DEBUG [com.simsilica.ethereal.net.StateReceiver] ** frame begin:49590032000
13:18:59,641 DEBUG [com.simsilica.ethereal.SharedObject] applyNetworkState(49590032000, com.simsilica.ethereal.net.ObjectState[id=10, positionBits=29c6a2b555cd1d])
13:18:59,641 DEBUG [com.simsilica.ethereal.net.StateReceiver] ** frame begin:49606698300
13:18:59,641 DEBUG [com.simsilica.ethereal.SharedObject] applyNetworkState(49606698300, com.simsilica.ethereal.net.ObjectState[id=10, REMOVED, positionBits=29c6a2b555cd1d])
13:18:59,642 TRACE [com.simsilica.ethereal.zone.ZoneManager] beginUpdate(49640031900)
13:18:59,642 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:beginUpdate(49640031900)
13:18:59,642 TRACE [com.simsilica.ethereal.zone.ZoneManager] updateEntity(3, true, Vec3d[55.16610525986306, 0.5, 220.71070323666498])
13:18:59,642 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:update(3, Vec3d[55.16610525986306, 0.5, 220.71070323666498])
13:18:59,642 TRACE [com.simsilica.ethereal.zone.ZoneManager] endUpdate()
13:18:59,642 TRACE [com.simsilica.ethereal.zone.ZoneManager] No-updates for keys:[]
13:18:59,642 TRACE [com.simsilica.ethereal.zone.ZoneManager] writing history
13:18:59,642 TRACE [com.simsilica.ethereal.zone.Zone] 0:0:1:commitUpdate() empty:false   children:[3]
13:18:59,642 TRACE [com.simsilica.ethereal.zone.ZoneManager] done writing history
13:18:59,644 DEBUG [infinity.client.SharedObjectUpdater] ****** Object removed[t=49606698300]:3  netId:10
13:18:59,644 DEBUG [infinity.client.SharedObjectUpdater] Setting entity to invisible for:3

asser_fahrenholz · January 1, 2021, 1:47pm

Dont know if this is anywhere near something… but, i’m wondering why the location of the “self” in the NSL is being removed from the entered zone keys:

14:24:49,353 TRACE [com.simsilica.ethereal.zone.ZoneManager] beginUpdate(10682794000)
14:24:49,353 TRACE [com.simsilica.ethereal.zone.Zone] 1:0:-1:beginUpdate(10682794000)
14:24:49,353 TRACE [com.simsilica.ethereal.zone.ZoneManager] updateEntity(3, true, Vec3d[49.884363889922696, 0.5, -8.021479782540247])
14:24:49,353 TRACE [com.simsilica.ethereal.zone.Zone] 1:0:-1:update(3, Vec3d[49.884363889922696, 0.5, -8.021479782540247])
14:24:49,353 TRACE [com.simsilica.ethereal.zone.ZoneManager] endUpdate()
14:24:49,353 TRACE [com.simsilica.ethereal.zone.ZoneManager] No-updates for keys:[]
14:24:49,353 TRACE [com.simsilica.ethereal.zone.ZoneManager] writing history
14:24:49,353 TRACE [com.simsilica.ethereal.zone.Zone] 1:0:-1:commitUpdate() empty:false   children:[3]
14:24:49,353 TRACE [com.simsilica.ethereal.zone.ZoneManager] done writing history
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] collect()
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] publishFrame()
14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:beginFrame(10649460100) selfPosition:Vec3d[-0.00201416015625, 0.4998779296875, -0.062023162841796875]
14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:stateChanged(StateBlock[time=10649460100, zone=1:0:-1, updates=[StateEntry[3, Vec3d[49.87719722419509, 0.5, -7.376300593946192], Quatd[0.0, 0.9717335334497018, 0.0, 0.23608036760679021]]]])
14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] stateChanged() zone:1:0:-1 updates:[StateEntry[3, Vec3d[49.87719722419509, 0.5, -7.376300593946192], Quatd[0.0, 0.9717335334497018, 0.0, 0.23608036760679021]]] removals:null
14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:endFrame(10649460100) selfPosition:Vec3d[49.87719722419509, 0.5, -7.376300593946192]
14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] endFrame() acked queue size:1
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter] ackSentState(156)
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter]   sentStates.size():1  recAcks.size():1
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter] updating mostRecentAckedMessageId to:156
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter]   checking:156 and 156
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter]      found:156
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter]        removed recvd acks:IntRange[155:155]
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter]        adding recvd ack:156
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter] startMessage() frameTime:10632793400
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter] startMessage() -> receivedAcks.size():1 mostRecentAckedMessageId:156  nextMessageID:157 difference:1  max diff:1
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] end publishFrame()
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] publishFrame()
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(2:0:-1, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(2:0:-2, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(1:0:0, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(1:0:-1, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(1:0:-2, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(2:0:0, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-2:0:-2, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-1:0:-2, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-2:0:-1, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-1:0:-1, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-2:0:0, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-1:0:0, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:beginFrame(10666126800) selfPosition:Vec3d[-0.001728057861328125, 0.4998779296875, -0.0612030029296875]
14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] 3:endFrame(10666126800) selfPosition:Vec3d[-0.001728057861328125, 0.4998779296875, -0.0612030029296875]
14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] endFrame() acked queue size:0
14:24:49,355 TRACE [com.simsilica.ethereal.net.StateWriter] frame in size remaining.  Messages per frame:1
14:24:49,355 DEBUG [com.simsilica.ethereal.NetworkStateListener] Object no longer in active zones, marking removed:3

So, we get a StateChange:

14:24:49,355 TRACE [com.simsilica.ethereal.NetworkStateListener] stateChanged() zone:1:0:-1

and then in the next bit, that cell is no longer being watched

14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(2:0:-1, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(2:0:-2, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(1:0:0, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(1:0:-1, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(1:0:-2, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] unwatch(2:0:0, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-2:0:-2, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-1:0:-2, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-2:0:-1, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-1:0:-1, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-2:0:0, com.simsilica.ethereal.NetworkStateListener@61735bfa)
14:24:49,355 TRACE [com.simsilica.ethereal.zone.StateCollector] watch(-1:0:0, com.simsilica.ethereal.NetworkStateListener@61735bfa)

And then the

14:24:49,355 DEBUG [com.simsilica.ethereal.NetworkStateListener] Object no longer in active zones, marking removed:3

Driving me nuts

asser_fahrenholz · January 1, 2021, 3:40pm

Edit: nope, that wasnt it

pspeed · January 1, 2021, 7:33pm

Do you set the self ID once and then never mess with it?

it’s been a while since I’ve had issues with SimEthereal but my memory tickles that in one case it was because I was doing weird things with self instead of just setting it during initialization and letting it update zones on its own. I don’t remember exactly what, though. Sometimes when I’m getting an app setup for the first time, I don’t have an entity to hook ‘self’ to and so end up doing something strange… then I forget and it bites me later.

That it still does it with trace logging on is at least something. Means it’s probably not timing related as trace logging should slow things down quite a bit.

P.S.: How long does the game have to run before this happens?

pspeed · January 1, 2021, 7:37pm

I know you deleted this but:
re: “I was sending world positions+rotation to NetworkStateListener - sending local ones instead now.”

Did you mistype? My recollection is that the application code shouldn’t be interacting with NetworkStateListener at all. You send your object updates to ZoneManager (and in world space).

asser_fahrenholz · January 1, 2021, 7:58pm

It varies from run to run unfortunately, can’t find a pattern to it. I am calling the setSelf all the time. I will try only setting it once connection is setup and then leaving it at that.

asser_fahrenholz · January 1, 2021, 8:12pm

The reason I am doing this is a leftover from your demo apps I think. In your CameraMovementState of net-demo (MOSS ref here), you call setView on gameSession, which in turn does this on the server session:

            // Force our viewpoint to the network view.
            // This is a bit of a hack and not officially supported to keep
            // resetting yourself... but it works.
            NetworkStateListener nsl = getService(EtherealHost.class).getStateListener(conn);
            //nsl.setMaxMessageSize(2000);
            if( nsl != null ) {
                nsl.setSelf(avatarEntity.getId(), location);
            }

asser_fahrenholz · January 1, 2021, 8:17pm

Well, it happens when I switch zones and it has to reload, but there’s no pattern to when this is triggered yet

pspeed · January 1, 2021, 9:17pm

I think those two things are related.

I think I hit problems with net-char and ended up fixing it there but I can’t remember.

And yeah, zone crossing is specifically the issue in those cases. I’d randomly see objects come in and out of view because zone transfer wasn’t happening correctly.

Edit: as far as I know, the sim-ethereal examples in simslica/examples still work… so they should be considered ‘canon’ until we discover otherwise.

asser_fahrenholz · January 2, 2021, 4:09pm

This seems to have fixed it (fingers crossed, no BodyPosition disappearing yet). Thanks for the help!