SimEthereal Questions

Troubleshooting networking
1

Hello

I have been playing with a non es version of @pspeed simethereal demo. I have a couple of things I am a bit curious about.

I’ve increased the speed of the ship a bit and changed it to top down view so I can see my own ship model. When moving around I sometimes get the below messages printed on the console. When this happens the ship rendering ‘jerks’ a bit.

Purging >5 history frames:6
collect underflow FPS:17
zone update underflow FPS:10
collect underflow FPS:19

I am just curious what these messages mean and if there is an easy way to alleviate this problem.

Also, I’ve been playing with the grid sizes a bit and this message popped up.

05:45:11,061 WARN [ZoneManager] Body is updating a zone that does not exist, id:42, zone:61:-57:-1

I am not sure what this message means either. Any help would be appreciated.

Thanks, Mithrin

2

They mean that one of the ‘constant processing threads’ got more time taken away than it expected. There are settings you can use to make them sleep less when they are idle which can somewhat alleviate the issue but there will always be the chance that they miss frames.

Means that more history was collected than reasonably expected before flushing it to the output streams. The thread that flushes the data got behind, basically. In normal configuration, you expect flushes every 3 frames of data or so.

I think that one goes hand in hand. I’m operating on lack of sleep so I may be misremembering which thread does what, but I believe it’s the state collector that pulls the history and sends it.

Or it might be this one.

Either way, each of these indicates a different thread that missed some processing. State collection and purging should be 20 FPS by normal configuration.

These watchdog printlns may eventually be removed and replaced with something else. They are kind of currently hard-coded to standard expectations that may not hold if you use odd frame rates for pushing data or whatever.

Can’t comment too far on this one without knowing what the zone setup that caused it was. If you can provide the conditions that caused it then I will look further… and at that time look into more detail on the other messages as well if you haven’t already poked in the code for them.

3

Ok, that makes sense, I will investigate that further. Thank you. I was basically just moving in circles when it started to happen, I got the feeling that I was crossing zone boundaries. I will dig deeper into the code. Any direction on the idle time settings you mentioned would be awesome.

I used a gameconstant gridSize of 64 and a MAX_OBJECT_RADIUS of 17 when I started seeing those kinds of messages pop up. I also increased the speed of the player to 16 max, so I was moving between zones fairly quickly I think.

Mithrin

4

Did you see this by itself or was it in a group of them?

I honestly can’t figure out how that message can happen.

5

The instance I pasted from there was 20+ of them, if I reduced the gridsize even further they were constant and my ship started flickering. I will investigate further and let you know.

Mithrin

6

I downloaded the latest sim-eth-es and haven’t been able to replicate my problem with it. The console is being spammed with “Time rolled backwords:0 nanos” though which seems a bit odd, it isn’t being recorded to the logfile either. Is there a way to supress this message? Its coming from simethereal itself.

I will work with the latest version, its possible I was using something old in my last build.

Thanks, Mithrin

7

Are you by any chance running with vsync off?

a) I need to fix the message because it probably shouldn’t display for 0, but
b) it’s very strange that you are somehow requesting time so often that it has not advanced even one nanosecond.

Either that or you client-server drift is somehow consistently exactly the delta in time moving forward which would also be very strange.

Even with 0 it’s kind of an indication of a problem somewhere.

8

Yes I am running with vsync turned off… I just fired it up with vsync turned on and the same message occured. I am not running a separate server instance, just hosting and hitting join in case that makes any difference.

Mithrin

9

I’ll try to beef up the error message later this weekend.so we can see what’s up.

10

Latest commit converts this to a warning and includes more information:

For time not to advance, either System.nanoTime() is not advancing or there is such an odd confluence of drift that it causes it to seem that way… which also seems unlikely.

11

Here is the console output after updating simethereal.

