Sim-eth-es Troubleshootings

pspeed · January 5, 2019, 1:14am

It’s a ghost object. The client doesn’t need to know about it.

DO NOT CREATE A BODYPOSITION FOR IT>
YOU ARE CREATING IT.
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>
DO NOT CREATE A BODYPOSITION FOR IT>

Then there is no buffer to fill.

Show me the code where you call new BodyPosition() and I will show you how to fix it.

Darkchaos · January 5, 2019, 1:51am

It seems sometimes I just need to be told things in such clarity to understand it, in that moment I didn’t even think about if the clients needs them or not.

Unfortunately that left me with the next problem: After consuming, the Powerup should be removed, so I just called ed.removeEntity() which works on the server (the effect isn’t triggered again), but the client doesn’t receive the removal message.

Is there a process to trigger that manually? What am I doing wrong this time?

pspeed · January 5, 2019, 2:00am

ed.removeEntity() should be removing all of its components… so the client-side system that is displaying it should see it’s position, model info, etc. go away and lose the object.

…if that’s not happening then something strange is going on. Maybe the code that is handling static objects is not setup to remove them also?

Edit: can you tell that I’m back at work at my day job now so I’m more quickly triggered by repeating myself? (sorry about that)

Darkchaos · January 5, 2019, 2:34am

Nope, I didn’t see a ComponentChangeMessage printed into the console, so I’ve dug into the code,
One of these EntityComponents: Position fails at !isRelevantChange() in DefaultEntitySet#entityChange, however objectType is, so that shouldn’t be the case.

So is there something to debug why the change isn’t propagated over the net potentially? (the relevant EntityContainers’ removeObject is not called and I don’t see the debug message).

No Problem First off you are probably the only one to solve these mysteries for me and also it was more efficient than messenging back and forth about things which are designwise wrong.

pspeed · January 5, 2019, 2:46am

It’s kind of baffling to me because this was the one case that was working fine for me when I started trying to sort out my position filtering stuff.

Or at least I don’t think I made any zay-es-net changes that would affect this particular case. If you build from source then you might try master just to see, I guess.

Darkchaos · January 5, 2019, 3:04am

I tried to build from source (well actually I’ve used jitpack), but it didn’t change a thing. I can’t tell what happens though since SiO2 depends on an older version of zay-es, what gradle will do in such a case exactly.

However that bug was pre-visibility filter commits as those aren’t released yet

pspeed · January 5, 2019, 5:24am

In gradle, whatever version you specify will override the ones you get transitively.

…and if you are ever wondering which version of anything is picked up:
gradle dependencies
…will tell you.

Darkchaos · January 5, 2019, 10:36am

Okay that worked, I’ve also confirmed it by trying to import ComponentVisibility, so I’m definitely on master.
I’ve also tried to remove components like ObjectType manually, but I get the same result.
How can I debug this further? If I understood that “relevantChange” thing right, and if that would be the cause, I’d need an EntitySet on the server plainly listening for Positions?

But as I said, ObjectType was seen as relevant Change so there should’ve been a packet/event about that. Where would I have to look into?

pspeed · January 5, 2019, 3:44pm

If it was a relevant change then it should have been added to the outbound message. I don’t know if turning up logging will be helpful in this case or not.

This is definitely working for me so I’m not sure what the issue is. Those demos where you see the fountain of balls… each one of those balls is ed.removeEntity() after some fixed time period and they all get removed.

Darkchaos · January 5, 2019, 8:20pm

@pspeed So I stepped through the code until here: zay-es/HostedEntityData.java at master · jMonkeyEngine-Contributions/zay-es · GitHub

For the HealthComponent Change, I am seeing that last != null, but for all the removed entities, it is. Not sure if that is still related to the comment on Line 440 though.

Edit: And there is no later “loop” otherwise because in L308 it fails early in the next frame.

pspeed · January 5, 2019, 8:58pm

Line 308 is about resetting filters. Are there filters being reset at the same time as these entities are being deleted or something?

The only way I see that tracker wouldn’t have these components is if it never saw them… ie: the client never had them. So I’m not sure what’s going on.

…and locally, I see this work correctly all the time so I cannot say what could be wrong.

pspeed · January 5, 2019, 9:01pm

Hmmm… I wonder if this is case where the components were already there when the set was requested?

Though I can’t see how that would work properly… I also don’t see it failing locally, either. I may try to force a wide window to see if I can make it happen.

Edit: no, that works, too… and I now understand why it works for new sets that already have values… because every update we mark them in the tracker again when they are in the set:

github.com

jMonkeyEngine-Contributions/zay-es/blob/master/extensions/Zay-ES-Net/src/main/java/com/simsilica/es/server/HostedEntityData.java#L458


    
    // Note: 2018-12-15 - since I just had to reteach myself, I'm
    // leaving a comment.  The reason that we don't see set.getRemovedEntities()
    // or set.getChangedEntities() is because we are going to send all of the
    // relevant EntityChange events in a later loop and that will take care
    // of that.  We specifically process added entities here so that we can send
    // the full component list for that entity.  I guess one of those is
    // probably redundant with a change we'll send later but so be it.                    
    
    // Follow up with anything remaining in the buffer 
    if( !entityBuffer.isEmpty() ) {
        sendAndClear(e.getKey(), entityBuffer);
    }
}
set.clearChangeSets();  // we don't need them
 
// Step 3: 'mark' usage in the tracker if there are entities
// in the set at all
if( !set.isEmpty() ) {
    Class<EntityComponent>[] types = ed.getTypes(set);
    for( Class<EntityComponent> type : types ) {

…at first I worried that this was another applyChanges() versus values already in the set issue. But past-me was smarter than that.

Darkchaos · January 5, 2019, 9:26pm

You probably have the wrong version currently, L308 is

if( changes.isEmpty() ) {
            return false;
        }

for me (actually the return statement).
So nothing is filtered at all, but that was just regards the comment in Line 440 saying that removes and changes will be handled in a “later loop”, so I was assuming another iteration.

If you have the time feel free to checkout github: MeFisto94/Monake.
From Breakpointing I can say though that the changes were present in HostedEntityData L475 in frameChanges, but skipped there because last == null.

I can clearly see an entitySet which only consists of objectType and Position though, so there has to be a listener…

I think I got something:
In L456, set has shrinked because the to-be-removed-entity is removed from there so it doesn’t mark any usage anymore in the tracker. Maybe one have to track the removed entities as being changed in line 451?

Edit: Though then the question is why they never appeared in the tracker, right?
Edit2: So fired up FINE Logging and there is never a call to L401 (“Updating entity sets”) for the related set before the remove happens, so clearly it’s tracker defaults to null.

22:46:10,275 TRACE [HostedEntityData] getEntitySet:GetEntitySetMessage[2, null, [class com.jmonkeyengine.monake.es.ObjectType, class com.jmonkeyengine.monake.es.Position]]
22:46:10,275 TRACE [HostedEntityData] Creating set for ID:2
22:46:10,275 TRACE [EntityDataWrapper] findEntities(null, [class com.jmonkeyengine.monake.es.ObjectType, class com.jmonkeyengine.monake.es.Position])
22:46:10,275 TRACE [EntityDataWrapper] getComponent(EntityId[0], class com.jmonkeyengine.monake.es.ObjectType)
22:46:10,275 TRACE [EntityDataWrapper] getComponent(EntityId[0], class com.jmonkeyengine.monake.es.Position)
22:46:10,275 INFO  [MessageDebugger] Received:EntityDataMessage[1, [ComponentData[EntityId[3], [ObjectType[type=1], BodyPosition[null]]]]]
22:46:10,275 TRACE [EntityDataWrapper] getComponent(EntityId[1], class com.jmonkeyengine.monake.es.ObjectType)
22:46:10,276 TRACE [EntityDataWrapper] getComponent(EntityId[1], class com.jmonkeyengine.monake.es.Position)

Maybe HostedEntityData getEntitySet has to trigger the tracker once so we even know what is being kept track of?
I wonder why it’s not in activeEntities though

pspeed · January 5, 2019, 9:54pm

activeEntities is for WatchedEntities.

I mean, it seems like you have some kind of case where things happen so fast that something gets skipped.

Like, EntitySet is retrieved with entity.
Entity is removed.
sendUpdates() is called.

…but then I don’t know why the frameChanges would be empty.

I was looking at the version you posted the link to… I assumed you posted the correct version.

Darkchaos · January 5, 2019, 10:01pm

Oh my fault, the L308 was for EntityDataWrapper, so sorry for that.

That’s true, I just noticed there is an activeSets as well, might’ve confused the two.

And no, I’m not really having fast paced things here, you can see a few seconds delay, first the models are displayed (that is retrieval of the EntitySet) and then I have to manually collide with the pick up item, that’s where sendUpdates doesn’t quit early.

The thing is this: The EntitySet is requested by the client but then never changed, so I guess in that case there might be a missing call to the tracker, the tracker should probably called as soon as the entitySet has been added to the activeSets, because that’s the actual time where it got requested/synched (sendAndClear is called)

pspeed · January 5, 2019, 10:06pm

Hmmm… it’s weird because I tested exactly this case: EntitySet that never changes until object is deleted.

I will dig a little deeper.

Edit: yeah, pretty sure you are correct. I also discovered another interesting issue is that if there are no simethereal objects in view then time doesn’t advance at all on the client.

pspeed · January 5, 2019, 10:52pm

That issue should be fixed in git now.

The magic line:

github.com

jMonkeyEngine-Contributions/zay-es/blob/master/extensions/Zay-ES-Net/src/main/java/com/simsilica/es/server/HostedEntityData.java#L304


    //  using a short-lived lock for that case.)
    activeSets.put(setId, set);
    
    // Pretend that a filter has been reset so that the sendUpdates() loop
    // will make one pass through the sets and mark the tracker for this new
    // entity set.  Without this, sets retrieved won't see their removes if
    // there are no other entity updates between set retrieval and entity removal.
    // Reusing this flag is a bit of a hack... but technically it's not wrong.
    // "Why can't we just update tracker here?"... because it's not thread safe
    // to do so.
    filtersReset.set(true);
}
 
public void resetEntitySetFilter( HostedConnection source, ResetEntitySetFilterMessage msg ) {
    if( log.isTraceEnabled() ) {
        log.trace( "resetEntitySetFilter:" + msg );
    }
    
    // Note: we could avoid the lock by queuing a command that applies
    //       the filter in sendUpdates() but we don't really avoid much
    //       threading overhead that way.

Darkchaos · January 5, 2019, 11:11pm

Great, and even included what I just thought: Why can’t we just update tracker here?
Unfortunately I still see that issue here, but don’t have the time to debug it right now, but I will as soon as I have the time.

Edit: I think that is because of a dependency issue then, because my jitpack build has another maven package id and hence isn’t used by SiO2 I guess.

Edit2: Yep that’s it. It works now, thanks again

remy_vd · April 14, 2019, 5:02pm

Bumping this thread… I have the same issue with the StateWriter complaining about the mismatched time sources.

I actually implemented the setTimeSource() method as you described, but instead of using GameSystemManager.getStepTime() I use the GameLoop.getStepTime(). Since my systems are being updated by another thread (game loop).

When I use the GameLoop SimTime, I get the warning messages about the delta being to large:

2019-04-14 16:52:03,920 WARN  [StateCollectionThread] com.simsilica.ethereal.net.StateWriter:209 - Mismatched time sources.  Delta:23315.122099169 seconds

When I use the GameSystemManager SimTime however, the error is gone.

pspeed · April 14, 2019, 8:42pm

You should be using the one from the GameSystemManager here. We aren’t using the “step” time, we’re accessing the raw time that the StepTime provides.

 ethereal.setTimeSource(new TimeSource() {
                @Override
                public long getTime() {
                    return systems.getStepTime().getUnlockedTime(System.nanoTime());
                }
            });

There may be some misunderstanding about what the GameLoop StepTime is giving you. The time provided by GameLoop and GameSystemsManager are effectively the same “time”. In fact, GameLoop is just calling down into the GameSystemManager.

There are two “times” we talk about here. “real time” and “step time”. “Step time” is the time that doesn’t move for some frame. This is useful when you are trying to pin things down in that frame because frames last long enough that a nano-timer will certainly be different at the beginning and the ending of a frame.

SimEthereal doesn’t want step time. It wants real actual-on-the-click-right-this-instant time. The same one used to generate the frame time.

The other issue is that even if you DID want “step time”, GameLoop won’t give it to you like you’ve done it. For one, the StepTime provided by GameLoop is only updated when you call GameLoop.getStepTime(). So if you don’t call that once per frame then the TimeStep it’s providing is never changing. For another, the physics (and physics listeners) are being updated by the game system manager… and so will want the time step provided by the manager anyway. So even if you wanted “step” time in this context (which we don’t), the two values would be the same (if they were both updated properly).

Bottom line: use the fix as I’ve provided it.