13:48:24,999 WARN [RemoteTimeSource] Time didn’t advance:0 nanos. Current:1171
73358123348 Last:117173358123348 Raw:117173458613569 Drift:-490221 Offset:-100000000
13:48:25,001 WARN [RemoteTimeSource] Time didn’t advance:0 nanos. Current:1171
73359588290 Last:117173359588290 Raw:117173460078511 Drift:-490221 Offset:-100000000
13:48:25,003 WARN [RemoteTimeSource] Time didn’t advance:0 nanos. Current:1171
73361788583 Last:117173361788583 Raw:117173462278804 Drift:-490221 Offset:-100000000
13:48:25,004 WARN [RemoteTimeSource] Time didn’t advance:0 nanos. Current:1171
73362531998 Last:117173362531998 Raw:117173463022219 Drift:-490221 Offset:-100000000
13:48:25,004 WARN [RemoteTimeSource] Time didn’t advance:0 nanos. Current:1171
73363360659 Last:117173363360659 Raw:117173463850880 Drift:-490221 Offset:-100000000
13:48:25,005 WARN [RemoteTimeSource] Time didn’t advance:0 nanos. Current:1171
73364010379 Last:117173364010379 Raw:117173464500600 Drift:-490221 Offset:-100000000
13:48:25,007 WARN [RemoteTimeSource] Time didn’t advance:0 nanos. Current:1171
73366172656 Last:117173366172656 Raw:117173466662877 Drift:-490221 Offset:-100000000

12

Also, while playing around with the latest version, I noticed a couple of things. I changed the camera to a top down view and flew really far away. When I logged in another client (on the same computer) it showed a ghost copy of my original ship. If I flew back within range it would disappear. http://sli.mg/Bdessb for a screenshot

Second issue, which I had occur to me on my previous build which I had modified quite heavily so I just figured it was something I had done. I occasionally get this message on logon "RuntimeException Error deserializing object, class ID: -48 If I click ok and then try joining again it usually lets me in. http://sli.mg/f7lZ3A for a screenshot

Thank you for your help :smiley:

13

The app keeps a log on disk that should have the full stack trace. Might be helpful.

Are you registering any of your own serializable stuff? When? etc.

Ok… this I should be able to recreate I guess.

14

This implies that you are somehow calling getTime() often enough that nanoTime() hasn’t advanced… which is strange because even two calls to nanoTime() in a row will generally give different values.

Do you call getTime() yourself in your code or is it only the default stuff that is calling it? I can’t remember whether I added the consistent time stuff to basic or es. I’ll take a look.

15

Also, since I’m unclear and it’s finally at a point that this information will be helpful…

Were these issues seen in your own app that uses SimEthereal, in the sim-eth-basic example, or in the sim-eth-es example?

Either way, if you use one of the examples, I’ve just updated their ModelViewState to grab the time from the TimeState instead of directly from the TimeSource. If this fixes the problem then that provides some more information.

Edit: especially regarding the ‘ghost’ issue… which sim-eth example you are using is important because they do object management completely differently.

16

Serializer error was in a pretty modified sim-eth-basic and in a unmodified sim-eth-es.

Ghosting was in sim-eth-es after playing with the camera view.

I’ll replicate the serializer error and then post the logfile. I have not registered any of my own serializers or messed with that code at all. That is one of the reasons I downloaded a fresh copy of sim-eth-es yesterday and played with it today, to remove anything I might have done to complicate things.

I haven’t done anything with time at all. I will change my current copy as per your last commit and I’ll let you know.

17

16:54:10,128 INFO [ConnectionState] Client started.
16:54:10,151 INFO [SerializerRegistrationsMessage] Registering:Registration[-19 = com.jme3.math.Vector3f, serializer=com.jme3.network.serializing.serializers.Vector3Serializer]
16:54:10,151 INFO [SerializerRegistrationsMessage] Registering:Registration[-41 = com.jme3.network.serializing.serializers.FieldSerializer, serializer=null]
16:54:10,151 INFO [SerializerRegistrationsMessage] Registering:Registration[-43 = [I, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
16:54:10,151 INFO [SerializerRegistrationsMessage] Registering:Registration[-46 = [Lcom.jme3.network.message.SerializerRegistrationsMessage$Registration;, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
16:54:10,152 INFO [SerializerRegistrationsMessage] Registering:Registration[-49 = [Ljava.lang.Object;, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
16:54:10,152 INFO [SerializerRegistrationsMessage] Registering:Registration[-48 = com.jme3.network.service.rpc.msg.RpcCallMessage, serializer=null]
16:54:10,152 INFO [SerializerRegistrationsMessage] Registering:Registration[-50 = com.jme3.network.service.rpc.msg.RpcResponseMessage, serializer=null]
16:54:10,153 INFO [SerializerRegistrationsMessage] Registering:Registration[-51 = com.jme3.network.service.rmi.ClassInfo, serializer=null]
16:54:10,155 INFO [SerializerRegistrationsMessage] Registering:Registration[-52 = com.jme3.network.service.rmi.MethodInfo, serializer=null]
16:54:10,155 INFO [SerializerRegistrationsMessage] Registering:Registration[-53 = com.jme3.math.Quaternion, serializer=null]
16:54:10,155 INFO [SerializerRegistrationsMessage] Registering:Registration[-54 = com.simsilica.ethereal.net.ClientStateMessage, serializer=null]
16:54:10,156 INFO [SerializerRegistrationsMessage] Registering:Registration[-56 = [B, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
16:54:10,156 INFO [SerializerRegistrationsMessage] Registering:Registration[-55 = com.simsilica.ethereal.net.ObjectStateMessage, serializer=null]
16:54:10,157 INFO [SerializerRegistrationsMessage] Registering:Registration[-57 = java.lang.Class, serializer=com.simsilica.es.net.ClassSerializer]
16:54:10,157 INFO [SerializerRegistrationsMessage] Registering:Registration[-58 = java.lang.reflect.Field, serializer=com.simsilica.es.net.ClassFieldSerializer]
16:54:10,158 INFO [SerializerRegistrationsMessage] Registering:Registration[-59 = com.simsilica.es.net.ComponentChangeMessage, serializer=null]
16:54:10,158 INFO [SerializerRegistrationsMessage] Registering:Registration[-60 = com.simsilica.es.net.EntityDataMessage, serializer=null]
16:54:10,159 INFO [SerializerRegistrationsMessage] Registering:Registration[-62 = com.simsilica.es.EntityId, serializer=null]
16:54:10,160 INFO [SerializerRegistrationsMessage] Registering:Registration[-61 = com.simsilica.es.net.EntityDataMessage$ComponentData, serializer=null]
16:54:10,160 INFO [SerializerRegistrationsMessage] Registering:Registration[-63 = com.simsilica.es.net.EntityIdsMessage, serializer=null]
16:54:10,161 INFO [SerializerRegistrationsMessage] Registering:Registration[-64 = com.simsilica.es.net.FindEntitiesMessage, serializer=null]
16:54:10,162 INFO [SerializerRegistrationsMessage] Registering:Registration[-65 = com.simsilica.es.net.FindEntityMessage, serializer=null]
16:54:10,162 INFO [SerializerRegistrationsMessage] Registering:Registration[-66 = com.simsilica.es.net.GetComponentsMessage, serializer=null]
16:54:10,163 INFO [SerializerRegistrationsMessage] Registering:Registration[-67 = com.simsilica.es.net.GetEntitySetMessage, serializer=null]
16:54:10,163 INFO [SerializerRegistrationsMessage] Registering:Registration[-68 = com.simsilica.es.net.ReleaseEntitySetMessage, serializer=null]
16:54:10,164 INFO [SerializerRegistrationsMessage] Registering:Registration[-69 = com.simsilica.es.net.ReleaseWatchedEntityMessage, serializer=null]
16:54:10,164 INFO [SerializerRegistrationsMessage] Registering:Registration[-70 = com.simsilica.es.net.ResetEntitySetFilterMessage, serializer=null]
16:54:10,165 INFO [SerializerRegistrationsMessage] Registering:Registration[-71 = com.simsilica.es.net.ResultComponentsMessage, serializer=null]
16:54:10,165 INFO [SerializerRegistrationsMessage] Registering:Registration[-72 = com.simsilica.es.net.StringIdMessage, serializer=null]
16:54:10,165 INFO [SerializerRegistrationsMessage] Registering:Registration[-73 = com.simsilica.es.net.WatchEntityMessage, serializer=null]
16:54:10,166 INFO [SerializerRegistrationsMessage] Registering:Registration[-62 = com.simsilica.es.EntityId, serializer=null]
16:54:10,166 INFO [SerializerRegistrationsMessage] Registering:Registration[-74 = com.simsilica.es.CreatedBy, serializer=null]
16:54:10,167 INFO [SerializerRegistrationsMessage] Registering:Registration[-75 = com.simsilica.es.Name, serializer=null]
16:54:10,167 INFO [SerializerRegistrationsMessage] Registering:Registration[-76 = com.simsilica.es.filter.FieldFilter, serializer=null]
16:54:10,168 INFO [SerializerRegistrationsMessage] Registering:Registration[-77 = com.simsilica.es.filter.OrFilter, serializer=null]
16:54:10,169 INFO [SerializerRegistrationsMessage] Registering:Registration[-78 = com.simsilica.es.filter.AndFilter, serializer=null]
16:54:10,169 INFO [SerializerRegistrationsMessage] Registering:Registration[-79 = com.simsilica.es.EntityChange, serializer=com.simsilica.es.net.EntityChangeSerializer]
16:54:10,170 INFO [SerializerRegistrationsMessage] Registering:Registration[-75 = com.simsilica.es.Name, serializer=null]
16:54:10,170 INFO [SerializerRegistrationsMessage] Registering:Registration[-80 = example.es.BodyPosition, serializer=null]
16:54:10,176 INFO [SharedObjectUpdater] start()
16:54:10,179 INFO [ConnectionState] clientConnected(com.jme3.network.base.DefaultClient@97a5f5a)
16:54:10,180 INFO [ConnectionState] onConnected()
16:54:10,895 INFO [ConnectionState] join(Min117)
16:54:11,119 INFO [PlayerMovementState] initialize()
16:54:11,123 INFO [PlayerMovementState] onEnable()
16:54:11,202 INFO [GameSessionState] initialize()
16:54:11,206 INFO [GameSessionState] Player object:EntityId[1]
16:54:13,883 INFO [InGameMenuState] exitGame()
16:54:15,070 ERROR [LegacyApplication] Uncaught exception thrown in Thread[jME3 Main,5,main]
java.lang.RuntimeException: Error invoking action method:stop
at com.simsilica.lemur.CallMethodAction.execute(CallMethodAction.java:180) ~[lemur-proto-1.7.2-SNAPSHOT.jar:?]
at com.simsilica.lemur.ActionButton$ClickCommand.execute(ActionButton.java:132) ~[lemur-proto-1.7.2-SNAPSHOT.jar:?]
at com.simsilica.lemur.ActionButton$ClickCommand.execute(ActionButton.java:127) ~[lemur-proto-1.7.2-SNAPSHOT.jar:?]
at com.simsilica.lemur.core.CommandMap.runCommands(CommandMap.java:61) ~[lemur-1.9.1-SNAPSHOT.jar:?]
at com.simsilica.lemur.Button.runClick(Button.java:333) ~[lemur-1.9.1-SNAPSHOT.jar:?]
at com.simsilica.lemur.Button$ButtonMouseHandler.mouseButtonEvent(Button.java:410) ~[lemur-1.9.1-SNAPSHOT.jar:?]
at com.simsilica.lemur.event.MouseEventControl.mouseButtonEvent(MouseEventControl.java:122) ~[lemur-1.9.1-SNAPSHOT.jar:?]
at com.simsilica.lemur.event.PickEventSession.buttonEvent(PickEventSession.java:553) ~[lemur-1.9.1-SNAPSHOT.jar:?]
at com.simsilica.lemur.event.MouseAppState.dispatch(MouseAppState.java:97) ~[lemur-1.9.1-SNAPSHOT.jar:?]
at com.simsilica.lemur.event.MouseAppState$MouseObserver.onMouseButtonEvent(MouseAppState.java:112) ~[lemur-1.9.1-SNAPSHOT.jar:?]
at com.jme3.input.InputManager.processQueue(InputManager.java:831) ~[jme3-core-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.input.InputManager.update(InputManager.java:907) ~[jme3-core-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.app.LegacyApplication.update(LegacyApplication.java:725) ~[jme3-core-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.app.SimpleApplication.update(SimpleApplication.java:227) ~[jme3-core-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.system.lwjgl.LwjglAbstractDisplay.runLoop(LwjglAbstractDisplay.java:151) ~[jme3-lwjgl-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.system.lwjgl.LwjglDisplay.runLoop(LwjglDisplay.java:193) ~[jme3-lwjgl-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.system.lwjgl.LwjglAbstractDisplay.run(LwjglAbstractDisplay.java:232) ~[jme3-lwjgl-3.1.0-beta1.jar:3.1-beta1]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_92]
Caused by: java.lang.IllegalArgumentException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_92]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_92]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_92]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_92]
at com.simsilica.lemur.CallMethodAction.execute(CallMethodAction.java:178) ~[lemur-proto-1.7.2-SNAPSHOT.jar:?]
… 17 more
16:54:15,131 INFO [GameClient] close()
16:54:15,131 INFO [SharedObjectUpdater] stop()
16:54:15,133 INFO [ConnectionState] clientDisconnected(com.jme3.network.base.DefaultClient@97a5f5a, null)
16:54:20,136 INFO [JmeSystem] Running on jMonkeyEngine 3.1-beta1

  • Branch: HEAD
  • Git Hash: 310f4db
  • Build Date: 2016-04-25
    16:54:20,414 INFO [LwjglContext] LWJGL 2.9.3 context running on thread jME3 Main
  • Graphics Adapter: aticfx64
  • Driver Version: 8.17.10.1404
  • Scaling Factor: 1
    16:54:20,432 INFO [GLRenderer] OpenGL Renderer Information
  • Vendor: ATI Technologies Inc.
  • Renderer: ATI FirePro V (FireGL V) Graphics Adapter
  • OpenGL Version: 4.5.13411 Compatibility Profile Context FireGL 15.201.2401.0
  • GLSL Version: 4.40
  • Profile: Compatibility
    16:54:20,521 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.blender.BlenderModelLoader
    16:54:20,556 INFO [DefaultControllerEnvironment] Loading: net.java.games.input.DirectAndRawInputEnvironmentPlugin
    16:54:20,824 INFO [ALAudioRenderer] Audio Renderer Information
  • Device: OpenAL Soft
  • Vendor: OpenAL Community
  • Renderer: OpenAL Soft
  • Version: 1.1 ALSOFT 1.15.1
  • Supported channels: 64
  • ALC extensions: ALC_ENUMERATE_ALL_EXT ALC_ENUMERATION_EXT ALC_EXT_CAPTURE ALC_EXT_DEDICATED ALC_EXT_disconnect ALC_EXT_EFX ALC_EXT_thread_local_context ALC_SOFT_loopback
  • AL extensions: AL_EXT_ALAW AL_EXT_DOUBLE AL_EXT_EXPONENT_DISTANCE AL_EXT_FLOAT32 AL_EXT_IMA4 AL_EXT_LINEAR_DISTANCE AL_EXT_MCFORMATS AL_EXT_MULAW AL_EXT_MULAW_MCFORMATS AL_EXT_OFFSET AL_EXT_source_distance_model AL_LOKI_quadriphonic AL_SOFT_buffer_samples AL_SOFT_buffer_sub_data AL_SOFTX_deferred_updates AL_SOFT_direct_channels AL_SOFT_loop_points AL_SOFT_source_latency
    16:54:20,825 WARN [ALAudioRenderer] Pausing audio device not supported.
    16:54:20,825 INFO [ALAudioRenderer] Audio effect extension version: 1.0
    16:54:20,825 INFO [ALAudioRenderer] Audio max auxiliary sends: 4
    16:54:20,915 INFO [GuiGlobals] Initializing GuiGlobals with:com.simsilica.lemur.GuiGlobals@41a6d32a
    16:54:20,924 INFO [GuiGlobals] Lemur build date:20160916
    16:54:23,459 INFO [MainMenuState] Connect… host:localhost port:4271
    16:54:23,565 INFO [ConnectionState] Creating game client for:localhost 4271
    16:54:23,567 INFO [GameClient] Connecting to:localhost 4271
    16:54:23,600 INFO [GameClient] Adding services…
    16:54:23,627 INFO [SharedObjectUpdater] onInitialize()
    16:54:23,627 INFO [ConnectionState] Connection established:example.net.client.GameClient@1c67537e
    16:54:23,628 INFO [ConnectionState] Starting client…
    16:54:23,628 INFO [GameClient] start()
    16:54:23,628 INFO [ConnectionState] Connection established:example.net.client.GameClient@1c67537e
    16:54:23,629 INFO [ConnectionState] Client started.
    16:54:23,784 INFO [SerializerRegistrationsMessage] Registering:Registration[-19 = com.jme3.math.Vector3f, serializer=com.jme3.network.serializing.serializers.Vector3Serializer]
    16:54:23,784 INFO [SerializerRegistrationsMessage] Registering:Registration[-41 = com.jme3.network.serializing.serializers.FieldSerializer, serializer=null]
    16:54:23,784 INFO [SerializerRegistrationsMessage] Registering:Registration[-43 = [I, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
    16:54:23,784 INFO [SerializerRegistrationsMessage] Registering:Registration[-46 = [Lcom.jme3.network.message.SerializerRegistrationsMessage$Registration;, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
    16:54:23,785 INFO [SerializerRegistrationsMessage] Registering:Registration[-49 = [Ljava.lang.Object;, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
    16:54:23,785 INFO [SerializerRegistrationsMessage] Registering:Registration[-48 = com.jme3.network.service.rpc.msg.RpcCallMessage, serializer=null]
    16:54:23,785 INFO [SerializerRegistrationsMessage] Registering:Registration[-50 = com.jme3.network.service.rpc.msg.RpcResponseMessage, serializer=null]
    16:54:23,786 INFO [SerializerRegistrationsMessage] Registering:Registration[-51 = com.jme3.network.service.rmi.ClassInfo, serializer=null]
    16:54:23,787 INFO [SerializerRegistrationsMessage] Registering:Registration[-52 = com.jme3.network.service.rmi.MethodInfo, serializer=null]
    16:54:23,787 INFO [SerializerRegistrationsMessage] Registering:Registration[-53 = com.jme3.math.Quaternion, serializer=null]
    16:54:23,787 INFO [SerializerRegistrationsMessage] Registering:Registration[-54 = com.simsilica.ethereal.net.ClientStateMessage, serializer=null]
    16:54:23,788 INFO [SerializerRegistrationsMessage] Registering:Registration[-56 = [B, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
    16:54:23,788 INFO [SerializerRegistrationsMessage] Registering:Registration[-55 = com.simsilica.ethereal.net.ObjectStateMessage, serializer=null]
    16:54:23,789 INFO [SerializerRegistrationsMessage] Registering:Registration[-57 = java.lang.Class, serializer=com.simsilica.es.net.ClassSerializer]
    16:54:23,789 INFO [SerializerRegistrationsMessage] Registering:Registration[-58 = java.lang.reflect.Field, serializer=com.simsilica.es.net.ClassFieldSerializer]
    16:54:23,790 INFO [SerializerRegistrationsMessage] Registering:Registration[-59 = com.simsilica.es.net.ComponentChangeMessage, serializer=null]
    16:54:23,790 INFO [SerializerRegistrationsMessage] Registering:Registration[-60 = com.simsilica.es.net.EntityDataMessage, serializer=null]
    16:54:23,791 INFO [SerializerRegistrationsMessage] Registering:Registration[-62 = com.simsilica.es.EntityId, serializer=null]
    16:54:23,791 INFO [SerializerRegistrationsMessage] Registering:Registration[-61 = com.simsilica.es.net.EntityDataMessage$ComponentData, serializer=null]
    16:54:23,856 INFO [SerializerRegistrationsMessage] Registering:Registration[-63 = com.simsilica.es.net.EntityIdsMessage, serializer=null]
    16:54:23,857 INFO [SerializerRegistrationsMessage] Registering:Registration[-64 = com.simsilica.es.net.FindEntitiesMessage, serializer=null]
    16:54:23,857 INFO [SerializerRegistrationsMessage] Registering:Registration[-65 = com.simsilica.es.net.FindEntityMessage, serializer=null]
    16:54:23,858 INFO [SerializerRegistrationsMessage] Registering:Registration[-66 = com.simsilica.es.net.GetComponentsMessage, serializer=null]
    16:54:23,858 INFO [SerializerRegistrationsMessage] Registering:Registration[-67 = com.simsilica.es.net.GetEntitySetMessage, serializer=null]
    16:54:23,859 INFO [SerializerRegistrationsMessage] Registering:Registration[-68 = com.simsilica.es.net.ReleaseEntitySetMessage, serializer=null]
    16:54:23,859 INFO [SerializerRegistrationsMessage] Registering:Registration[-69 = com.simsilica.es.net.ReleaseWatchedEntityMessage, serializer=null]
    16:54:23,860 INFO [SerializerRegistrationsMessage] Registering:Registration[-70 = com.simsilica.es.net.ResetEntitySetFilterMessage, serializer=null]
    16:54:23,860 INFO [SerializerRegistrationsMessage] Registering:Registration[-71 = com.simsilica.es.net.ResultComponentsMessage, serializer=null]
    16:54:23,861 INFO [SerializerRegistrationsMessage] Registering:Registration[-72 = com.simsilica.es.net.StringIdMessage, serializer=null]
    16:54:23,861 INFO [SerializerRegistrationsMessage] Registering:Registration[-73 = com.simsilica.es.net.WatchEntityMessage, serializer=null]
    16:54:23,862 INFO [SerializerRegistrationsMessage] Registering:Registration[-62 = com.simsilica.es.EntityId, serializer=null]
    16:54:23,862 INFO [SerializerRegistrationsMessage] Registering:Registration[-74 = com.simsilica.es.CreatedBy, serializer=null]
    16:54:23,862 INFO [SerializerRegistrationsMessage] Registering:Registration[-75 = com.simsilica.es.Name, serializer=null]
    16:54:23,863 INFO [SerializerRegistrationsMessage] Registering:Registration[-76 = com.simsilica.es.filter.FieldFilter, serializer=null]
    16:54:23,863 INFO [SerializerRegistrationsMessage] Registering:Registration[-77 = com.simsilica.es.filter.OrFilter, serializer=null]
    16:54:23,864 INFO [SerializerRegistrationsMessage] Registering:Registration[-78 = com.simsilica.es.filter.AndFilter, serializer=null]
    16:54:23,865 INFO [SerializerRegistrationsMessage] Registering:Registration[-79 = com.simsilica.es.EntityChange, serializer=com.simsilica.es.net.EntityChangeSerializer]
    16:54:23,865 INFO [SerializerRegistrationsMessage] Registering:Registration[-75 = com.simsilica.es.Name, serializer=null]
    16:54:23,866 INFO [SerializerRegistrationsMessage] Registering:Registration[-80 = example.es.BodyPosition, serializer=null]
    16:54:23,871 INFO [SharedObjectUpdater] start()
    16:54:23,874 INFO [ConnectionState] clientConnected(com.jme3.network.base.DefaultClient@7abd58f2)
    16:54:23,907 INFO [ConnectionState] onConnected()
    16:54:24,957 INFO [ConnectionState] join(Min117)
    16:54:25,182 INFO [PlayerMovementState] initialize()
    16:54:25,184 INFO [PlayerMovementState] onEnable()
    16:54:25,309 INFO [GameSessionState] initialize()
    16:54:25,310 INFO [GameSessionState] Player object:EntityId[2]
    16:54:26,874 INFO [InGameMenuState] exitGame()
    16:54:27,760 ERROR [LegacyApplication] Uncaught exception thrown in Thread[jME3 Main,5,main]
    java.lang.RuntimeException: Error invoking action method:stop
    at com.simsilica.lemur.CallMethodAction.execute(CallMethodAction.java:180) ~[lemur-proto-1.7.2-SNAPSHOT.jar:?]
    at com.simsilica.lemur.ActionButton$ClickCommand.execute(ActionButton.java:132) ~[lemur-proto-1.7.2-SNAPSHOT.jar:?]
    at com.simsilica.lemur.ActionButton$ClickCommand.execute(ActionButton.java:127) ~[lemur-proto-1.7.2-SNAPSHOT.jar:?]
    at com.simsilica.lemur.core.CommandMap.runCommands(CommandMap.java:61) ~[lemur-1.9.1-SNAPSHOT.jar:?]
    at com.simsilica.lemur.Button.runClick(Button.java:333) ~[lemur-1.9.1-SNAPSHOT.jar:?]
    at com.simsilica.lemur.Button$ButtonMouseHandler.mouseButtonEvent(Button.java:410) ~[lemur-1.9.1-SNAPSHOT.jar:?]
    at com.simsilica.lemur.event.MouseEventControl.mouseButtonEvent(MouseEventControl.java:122) ~[lemur-1.9.1-SNAPSHOT.jar:?]
    at com.simsilica.lemur.event.PickEventSession.buttonEvent(PickEventSession.java:553) ~[lemur-1.9.1-SNAPSHOT.jar:?]
    at com.simsilica.lemur.event.MouseAppState.dispatch(MouseAppState.java:97) ~[lemur-1.9.1-SNAPSHOT.jar:?]
    at com.simsilica.lemur.event.MouseAppState$MouseObserver.onMouseButtonEvent(MouseAppState.java:112) ~[lemur-1.9.1-SNAPSHOT.jar:?]
    at com.jme3.input.InputManager.processQueue(InputManager.java:831) ~[jme3-core-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.input.InputManager.update(InputManager.java:907) ~[jme3-core-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.app.LegacyApplication.update(LegacyApplication.java:725) ~[jme3-core-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.app.SimpleApplication.update(SimpleApplication.java:227) ~[jme3-core-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.system.lwjgl.LwjglAbstractDisplay.runLoop(LwjglAbstractDisplay.java:151) ~[jme3-lwjgl-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.system.lwjgl.LwjglDisplay.runLoop(LwjglDisplay.java:193) ~[jme3-lwjgl-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.system.lwjgl.LwjglAbstractDisplay.run(LwjglAbstractDisplay.java:232) ~[jme3-lwjgl-3.1.0-beta1.jar:3.1-beta1]
    at java.lang.Thread.run(Unknown Source) [?:1.8.0_92]
    Caused by: java.lang.IllegalArgumentException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_92]
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_92]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_92]
    at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_92]
    at com.simsilica.lemur.CallMethodAction.execute(CallMethodAction.java:178) ~[lemur-proto-1.7.2-SNAPSHOT.jar:?]
    … 17 more
    16:54:27,793 INFO [GameClient] close()
    16:54:27,794 INFO [SharedObjectUpdater] stop()
    16:54:27,795 INFO [ConnectionState] clientDisconnected(com.jme3.network.base.DefaultClient@7abd58f2, null)
18

The above log includes the serializer error and a stop error I’ve been getting when I close the application.

To replicate this error I open one copy, host a server, join the server. Then I open a second copy and attempt to join again. Sometimes it happens, sometimes it doesn’t. Seems to be about 1 in 10 or so, I just try to join as quickly as possible.

edit: looking at it more closely, it seems to be the stop error twice. The logfile doesn’t have anything about the serializer error.

19

Ok, got the serializer error below:

17:16:24,722 ERROR [ConnectionState] Connection error
java.lang.RuntimeException: Error deserializing object, class ID:-48
at com.jme3.network.base.MessageProtocol.createMessage(MessageProtocol.java:184) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.MessageProtocol.addBuffer(MessageProtocol.java:160) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.ConnectorAdapter.run(ConnectorAdapter.java:169) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
Caused by: com.jme3.network.serializing.SerializerException: Class not found for buffer data.
at com.jme3.network.serializing.Serializer.readClassAndObject(Serializer.java:391) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.MessageProtocol.createMessage(MessageProtocol.java:180) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
… 2 more
17:16:29,726 INFO [ConnectionState] disconnect()
17:16:29,726 INFO [ConnectionState] Detaching ConnectionState
17:16:29,726 INFO [GameClient] close()
17:16:29,727 ERROR [ConnectionState] Connection error
com.jme3.network.kernel.ConnectorException: Connector closed.
at com.jme3.network.base.ConnectorAdapter.run(ConnectorAdapter.java:161) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
17:16:29,731 INFO [ConnectionState] clientDisconnected(com.jme3.network.base.DefaultClient@6360b070, null)
17:16:29,763 INFO [ConnectionState] onDisconnected(null)
17:16:31,910 INFO [ConnectionState] disconnect()

20

I added the timestate code that you committed to sim-eth-es and now I don’t get anymore nano messages.