SimEthereal Questions

Troubleshooting networking
21

Well, at least there’s that. :slight_smile:

Regarding the ghosting, there are some other issues I’ve noticed in the -es version when objects go out of scope of one another. So hopefully fixing all of that will clear things up.

I’m going to add some more debugging in Lemur to try to provide more information in the case of these IllegalArgumentExcetions for reflected method calls. Kind of a shame Java isn’t providing more information.

re: the serialization exception. That’s going to be a trickier one. I assume you run both the host+joined and the joined one from the same directory? If so then I’m not sure I can rely on the logs. (I do that too but I’ve never looked to see what it does to the appllication.log file.) It feels like maybe the client is calling something before the connection services are fully setup, ie: we’re trying to send a message before we’ve received the serializer registrations on the client.

So, the next time it happens… can you provide the whole log file so that I can see what order things happened in? In the mean time, I may see if I can force it to happen with the stand-alone server. (Did you know you can also run a stand-alone server and that it will use a different log file?)

22

Ok… so some progress.

The IllegalArgumentException from CallMethodAction has been fixed. (99.999% sure) And even if not, I’ve added more information to the exception. This should fix your exit problems. (Requires the latest Lemur source.)

I’ve also fixed (should be) the ship ghosting problems… they actually existed in both versions. (Note: that it requires a rebuild of SimMath from source or you will get a bunch of watchdog messages to console whenever a ship is out of range… that’s optional, just be aware.)

Finally, I’ve added additional logging to sim-eth-es to try and track down your Serializer issue. I’ve traced through the code a bunch of different ways and I can’t figure out why it’s happening. So in the mean time, I’ve started logging all of the messages that the client receives to see if some come in an odd or unexpected order. (Can’t see how… but who knows?)

So, if you see that serializer exception again with all updated code, please capture the application.log (before you’ve shut down the one that’s hosting or it will add extra junk)… and post the whole log here please. It may actually be a bug down in the SpiderMonkey layer… so I’m keen to fix it.

Thanks again for testing this stuff.

Edit: if you want to super-duper go the extra mile, then running the application from two different directories so I can get both server+client and client-only logs would be really awesome.

23

Awesome :smiley: I’ll test those out once I’m done playing with this serializer one :smiley:

I always run my second client from a new directory (usually I use the distribution jar), I will get you logfiles.

Here is what I’ve done, I nuked my local versions of everything, redownloaded all the libraries (simmath, sio2, lemur) recompiled, gradle installed. I will post the application logs in the next reply.

24

This is the client logfile.

05:10:50,748 INFO [JmeSystem] Running on jMonkeyEngine 3.1-beta1

  • Branch: HEAD
  • Git Hash: 310f4db
  • Build Date: 2016-04-25
    05:10:51,212 INFO [LwjglContext] LWJGL 2.9.3 context running on thread jME3 Main
  • Graphics Adapter: aticfx64
  • Driver Version: 8.17.10.1404
  • Scaling Factor: 1
    05:10:51,231 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
    05:10:51,262 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.MeshLoader
    05:10:51,262 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.SkeletonLoader
    05:10:51,263 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.MaterialLoader
    05:10:51,263 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.SceneLoader
    05:10:51,264 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.blender.BlenderModelLoader
    05:10:51,265 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.fbx.FbxLoader
    05:10:51,267 WARN [AssetConfig] Cannot find loader com.jme3.audio.plugins.OGGLoader
    05:10:51,295 INFO [DefaultControllerEnvironment] Loading: net.java.games.input.DirectAndRawInputEnvironmentPlugin
    05:10:51,515 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
    05:10:51,516 WARN [ALAudioRenderer] Pausing audio device not supported.
    05:10:51,516 INFO [ALAudioRenderer] Audio effect extension version: 1.0
    05:10:51,517 INFO [ALAudioRenderer] Audio max auxiliary sends: 4
    05:10:51,602 INFO [GuiGlobals] Initializing GuiGlobals with:com.simsilica.lemur.GuiGlobals@6936bcc1
    05:10:51,611 INFO [GuiGlobals] Lemur build date:20160918
    05:10:51,612 INFO [BaseStyles] loadStyleResource(com/simsilica/lemur/style/base/glass-styles.groovy)
    05:10:52,011 INFO [BaseStyles] Loading base resource:jar:file:/C:/Users/Min117/.m2/repository/com/simsilica/lemur/1.9.1-SNAPSHOT/lemur-1.9.1-SNAPSHOT.jar!/com/simsilica/lemur/style/base/glass-styles.groovy
    05:10:52,537 INFO [BaseStyles] Loading extension resources for:com/simsilica/lemur/style/base/glass-styles.groovy
    05:10:52,537 INFO [BaseStyles] Loading extension resource:jar:file:/C:/Users/Min117/.m2/repository/com/simsilica/lemur-proto/1.7.2-SNAPSHOT/lemur-proto-1.7.2-SNAPSHOT.jar!/com/simsilica/lemur/style/base/glass-styles.groovy
    05:10:53,860 INFO [MainMenuState] Connect… host:localhost port:4271
    05:10:53,875 INFO [ConnectionState] Creating game client for:localhost 4271
    05:10:53,878 INFO [GameClient] Connecting to:localhost 4271
    05:10:53,914 INFO [GameClient] Adding services…
    05:10:53,973 DEBUG [AccountClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
    05:10:53,973 DEBUG [AccountClientService] Sharing session callback.
    05:10:53,974 DEBUG [GameSessionClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.GameSessionClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
    05:10:53,974 DEBUG [GameSessionClientService] Sharing session callback.
    05:10:53,980 DEBUG [ChatClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.GameSessionClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.simsilica.es.client.EntityDataClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.chat.client.ChatClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
    05:10:53,980 DEBUG [ChatClientService] Sharing session callback.
    05:10:53,986 INFO [SharedObjectUpdater] onInitialize()
    05:10:53,986 INFO [ConnectionState] Connection established:example.net.client.GameClient@1b518447
    05:10:53,988 INFO [ConnectionState] Starting client…
    05:10:53,988 INFO [GameClient] start()
    05:10:53,989 INFO [ConnectionState] Client started.
    05:10:54,069 INFO [ConnectionState] Connection established:example.net.client.GameClient@1b518447
    05:10:54,248 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
25

This is the client + server logfile.

05:09:47,298 INFO [JmeSystem] Running on jMonkeyEngine 3.1-beta1

  • Branch: HEAD
  • Git Hash: 310f4db
  • Build Date: 2016-04-25
    05:09:47,580 INFO [LwjglContext] LWJGL 2.9.3 context running on thread jME3 Main
  • Graphics Adapter: aticfx64
  • Driver Version: 8.17.10.1404
  • Scaling Factor: 1
    05:09:47,640 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
    05:09:47,668 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.MeshLoader
    05:09:47,668 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.SkeletonLoader
    05:09:47,669 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.MaterialLoader
    05:09:47,669 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.SceneLoader
    05:09:47,670 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.blender.BlenderModelLoader
    05:09:47,671 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.fbx.FbxLoader
    05:09:47,672 WARN [AssetConfig] Cannot find loader com.jme3.audio.plugins.OGGLoader
    05:09:47,701 INFO [DefaultControllerEnvironment] Loading: net.java.games.input.DirectAndRawInputEnvironmentPlugin
    05:09:47,931 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
    05:09:47,931 WARN [ALAudioRenderer] Pausing audio device not supported.
    05:09:47,931 INFO [ALAudioRenderer] Audio effect extension version: 1.0
    05:09:47,932 INFO [ALAudioRenderer] Audio max auxiliary sends: 4
    05:09:48,012 INFO [GuiGlobals] Initializing GuiGlobals with:com.simsilica.lemur.GuiGlobals@7e2e359a
    05:09:48,022 INFO [GuiGlobals] Lemur build date:20160918
    05:09:48,022 INFO [BaseStyles] loadStyleResource(com/simsilica/lemur/style/base/glass-styles.groovy)
    05:09:48,393 INFO [BaseStyles] Loading base resource:jar:file:/C:/Users/Min117/.m2/repository/com/simsilica/lemur/1.9.1-SNAPSHOT/lemur-1.9.1-SNAPSHOT.jar!/com/simsilica/lemur/style/base/glass-styles.groovy
    05:09:48,860 INFO [BaseStyles] Loading extension resources for:com/simsilica/lemur/style/base/glass-styles.groovy
    05:09:48,861 INFO [BaseStyles] Loading extension resource:jar:file:/C:/Users/Min117/.m2/repository/com/simsilica/lemur-proto/1.7.2-SNAPSHOT/lemur-proto-1.7.2-SNAPSHOT.jar!/com/simsilica/lemur/style/base/glass-styles.groovy
    05:09:51,297 INFO [MainMenuState] Host a game on port:4271
    05:09:51,297 INFO [MainMenuState] Description:
    05:09:51,297 INFO [MainMenuState] This a game server.
    There are many like it
    but this one is mine.
    05:09:51,390 INFO [GameServer] Initializing game systems…
    05:09:51,390 TRACE [GameSystemManager] initialize()
    05:09:51,391 TRACE [GameSystemManager] initializing:com.simsilica.sim.TaskDispatcher@6a4d88bc
    05:09:51,391 TRACE [GameSystemManager] initializing:example.sim.SimplePhysics@3256de73
    05:09:51,391 TRACE [GameSystemManager] initializing:example.net.server.ZoneNetworkSystem@4e099fa1
    05:09:51,391 TRACE [GameSystemManager] initializing:com.simsilica.es.server.EntityUpdater@45415f97
    05:09:51,391 TRACE [GameSystemManager] initializing:example.sim.BodyPositionPublisher@43cf37eb
    05:09:51,391 TRACE [GameSystemManager] initializing:example.sim.BasicEnvironment@47eecca7
    05:09:51,392 INFO [GameServer] Starting game server…
    05:09:51,392 TRACE [GameSystemManager] start()
    05:09:51,392 TRACE [GameSystemManager] starting:com.simsilica.sim.TaskDispatcher@6a4d88bc
    05:09:51,392 TRACE [GameSystemManager] starting:example.sim.SimplePhysics@3256de73
    05:09:51,396 TRACE [GameSystemManager] starting:example.net.server.ZoneNetworkSystem@4e099fa1
    05:09:51,396 TRACE [GameSystemManager] starting:com.simsilica.es.server.EntityUpdater@45415f97
    05:09:51,396 TRACE [GameSystemManager] starting:example.sim.BodyPositionPublisher@43cf37eb
    05:09:51,396 TRACE [GameSystemManager] starting:example.sim.BasicEnvironment@47eecca7
    05:09:51,421 INFO [StateCollector] Starting state collector.
    05:09:51,421 INFO [GameServer] Game server started.
    05:09:52,980 INFO [HostState] joinGame()
    05:09:52,988 INFO [ConnectionState] Creating game client for:127.0.0.1 4271
    05:09:52,989 INFO [GameClient] Connecting to:127.0.0.1 4271
    05:09:53,004 INFO [SerializerRegistrationsMessage] Skipping registration of SerializerRegistrationsMessage.
    05:09:53,007 INFO [GameClient] Adding services…
    05:09:53,016 DEBUG [AccountClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
    05:09:53,016 DEBUG [AccountClientService] Sharing session callback.
    05:09:53,017 DEBUG [GameSessionClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.GameSessionClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
    05:09:53,017 DEBUG [GameSessionClientService] Sharing session callback.
    05:09:53,019 DEBUG [ChatClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.GameSessionClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.simsilica.es.client.EntityDataClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.chat.client.ChatClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
    05:09:53,019 DEBUG [ChatClientService] Sharing session callback.
    05:09:53,025 INFO [SharedObjectUpdater] onInitialize()
    05:09:53,025 INFO [ConnectionState] Connection established:example.net.client.GameClient@f5ed719
    05:09:53,026 INFO [ConnectionState] Starting client…
    05:09:53,026 INFO [GameClient] start()
    05:09:53,027 INFO [ConnectionState] Client started.
    05:09:53,030 INFO [ConnectionState] Connection established:example.net.client.GameClient@f5ed719
    05:09:53,044 DEBUG [AccountHostedService] startHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61205]], fast=UdpEndpoint[1, /127.0.0.1:57605] ])
    05:09:53,046 INFO [MessageDebugger] Received:com.jme3.network.message.SerializerRegistrationsMessage@20217167
    05:09:53,046 INFO [SerializerRegistrationsMessage] Skipping registration as registry is locked, presumably by a local server process.
    05:09:53,055 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:09:53,056 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:09:53,061 DEBUG [AccountClientService] start()
    05:09:53,061 DEBUG [AccountClientService] delegate:RemoteObject[#1, example.net.AccountSession]
    05:09:53,061 DEBUG [GameSessionClientService] start()
    05:09:53,061 DEBUG [ChatClientService] start()
    05:09:53,061 INFO [SharedObjectUpdater] start()
    05:09:53,063 INFO [ConnectionState] clientConnected(com.jme3.network.base.DefaultClient@282ea54f)
    05:09:53,080 INFO [ConnectionState] onConnected()
    05:09:53,083 INFO [MessageDebugger] Received:RpcResponseMessage[#0, result=This a game server.
    There are many like it
    but this one is mine.]
    05:09:53,083 DEBUG [ConnectionState] Server info:This a game server.
    There are many like it
    but this one is mine.
    05:09:58,833 INFO [ConnectionState] join(Mithrin123)
    05:09:58,834 INFO [AccountHostedService] login(Mithrin123)
    05:09:58,834 INFO [AccountHostedService] Created player entity:EntityId[64] for:Mithrin123
    05:09:58,835 DEBUG [AccountHostedService] publishing playerLoggedOn event for:Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61205]], fast=UdpEndpoint[1, /127.0.0.1:57605] ]
    05:09:58,835 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=1, procId=0, args.length=1]
    05:09:58,835 DEBUG [GameSessionHostedService] onPlayerLoggedOn()
    05:09:58,835 DEBUG [GameSessionHostedService] startHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61205]], fast=UdpEndpoint[1, /127.0.0.1:57605] ])
    05:09:58,838 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:09:58,839 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:09:58,841 DEBUG [ChatHostedService] startHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61205]], fast=UdpEndpoint[1, /127.0.0.1:57605] ])
    05:09:58,842 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:09:58,842 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:09:58,844 INFO [MessageDebugger] Received:EntityDataMessage[0, [ComponentData[EntityId[65], [BodyPosition[null]]]]]
    05:09:58,845 INFO [MessageDebugger] Received:ComponentChangeMessage[[EntityChange[EntityId[65], BodyPosition[null], class example.es.BodyPosition]]]
    05:09:58,849 INFO [MessageDebugger] Object state updates started.
    05:09:59,145 INFO [PlayerMovementState] initialize()
    05:09:59,146 INFO [MessageDebugger] Received:EntityDataMessage[1, [ComponentData[EntityId[65], [ObjectType[type=1], BodyPosition[null]]]]]
    05:09:59,147 INFO [PlayerMovementState] onEnable()
    05:09:59,165 INFO [MessageDebugger] Received:EntityDataMessage[2, [ComponentData[EntityId[0], [ObjectType[type=0], Position[location=Vec3[-384.0, -384.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[1], [ObjectType[type=0], Position[location=Vec3[-384.0, -384.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[2], [ObjectType[type=0], Position[location=Vec3[-384.0, -384.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[3], [ObjectType[type=0], Position[location=Vec3[-384.0, -384.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[4], [ObjectType[type=0], Position[location=Vec3[-384.0, -128.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[5], [ObjectType[type=0], Position[location=Vec3[-384.0, -128.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[6], [ObjectType[type=0], Position[location=Vec3[-384.0, -128.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[7], [ObjectType[type=0], Position[location=Vec3[-384.0, -128.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[8], [ObjectType[type=0], Position[location=Vec3[-384.0, 128.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[9], [ObjectType[type=0], Position[location=Vec3[-384.0, 128.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[10], [ObjectType[type=0], Position[location=Vec3[-384.0, 128.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[11], [ObjectType[type=0], Position[location=Vec3[-384.0, 128.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[12], [ObjectType[type=0], Position[location=Vec3[-384.0, 384.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[13], [ObjectType[type=0], Position[location=Vec3[-384.0, 384.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[14], [ObjectType[type=0], Position[location=Vec3[-384.0, 384.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[15], [ObjectType[type=0], Position[location=Vec3[-384.0, 384.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[16], [ObjectType[type=0], Position[location=Vec3[-128.0, -384.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[17], [ObjectType[type=0], Position[location=Vec3[-128.0, -384.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[18], [ObjectType[type=0], Position[location=Vec3[-128.0, -384.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[19], [ObjectType[type=0], Position[location=Vec3[-128.0, -384.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[20], [ObjectType[type=0], Position[location=Vec3[-128.0, -128.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]]]]
    05:09:59,169 INFO [MessageDebugger] Received:EntityDataMessage[2, [ComponentData[EntityId[21], [ObjectType[type=0], Position[location=Vec3[-128.0, -128.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[22], [ObjectType[type=0], Position[location=Vec3[-128.0, -128.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[23], [ObjectType[type=0], Position[location=Vec3[-128.0, -128.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[24], [ObjectType[type=0], Position[location=Vec3[-128.0, 128.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[25], [ObjectType[type=0], Position[location=Vec3[-128.0, 128.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[26], [ObjectType[type=0], Position[location=Vec3[-128.0, 128.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[27], [ObjectType[type=0], Position[location=Vec3[-128.0, 128.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[28], [ObjectType[type=0], Position[location=Vec3[-128.0, 384.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[29], [ObjectType[type=0], Position[location=Vec3[-128.0, 384.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[30], [ObjectType[type=0], Position[location=Vec3[-128.0, 384.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[31], [ObjectType[type=0], Position[location=Vec3[-128.0, 384.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[32], [ObjectType[type=0], Position[location=Vec3[128.0, -384.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[33], [ObjectType[type=0], Position[location=Vec3[128.0, -384.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[34], [ObjectType[type=0], Position[location=Vec3[128.0, -384.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[35], [ObjectType[type=0], Position[location=Vec3[128.0, -384.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[36], [ObjectType[type=0], Position[location=Vec3[128.0, -128.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[37], [ObjectType[type=0], Position[location=Vec3[128.0, -128.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[38], [ObjectType[type=0], Position[location=Vec3[128.0, -128.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[39], [ObjectType[type=0], Position[location=Vec3[128.0, -128.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[40], [ObjectType[type=0], Position[location=Vec3[128.0, 128.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[41], [ObjectType[type=0], Position[location=Vec3[128.0, 128.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]]]]
    05:09:59,170 INFO [MessageDebugger] Received:EntityDataMessage[2, [ComponentData[EntityId[42], [ObjectType[type=0], Position[location=Vec3[128.0, 128.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[43], [ObjectType[type=0], Position[location=Vec3[128.0, 128.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[44], [ObjectType[type=0], Position[location=Vec3[128.0, 384.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[45], [ObjectType[type=0], Position[location=Vec3[128.0, 384.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[46], [ObjectType[type=0], Position[location=Vec3[128.0, 384.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[47], [ObjectType[type=0], Position[location=Vec3[128.0, 384.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[48], [ObjectType[type=0], Position[location=Vec3[384.0, -384.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[49], [ObjectType[type=0], Position[location=Vec3[384.0, -384.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[50], [ObjectType[type=0], Position[location=Vec3[384.0, -384.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[51], [ObjectType[type=0], Position[location=Vec3[384.0, -384.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[52], [ObjectType[type=0], Position[location=Vec3[384.0, -128.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[53], [ObjectType[type=0], Position[location=Vec3[384.0, -128.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[54], [ObjectType[type=0], Position[location=Vec3[384.0, -128.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[55], [ObjectType[type=0], Position[location=Vec3[384.0, -128.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[56], [ObjectType[type=0], Position[location=Vec3[384.0, 128.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[57], [ObjectType[type=0], Position[location=Vec3[384.0, 128.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[58], [ObjectType[type=0], Position[location=Vec3[384.0, 128.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[59], [ObjectType[type=0], Position[location=Vec3[384.0, 128.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[60], [ObjectType[type=0], Position[location=Vec3[384.0, 384.0, -384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[61], [ObjectType[type=0], Position[location=Vec3[384.0, 384.0, -128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[62], [ObjectType[type=0], Position[location=Vec3[384.0, 384.0, 128.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]]]]
    05:09:59,175 INFO [MessageDebugger] Received:EntityDataMessage[2, [ComponentData[EntityId[63], [ObjectType[type=0], Position[location=Vec3[384.0, 384.0, 384.0], facing=Quatd[-0.7071067811865475, 0.0, 0.0, 0.7071067811865476]]]], ComponentData[EntityId[65], [ObjectType[type=1], Position[location=Vec3[1.0, 1.0, 1.0], facing=Quatd[0.0, 0.0, 0.0, 1.0]]]]]]
    05:09:59,175 INFO [MessageDebugger] Received:EntityDataMessage[3, [ComponentData[EntityId[65], [Name[Mithrin123], BodyPosition[null]]]]]
    05:09:59,221 INFO [GameSessionState] initialize()
    05:09:59,222 DEBUG [GameSessionClientService] delegate:RemoteObject[#2, example.net.GameSession]
    05:09:59,227 INFO [MessageDebugger] Received:RpcResponseMessage[#1, result=EntityId[64]]
    05:09:59,228 INFO [MessageDebugger] Received:RpcResponseMessage[#2, result=EntityId[65]]
    05:09:59,229 INFO [GameSessionState] Player object:EntityId[65]
    05:09:59,231 INFO [MessageDebugger] Received:StringIdMessage[id=null, string=gravSphere]
26

Second half of client+server, broken up due to post character limit.

05:09:59,232 INFO [MessageDebugger] Received:ReturnComponentsMessage[1, EntityId[0], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,265 INFO [MessageDebugger] Received:ReturnComponentsMessage[2, EntityId[1], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,271 INFO [MessageDebugger] Received:ReturnComponentsMessage[3, EntityId[2], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,276 INFO [MessageDebugger] Received:ReturnComponentsMessage[4, EntityId[3], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,284 INFO [MessageDebugger] Received:ReturnComponentsMessage[5, EntityId[4], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,290 INFO [MessageDebugger] Received:ReturnComponentsMessage[6, EntityId[5], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,295 INFO [MessageDebugger] Received:ReturnComponentsMessage[7, EntityId[6], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,301 INFO [MessageDebugger] Received:ReturnComponentsMessage[8, EntityId[7], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,305 INFO [MessageDebugger] Received:ReturnComponentsMessage[9, EntityId[8], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,310 INFO [MessageDebugger] Received:ReturnComponentsMessage[10, EntityId[9], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,314 INFO [MessageDebugger] Received:ReturnComponentsMessage[11, EntityId[10], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,319 INFO [MessageDebugger] Received:ReturnComponentsMessage[12, EntityId[11], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,323 INFO [MessageDebugger] Received:ReturnComponentsMessage[13, EntityId[12], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,328 INFO [MessageDebugger] Received:ReturnComponentsMessage[14, EntityId[13], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,334 INFO [MessageDebugger] Received:ReturnComponentsMessage[15, EntityId[14], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,339 INFO [MessageDebugger] Received:ReturnComponentsMessage[16, EntityId[15], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,344 INFO [MessageDebugger] Received:ReturnComponentsMessage[17, EntityId[16], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,348 INFO [MessageDebugger] Received:ReturnComponentsMessage[18, EntityId[17], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,352 INFO [MessageDebugger] Received:ReturnComponentsMessage[19, EntityId[18], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,358 INFO [MessageDebugger] Received:ReturnComponentsMessage[20, EntityId[19], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,362 INFO [MessageDebugger] Received:ReturnComponentsMessage[21, EntityId[20], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,366 INFO [MessageDebugger] Received:ReturnComponentsMessage[22, EntityId[21], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,370 INFO [MessageDebugger] Received:ReturnComponentsMessage[23, EntityId[22], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,373 INFO [MessageDebugger] Received:ReturnComponentsMessage[24, EntityId[23], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,376 INFO [MessageDebugger] Received:ReturnComponentsMessage[25, EntityId[24], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,379 INFO [MessageDebugger] Received:ReturnComponentsMessage[26, EntityId[25], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,382 INFO [MessageDebugger] Received:ReturnComponentsMessage[27, EntityId[26], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,384 INFO [MessageDebugger] Received:ReturnComponentsMessage[28, EntityId[27], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,387 INFO [MessageDebugger] Received:ReturnComponentsMessage[29, EntityId[28], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,390 INFO [MessageDebugger] Received:ReturnComponentsMessage[30, EntityId[29], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,392 INFO [MessageDebugger] Received:ReturnComponentsMessage[31, EntityId[30], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,395 INFO [MessageDebugger] Received:ReturnComponentsMessage[32, EntityId[31], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,401 INFO [MessageDebugger] Received:ReturnComponentsMessage[33, EntityId[32], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,411 INFO [MessageDebugger] Received:ReturnComponentsMessage[34, EntityId[33], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,416 INFO [MessageDebugger] Received:ReturnComponentsMessage[35, EntityId[34], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,420 INFO [MessageDebugger] Received:ReturnComponentsMessage[36, EntityId[35], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,424 INFO [MessageDebugger] Received:ReturnComponentsMessage[37, EntityId[36], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,427 INFO [MessageDebugger] Received:ReturnComponentsMessage[38, EntityId[37], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,430 INFO [MessageDebugger] Received:ReturnComponentsMessage[39, EntityId[38], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,434 INFO [MessageDebugger] Received:ReturnComponentsMessage[40, EntityId[39], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,439 INFO [MessageDebugger] Received:ReturnComponentsMessage[41, EntityId[40], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,441 INFO [MessageDebugger] Received:ReturnComponentsMessage[42, EntityId[41], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,447 INFO [MessageDebugger] Received:ReturnComponentsMessage[43, EntityId[42], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,454 INFO [MessageDebugger] Received:ReturnComponentsMessage[44, EntityId[43], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,459 INFO [MessageDebugger] Received:ReturnComponentsMessage[45, EntityId[44], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,461 INFO [MessageDebugger] Received:ReturnComponentsMessage[46, EntityId[45], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,464 INFO [MessageDebugger] Received:ReturnComponentsMessage[47, EntityId[46], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,469 INFO [MessageDebugger] Received:ReturnComponentsMessage[48, EntityId[47], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,471 INFO [MessageDebugger] Received:ReturnComponentsMessage[49, EntityId[48], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,473 INFO [MessageDebugger] Received:ReturnComponentsMessage[50, EntityId[49], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,476 INFO [MessageDebugger] Received:ReturnComponentsMessage[51, EntityId[50], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,478 INFO [MessageDebugger] Received:ReturnComponentsMessage[52, EntityId[51], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,480 INFO [MessageDebugger] Received:ReturnComponentsMessage[53, EntityId[52], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,484 INFO [MessageDebugger] Received:ReturnComponentsMessage[54, EntityId[53], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,486 INFO [MessageDebugger] Received:ReturnComponentsMessage[55, EntityId[54], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,488 INFO [MessageDebugger] Received:ReturnComponentsMessage[56, EntityId[55], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,490 INFO [MessageDebugger] Received:ReturnComponentsMessage[57, EntityId[56], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,492 INFO [MessageDebugger] Received:ReturnComponentsMessage[58, EntityId[57], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,494 INFO [MessageDebugger] Received:ReturnComponentsMessage[59, EntityId[58], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,496 INFO [MessageDebugger] Received:ReturnComponentsMessage[60, EntityId[59], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,499 INFO [MessageDebugger] Received:ReturnComponentsMessage[61, EntityId[60], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,503 INFO [MessageDebugger] Received:ReturnComponentsMessage[62, EntityId[61], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,505 INFO [MessageDebugger] Received:ReturnComponentsMessage[63, EntityId[62], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,507 INFO [MessageDebugger] Received:ReturnComponentsMessage[64, EntityId[63], [SphereShape[radius=10.0, centerOffset=Vec3[0.0, 0.0, 0.0]]]]
05:09:59,514 INFO [MessageDebugger] Received:StringIdMessage[id=null, string=ship]
05:10:18,009 INFO [PlayerMovementState] onEnable()
05:10:30,581 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,598 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,615 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,631 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,648 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,665 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,682 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,698 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,715 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,732 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,748 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,765 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,782 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,798 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,815 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,832 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,848 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,865 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,882 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,899 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,915 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,932 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,949 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,965 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,982 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:30,999 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,015 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,032 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,049 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,065 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,082 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,645 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,662 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,678 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,695 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:31,712 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:39,199 DEBUG [AccountHostedService] startHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61217]], fast=UdpEndpoint[2, /127.0.0.1:57611] ])
05:10:40,091 INFO [AccountHostedService] login(Min117)
05:10:40,091 INFO [AccountHostedService] Created player entity:EntityId[66] for:Min117
05:10:40,091 DEBUG [AccountHostedService] publishing playerLoggedOn event for:Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61217]], fast=UdpEndpoint[2, /127.0.0.1:57611] ]
05:10:40,091 DEBUG [GameSessionHostedService] onPlayerLoggedOn()
05:10:40,091 DEBUG [GameSessionHostedService] startHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61217]], fast=UdpEndpoint[2, /127.0.0.1:57611] ])
05:10:40,091 DEBUG [ChatHostedService] startHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61217]], fast=UdpEndpoint[2, /127.0.0.1:57611] ])
05:10:40,092 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=0, async, objId=3, procId=1, args.length=2]
05:10:40,100 INFO [MessageDebugger] Received:EntityDataMessage[0, [ComponentData[EntityId[67], [BodyPosition[null]]]]]
05:10:40,100 INFO [MessageDebugger] Received:EntityDataMessage[1, [ComponentData[EntityId[67], [ObjectType[type=1], BodyPosition[null]]]]]
05:10:40,100 INFO [MessageDebugger] Received:EntityDataMessage[2, [ComponentData[EntityId[67], [ObjectType[type=1], Position[location=Vec3[1.0, 1.0, 1.0], facing=Quatd[0.0, 0.0, 0.0, 1.0]]]]]]
05:10:40,100 INFO [MessageDebugger] Received:EntityDataMessage[3, [ComponentData[EntityId[67], [Name[Min117], BodyPosition[null]]]]]
05:10:40,101 INFO [MessageDebugger] Received:ComponentChangeMessage[[EntityChange[EntityId[67], Name[Min117], class com.simsilica.es.Name], EntityChange[EntityId[67], ObjectType[type=1], class example.es.ObjectType], EntityChange[EntityId[67], Position[location=Vec3[1.0, 1.0, 1.0], facing=Quatd[0.0, 0.0, 0.0, 1.0]], class example.es.Position], EntityChange[EntityId[67], BodyPosition[null], class example.es.BodyPosition]]]
05:10:42,320 WARN [ZoneManager] Pausing history collect. Overlow detected, current history size:11 max:12
05:10:44,384 DEBUG [AccountHostedService] stopHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:57611] ])
05:10:44,384 DEBUG [AccountHostedService] publishing playerLoggedOff event for:Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:57611] ]
05:10:44,384 DEBUG [GameSessionHostedService] onPlayerLoggedOff()
05:10:44,384 DEBUG [GameSessionHostedService] stopHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:57611] ])
05:10:44,384 DEBUG [GameSessionHostedService] Closing game session for:Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:57611] ]
05:10:44,384 DEBUG [ChatHostedService] stopHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:57611] ])
05:10:44,384 DEBUG [GameSessionHostedService] stopHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:57611] ])
05:10:44,384 DEBUG [ChatHostedService] stopHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:57611] ])
05:10:44,385 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=0, async, objId=3, procId=2, args.length=2]
05:10:44,387 ERROR [GameSystemManager] Error updating systems
java.lang.NullPointerException
at example.sim.BodyPositionPublisher.removeBody(BodyPositionPublisher.java:110) ~[main/:?]
at example.sim.SimplePhysics.fireBodyListListeners(SimplePhysics.java:164) ~[main/:?]
at example.sim.SimplePhysics.update(SimplePhysics.java:193) ~[main/:?]
at com.simsilica.sim.GameSystemManager.update(GameSystemManager.java:288) [sio2-1.0.3-SNAPSHOT.jar:?]
at com.simsilica.sim.GameLoop$Runner.run(GameLoop.java:167) [sio2-1.0.3-SNAPSHOT.jar:?]
05:10:44,404 INFO [MessageDebugger] Received:ComponentChangeMessage[[EntityChange[EntityId[67], null, class example.es.Position], EntityChange[EntityId[67], null, class example.es.BodyPosition], EntityChange[EntityId[67], null, class com.simsilica.es.Name], EntityChange[EntityId[67], null, class example.es.ObjectType]]]
05:10:44,453 DEBUG [SharedObjectUpdater] ****** Object removed[t=172507594898469]:67
05:10:44,453 DEBUG [SharedObjectUpdater] No entity for removed object for:67
05:10:54,232 DEBUG [AccountHostedService] startHostingOnConnection(Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:61227]], fast=UdpEndpoint[3, /127.0.0.1:57614] ])
05:22:12,577 DEBUG [AccountHostedService] stopHostingOnConnection(Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[3, /127.0.0.1:57614] ])
05:22:12,577 DEBUG [AccountHostedService] publishing playerLoggedOff event for:Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[3, /127.0.0.1:57614] ]
05:22:12,577 DEBUG [GameSessionHostedService] onPlayerLoggedOff()
05:22:12,577 DEBUG [GameSessionHostedService] stopHostingOnConnection(Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[3, /127.0.0.1:57614] ])
05:22:12,579 ERROR [KernelAdapter] Unhandled error, endpoint:NioEndpoint[3, java.nio.channels.SocketChannel[closed]], context:EndpointEvent[REMOVE, NioEndpoint[3, java.nio.channels.SocketChannel[closed]]]
java.lang.IllegalArgumentException: EntityId cannot be null.
at com.simsilica.es.base.DefaultEntityData.removeComponent(DefaultEntityData.java:185) ~[zay-es-1.2.1.jar:?]
at com.simsilica.es.base.DefaultEntityData.removeEntity(DefaultEntityData.java:126) ~[zay-es-1.2.1.jar:?]
at example.net.server.AccountHostedService$AccountSessionImpl.dispose(AccountHostedService.java:194) ~[main/:?]
at example.net.server.AccountHostedService.stopHostingOnConnection(AccountHostedService.java:135) ~[main/:?]
at com.jme3.network.service.AbstractHostedConnectionService.connectionRemoved(AbstractHostedConnectionService.java:146) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.service.HostedServiceManager.removeConnection(HostedServiceManager.java:124) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.service.HostedServiceManager$ConnectionObserver.connectionRemoved(HostedServiceManager.java:137) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.DefaultServer.fireConnectionRemoved(DefaultServer.java:356) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.DefaultServer$Connection.closeConnection(DefaultServer.java:616) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.DefaultServer.connectionClosed(DefaultServer.java:513) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.KernelAdapter.connectionClosed(KernelAdapter.java:144) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.KernelAdapter.createAndDispatch(KernelAdapter.java:249) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.KernelAdapter.flushEvents(KernelAdapter.java:258) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
at com.jme3.network.base.KernelAdapter.run(KernelAdapter.java:271) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]

27

It’s weird because according to this client-only log, no message was ever received… which means that somehow someone is sending a message before the connection is fully setup (or this code wasn’t really compiled but I may add something to check for that).

I also should make the server dump its serializer registry so we know which message it is. I thought it already was but I guess not.

28

I was attempting to debug this again this morning, it looks like a RpcCallMessage unless I’m mistaken on what this message means.

05:41:45,136 INFO [SerializerRegistrationsMessage] Registering:Registration[-48 = com.jme3.network.service.rpc.msg.RpcCallMessage, serializer=null]

29

Yeah, but that message didn’t appear in either of your posted logs and I hate to assume. Anyway, it’s likely consistent.

Is this only ever from the second connection, I wonder… like can it happen from the second machine if you just host the game but don’t join it. I may have an idea of what’s going on.

30

I opened a host game, didn’t join it. Opened a second client, closed and opened it a few times, crashed with serializer error.

I attempted to do something similar from a single client(opening a host, and then joining/disconnecting over and over), but it keeps adding the “speed, position, etc” into the title bar over and over and then crashes after there are too many of them. :smiley:

31

Oops… something is not cleaning itself up properly. :slight_smile:

32

Ok, so, playing around some more…

In the MessageDebugger Class I changed the info to these lines.

            log.info("Received:" + m);
            log.info("Class:" + m.getClass());
            log.info("Source:" + source);

When I connect properly I get these messages in the log/console

19:34:01,229 DEBUG [AccountClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
19:34:01,229 DEBUG [AccountClientService] Sharing session callback.
19:34:01,229 DEBUG [GameSessionClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.GameSessionClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
19:34:01,229 DEBUG [GameSessionClientService] Sharing session callback.
19:34:01,235 DEBUG [ChatClientService] onInitialize(com.jme3.network.service.ClientServiceManager[services=[com.jme3.network.service.serializer.ClientSerializerRegistrationsService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rpc.RpcClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.jme3.network.service.rmi.RmiClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.AccountClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.client.GameSessionClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], com.simsilica.es.client.EntityDataClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager], example.net.chat.client.ChatClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
19:34:01,235 DEBUG [ChatClientService] Sharing session callback.
19:34:01,247 INFO [SharedObjectUpdater] onInitialize()
19:34:01,248 INFO [ConnectionState] Connection established:example.net.client.GameClient@6093595d
19:34:01,249 INFO [ConnectionState] Starting client…
19:34:01,250 INFO [GameClient] start()
19:34:01,251 INFO [ConnectionState] Client started.
19:34:01,256 INFO [ConnectionState] Connection established:example.net.client.GameClient@6093595d
19:34:01,263 INFO [MessageDebugger] Received:com.jme3.network.message.SerializerRegistrationsMessage@55ad8213
19:34:01,263 INFO [MessageDebugger] Class:class com.jme3.network.message.SerializerRegistrationsMessage
19:34:01,264 INFO [MessageDebugger] Source:com.jme3.network.base.DefaultClient@74f30241
19:34:01,264 INFO [SerializerRegistrationsMessage] Registering:Registration[-19 = com.jme3.math.Vector3f, serializer=com.jme3.network.serializing.serializers.Vector3Serializer]
19:34:01,264 INFO [SerializerRegistrationsMessage] Registering:Registration[-41 = com.jme3.network.serializing.serializers.FieldSerializer, serializer=null]
19:34:01,264 INFO [SerializerRegistrationsMessage] Registering:Registration[-43 = [I, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
19:34:01,265 INFO [SerializerRegistrationsMessage] Registering:Registration[-46 = [Lcom.jme3.network.message.SerializerRegistrationsMessage$Registration;, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
19:34:01,265 INFO [SerializerRegistrationsMessage] Registering:Registration[-49 = [Ljava.lang.Object;, serializer=com.jme3.network.serializing.serializers.ArraySerializer]
19:34:01,265 INFO [SerializerRegistrationsMessage] Registering:Registration[-48 = com.jme3.network.service.rpc.msg.RpcCallMessage, serializer=null]
19:34:01,265 INFO [SerializerRegistrationsMessage] Registering:Registration[-50 = com.jme3.network.service.rpc.msg.RpcResponseMessage, serializer=null]
Etc Etc, Snip
19:34:01,287 INFO [SerializerRegistrationsMessage] Registering:Registration[-82 = example.es.Position, serializer=null]
19:34:01,288 INFO [SerializerRegistrationsMessage] Registering:Registration[-85 = example.es.SphereShape, serializer=null]
19:34:01,289 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
19:34:01,289 INFO [MessageDebugger] Class:class com.jme3.network.service.rpc.msg.RpcCallMessage
19:34:01,289 INFO [MessageDebugger] Source:com.jme3.network.base.DefaultClient@74f30241
19:34:01,289 INFO [MessageDebugger] Received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
19:34:01,289 INFO [MessageDebugger] Class:class com.jme3.network.service.rpc.msg.RpcCallMessage
19:34:01,289 INFO [MessageDebugger] Source:com.jme3.network.base.DefaultClient@74f30241
19:34:01,294 DEBUG [AccountClientService] start()

I’m not sure if that helps at all, but it looks like some RpCallMessages are happening right near/after the serializer stuff happens. Those messagedebugger messages don’t really help me identify what is calling that stuff though.

33

You get the error before the first message is even reported… which means something is trying to send a message before the connection is even setup. Unfortunately, that means it’s a bug in SpiderMonkey itself but I may be able to also work-around it. I have to think about it.

34

Ah ok, that makes sense. Thanks for all your help :smiley:

35

And double checking… you say this only happens if you hit “Join” too quickly? ie: as long as you wait a second then it works around the issue? Or does it happen randomly no matter what?

36

After further testing, it seems to be random no matter what.

37

kind of a long shot but this might fix the symptom (and also point to the real issue)…

Could you try changing the channels in the constant file:

…and make them equal MessageConnection.CHANNEL_DEFAULT_RELIABLE

The theory is that the chat service is sending an RPC message during connection setup but because it’s on a different channel, that message has a chance to bypass the serializer registration message. Thus changing the channels to all be the standard reliable channel should cause everything to go in the proper order.

…and if that’s the issue then I can fix it.

38

:smiley: I changed both chat channel and es channel to MessageConnection.CHANNEL_DEFAULT_RELIABLE, no change in behavior, still gives a serializer error.

39

Shoot… I was really hoping that would fix it.

When the error happens it’s when you first connect (ie: click “Connect”), right?

Another thing you can try is to set the logging level on the server so that it logs every message it sends.

ie: add this to your log4j2.xml (or your server-log4j2.xml if you are running a stand-alone server):

    <Logger name="com.jme3.network.base.DefaultServer" level="TRACE" />

Like, to be 100% clear, this is what my log4j.xml file has in it right now:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" name="MyApp" packages="">
  <Appenders>
    <RollingFile name="RollingFile" fileName="application.log" ignoreExceptions="false"                
                 filePattern="logs/$${date:yyyy-MM}/application-%d{MM-dd-yyyy}-%i.log.gz">
      <PatternLayout>
        <Pattern>%d{ABSOLUTE} %-5p [%c{1}] %m%n</Pattern>        
      </PatternLayout>
      <OnStartupTriggeringPolicy />
    </RollingFile>
    
    <Console name="STDOUT" target="SYSTEM_OUT" ignoreExceptions="false">
      <PatternLayout pattern="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Logger name="example" level="DEBUG"/>
    <Logger name="com.simsilica.sim" level="TRACE"/>
    <Logger name="com.jme3.network.base.DefaultServer" level="TRACE" />
    
    <Root level="INFO">
      <AppenderRef ref="RollingFile"/>
      <AppenderRef ref="STDOUT"/>
    </Root>
  </Loggers>
</Configuration>
40

Yes, I click connect and it will either display the window for entering a username, or a serializer error.

To produce the attached log, I opened one copy that had trace turned on. Hit host. Opened another copy in a different folder, hit connect, if it brought up the username I hit cancel and then exit, closed completely. Repeat until it popped a serializer message. Then I closed both clients using the exit buttons.

05:15:50,368 INFO [JmeSystem] Running on jMonkeyEngine 3.1-beta1

  • Branch: HEAD
  • Git Hash: 310f4db
  • Build Date: 2016-04-25
    05:15:50,685 INFO [LwjglContext] LWJGL 2.9.3 context running on thread jME3 Main
  • Graphics Adapter: aticfx64
  • Driver Version: 8.17.10.1404
  • Scaling Factor: 1
    05:15:50,749 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
    05:15:50,778 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.MeshLoader
    05:15:50,778 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.SkeletonLoader
    05:15:50,778 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.MaterialLoader
    05:15:50,779 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.SceneLoader
    05:15:50,779 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.blender.BlenderModelLoader
    05:15:50,780 WARN [AssetConfig] Cannot find loader com.jme3.scene.plugins.fbx.FbxLoader
    05:15:50,782 WARN [AssetConfig] Cannot find loader com.jme3.audio.plugins.OGGLoader
    05:15:50,810 INFO [DefaultControllerEnvironment] Loading: net.java.games.input.DirectAndRawInputEnvironmentPlugin
    05:15:51,076 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
    05:15:51,076 WARN [ALAudioRenderer] Pausing audio device not supported.
    05:15:51,076 INFO [ALAudioRenderer] Audio effect extension version: 1.0
    05:15:51,077 INFO [ALAudioRenderer] Audio max auxiliary sends: 4
    05:15:51,164 INFO [GuiGlobals] Initializing GuiGlobals with:com.simsilica.lemur.GuiGlobals@f41af17
    05:15:51,175 INFO [GuiGlobals] Lemur build date:20160918
    05:15:51,176 INFO [BaseStyles] loadStyleResource(com/simsilica/lemur/style/base/glass-styles.groovy)
    05:15:51,562 INFO [BaseStyles] Loading base resource:jar:file:/C:/Users/Min117/.m2/repository/com/simsilica/lemur/1.9.1-SNAPSHOT/lemur-1.9.1-SNAPSHOT.jar!/com/simsilica/lemur/style/base/glass-styles.groovy
    05:15:52,050 INFO [BaseStyles] Loading extension resources for:com/simsilica/lemur/style/base/glass-styles.groovy
    05:15:52,050 INFO [BaseStyles] Loading extension resource:jar:file:/C:/Users/Min117/.m2/repository/com/simsilica/lemur-proto/1.7.2-SNAPSHOT/lemur-proto-1.7.2-SNAPSHOT.jar!/com/simsilica/lemur/style/base/glass-styles.groovy
    05:15:56,836 INFO [MainMenuState] Host a game on port:4271
    05:15:56,836 INFO [MainMenuState] Description:
    05:15:56,836 INFO [MainMenuState] This a game server.
    There are many like it
    but this one is mine.
    05:15:56,895 DEBUG [DefaultServer] Adding standard services…
    05:15:57,082 INFO [GameServer] Initializing game systems…
    05:15:57,082 TRACE [GameSystemManager] initialize()
    05:15:57,083 TRACE [GameSystemManager] initializing:com.simsilica.sim.TaskDispatcher@7b337244
    05:15:57,083 TRACE [GameSystemManager] initializing:example.sim.SimplePhysics@1da4bf39
    05:15:57,083 TRACE [GameSystemManager] initializing:example.net.server.ZoneNetworkSystem@17b7528f
    05:15:57,083 TRACE [GameSystemManager] initializing:com.simsilica.es.server.EntityUpdater@181f1b63
    05:15:57,083 TRACE [GameSystemManager] initializing:example.sim.BodyPositionPublisher@785eeb76
    05:15:57,084 TRACE [GameSystemManager] initializing:example.sim.BasicEnvironment@403bde33
    05:15:57,085 INFO [GameServer] Starting game server…
    05:15:57,085 TRACE [GameSystemManager] start()
    05:15:57,085 TRACE [GameSystemManager] starting:com.simsilica.sim.TaskDispatcher@7b337244
    05:15:57,085 TRACE [GameSystemManager] starting:example.sim.SimplePhysics@1da4bf39
    05:15:57,117 TRACE [GameSystemManager] starting:example.net.server.ZoneNetworkSystem@17b7528f
    05:15:57,117 TRACE [GameSystemManager] starting:com.simsilica.es.server.EntityUpdater@181f1b63
    05:15:57,117 TRACE [GameSystemManager] starting:example.sim.BodyPositionPublisher@785eeb76
    05:15:57,117 TRACE [GameSystemManager] starting:example.sim.BasicEnvironment@403bde33
    05:15:57,164 INFO [StateCollector] Starting state collector.
    05:15:57,164 INFO [GameServer] Game server started.
    05:17:27,537 DEBUG [DefaultServer] Registering client for endpoint, pass 1:NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]].
    05:17:27,538 DEBUG [DefaultServer] Setting up channel:0
    05:17:27,538 TRACE [DefaultServer] send(ChannelInfoMessage[779177977019930, [[I@7c0130fc]])
    05:17:27,541 DEBUG [DefaultServer] Refining client registration for endpoint:UdpEndpoint[1, /127.0.0.1:50321].
    05:17:27,542 DEBUG [DefaultServer] Setting up channel:1
    05:17:27,560 DEBUG [DefaultServer] Refining client registration for endpoint:NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4273 remote=/127.0.0.1:50727]].
    05:17:27,560 DEBUG [DefaultServer] Setting up channel:3
    05:17:27,561 DEBUG [DefaultServer] Refining client registration for endpoint:NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4272 remote=/127.0.0.1:50726]].
    05:17:27,561 DEBUG [DefaultServer] Setting up channel:2
    05:17:27,561 DEBUG [DefaultServer] Client registered:Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ].
    05:17:27,562 TRACE [DefaultServer] send(com.jme3.network.message.ClientRegistrationMessage[id=0, gameName=null, version=0])
    05:17:27,562 TRACE [DefaultServer] send(com.jme3.network.message.SerializerRegistrationsMessage@32a92243)
    05:17:27,569 DEBUG [AccountHostedService] startHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ])
    05:17:27,587 TRACE [DefaultServer] send(-2, RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1])
    05:17:27,588 TRACE [DefaultServer] send(-2, RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4])
    05:17:27,593 TRACE [DefaultServer] send(com.jme3.network.message.ClientRegistrationMessage[id=-1, gameName=null, version=0])
    05:17:27,661 TRACE [DefaultServer] Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:27,661 TRACE [DefaultServer] Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:27,674 TRACE [DefaultServer] Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:27,674 TRACE [DefaultServer] Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:27,676 TRACE [DefaultServer] Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:27,676 TRACE [DefaultServer] Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:27,678 TRACE [DefaultServer] Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ] received:GetEntitySetMessage[0, null, [class example.es.BodyPosition]]
    05:17:27,728 TRACE [DefaultServer] Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50725]], fast=UdpEndpoint[1, /127.0.0.1:50321] ] received:RpcCallMessage[#0, channel=-2, sync, objId=1, procId=0, args.length=0]
    05:17:27,729 TRACE [DefaultServer] send(RpcResponseMessage[#0, result=This a game server.
    There are many like it
    but this one is mine.])
    05:17:30,150 DEBUG [DefaultServer] Connection closed:NioEndpoint[1, java.nio.channels.SocketChannel[closed]].
    05:17:30,150 DEBUG [DefaultServer] Connections size:0
    05:17:30,150 DEBUG [DefaultServer] Connection closed:NioEndpoint[1, java.nio.channels.SocketChannel[closed]].
    05:17:30,150 DEBUG [DefaultServer] Endpoint mappings size:3
    05:17:30,151 DEBUG [DefaultServer] Connection closed:NioEndpoint[1, java.nio.channels.SocketChannel[closed]].
    05:17:30,151 DEBUG [DefaultServer] Client closed:Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[1, /127.0.0.1:50321] ].
    05:17:30,151 DEBUG [DefaultServer] Connections size:0
    05:17:30,151 DEBUG [DefaultServer] Endpoint mappings size:2
    05:17:30,151 DEBUG [AccountHostedService] stopHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[1, /127.0.0.1:50321] ])
    05:17:30,151 DEBUG [AccountHostedService] publishing playerLoggedOff event for:Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[1, /127.0.0.1:50321] ]
    05:17:30,152 DEBUG [GameSessionHostedService] onPlayerLoggedOff()
    05:17:30,152 DEBUG [GameSessionHostedService] stopHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[1, /127.0.0.1:50321] ])
    05:17:30,152 DEBUG [DefaultServer] Connection closed:UdpEndpoint[1, /127.0.0.1:50321].
    05:17:30,152 DEBUG [DefaultServer] Connections size:0
    05:17:30,152 DEBUG [DefaultServer] Endpoint mappings size:1
    05:17:30,154 DEBUG [DefaultServer] Connections size:0
    05:17:30,154 DEBUG [DefaultServer] Endpoint mappings size:0
    05:17:30,153 ERROR [KernelAdapter] Unhandled error, endpoint:NioEndpoint[1, java.nio.channels.SocketChannel[closed]], context:EndpointEvent[REMOVE, NioEndpoint[1, java.nio.channels.SocketChannel[closed]]]
    java.lang.IllegalArgumentException: EntityId cannot be null.
    at com.simsilica.es.base.DefaultEntityData.removeComponent(DefaultEntityData.java:185) ~[zay-es-1.2.1.jar:?]
    at com.simsilica.es.base.DefaultEntityData.removeEntity(DefaultEntityData.java:126) ~[zay-es-1.2.1.jar:?]
    at example.net.server.AccountHostedService$AccountSessionImpl.dispose(AccountHostedService.java:194) ~[main/:?]
    at example.net.server.AccountHostedService.stopHostingOnConnection(AccountHostedService.java:135) ~[main/:?]
    at com.jme3.network.service.AbstractHostedConnectionService.connectionRemoved(AbstractHostedConnectionService.java:146) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.service.HostedServiceManager.removeConnection(HostedServiceManager.java:124) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.service.HostedServiceManager$ConnectionObserver.connectionRemoved(HostedServiceManager.java:137) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.DefaultServer.fireConnectionRemoved(DefaultServer.java:356) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.DefaultServer$Connection.closeConnection(DefaultServer.java:616) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.DefaultServer.connectionClosed(DefaultServer.java:513) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.KernelAdapter.connectionClosed(KernelAdapter.java:144) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.KernelAdapter.createAndDispatch(KernelAdapter.java:249) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.KernelAdapter.flushEvents(KernelAdapter.java:258) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.KernelAdapter.run(KernelAdapter.java:271) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    05:17:44,396 DEBUG [DefaultServer] Registering client for endpoint, pass 1:NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]].
    05:17:44,396 DEBUG [DefaultServer] Setting up channel:0
    05:17:44,397 TRACE [DefaultServer] send(ChannelInfoMessage[779194840031134, [[I@45f1bed8]])
    05:17:44,397 DEBUG [DefaultServer] Refining client registration for endpoint:UdpEndpoint[2, /127.0.0.1:50324].
    05:17:44,397 DEBUG [DefaultServer] Setting up channel:1
    05:17:44,401 DEBUG [DefaultServer] Refining client registration for endpoint:NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4272 remote=/127.0.0.1:50734]].
    05:17:44,402 DEBUG [DefaultServer] Setting up channel:2
    05:17:44,403 DEBUG [DefaultServer] Refining client registration for endpoint:NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4273 remote=/127.0.0.1:50735]].
    05:17:44,403 DEBUG [DefaultServer] Setting up channel:3
    05:17:44,403 DEBUG [DefaultServer] Client registered:Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ].
    05:17:44,403 TRACE [DefaultServer] send(com.jme3.network.message.ClientRegistrationMessage[id=1, gameName=null, version=0])
    05:17:44,404 TRACE [DefaultServer] send(com.jme3.network.message.SerializerRegistrationsMessage@32a92243)
    05:17:44,405 DEBUG [AccountHostedService] startHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ])
    05:17:44,408 TRACE [DefaultServer] send(-2, RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1])
    05:17:44,408 TRACE [DefaultServer] send(-2, RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4])
    05:17:44,408 TRACE [DefaultServer] send(com.jme3.network.message.ClientRegistrationMessage[id=-1, gameName=null, version=0])
    05:17:44,497 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:44,497 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:44,498 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:44,498 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:44,498 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:44,499 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:44,505 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:GetEntitySetMessage[0, null, [class example.es.BodyPosition]]
    05:17:44,523 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50733]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:RpcCallMessage[#0, channel=-2, sync, objId=1, procId=0, args.length=0]
    05:17:44,523 TRACE [DefaultServer] send(RpcResponseMessage[#0, result=This a game server.
    There are many like it
    but this one is mine.])
    05:17:45,907 TRACE [DefaultServer] Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:50324] ] received:ReleaseEntitySetMessage[0]
    05:17:45,907 DEBUG [DefaultServer] Connection closed:NioEndpoint[2, java.nio.channels.SocketChannel[closed]].
    05:17:45,907 DEBUG [DefaultServer] Connections size:0
    05:17:45,908 DEBUG [DefaultServer] Endpoint mappings size:3
    05:17:45,908 DEBUG [DefaultServer] Client closed:Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:50324] ].
    05:17:45,909 DEBUG [DefaultServer] Connection closed:NioEndpoint[2, java.nio.channels.SocketChannel[closed]].
    05:17:45,909 DEBUG [DefaultServer] Connections size:0
    05:17:45,909 DEBUG [DefaultServer] Endpoint mappings size:2
    05:17:45,909 DEBUG [AccountHostedService] stopHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:50324] ])
    05:17:45,910 DEBUG [AccountHostedService] publishing playerLoggedOff event for:Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:50324] ]
    05:17:45,910 DEBUG [GameSessionHostedService] onPlayerLoggedOff()
    05:17:45,910 DEBUG [GameSessionHostedService] stopHostingOnConnection(Connection[ id=1, reliable=NioEndpoint[2, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[2, /127.0.0.1:50324] ])
    05:17:45,910 ERROR [KernelAdapter] Unhandled error, endpoint:NioEndpoint[2, java.nio.channels.SocketChannel[closed]], context:EndpointEvent[REMOVE, NioEndpoint[2, java.nio.channels.SocketChannel[closed]]]
    java.lang.IllegalArgumentException: EntityId cannot be null.
    at com.simsilica.es.base.DefaultEntityData.removeComponent(DefaultEntityData.java:185) ~[zay-es-1.2.1.jar:?]
    at com.simsilica.es.base.DefaultEntityData.removeEntity(DefaultEntityData.java:126) ~[zay-es-1.2.1.jar:?]
    at example.net.server.AccountHostedService$AccountSessionImpl.dispose(AccountHostedService.java:194) ~[main/:?]
    at example.net.server.AccountHostedService.stopHostingOnConnection(AccountHostedService.java:135) ~[main/:?]
    at com.jme3.network.service.AbstractHostedConnectionService.connectionRemoved(AbstractHostedConnectionService.java:146) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.service.HostedServiceManager.removeConnection(HostedServiceManager.java:124) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.service.HostedServiceManager$ConnectionObserver.connectionRemoved(HostedServiceManager.java:137) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.DefaultServer.fireConnectionRemoved(DefaultServer.java:356) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.DefaultServer$Connection.closeConnection(DefaultServer.java:616) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.DefaultServer.connectionClosed(DefaultServer.java:513) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.KernelAdapter.connectionClosed(KernelAdapter.java:144) ~[jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.KernelAdapter.createAndDispatch(KernelAdapter.java:249) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.KernelAdapter.flushEvents(KernelAdapter.java:258) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    at com.jme3.network.base.KernelAdapter.run(KernelAdapter.java:271) [jme3-networking-3.1.0-beta1.jar:3.1-beta1]
    05:17:45,911 DEBUG [DefaultServer] Connection closed:UdpEndpoint[2, /127.0.0.1:50324].
    05:17:45,908 DEBUG [DefaultServer] Connection closed:NioEndpoint[2, java.nio.channels.SocketChannel[closed]].
    05:17:45,911 DEBUG [DefaultServer] Connections size:0
    05:17:45,911 DEBUG [DefaultServer] Endpoint mappings size:1
    05:17:45,912 DEBUG [DefaultServer] Connections size:0
    05:17:45,912 DEBUG [DefaultServer] Endpoint mappings size:0
    05:17:58,408 DEBUG [DefaultServer] Registering client for endpoint, pass 1:NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]].
    05:17:58,408 DEBUG [DefaultServer] Setting up channel:0
    05:17:58,408 TRACE [DefaultServer] send(ChannelInfoMessage[779208842778799, [[I@75684b23]])
    05:17:58,409 DEBUG [DefaultServer] Refining client registration for endpoint:UdpEndpoint[3, /127.0.0.1:50327].
    05:17:58,409 DEBUG [DefaultServer] Setting up channel:1
    05:17:58,414 DEBUG [DefaultServer] Refining client registration for endpoint:NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4272 remote=/127.0.0.1:50744]].
    05:17:58,414 DEBUG [DefaultServer] Setting up channel:2
    05:17:58,416 DEBUG [DefaultServer] Refining client registration for endpoint:NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4273 remote=/127.0.0.1:50745]].
    05:17:58,416 DEBUG [DefaultServer] Setting up channel:3
    05:17:58,416 DEBUG [DefaultServer] Client registered:Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ].
    05:17:58,416 TRACE [DefaultServer] send(com.jme3.network.message.ClientRegistrationMessage[id=2, gameName=null, version=0])
    05:17:58,417 TRACE [DefaultServer] send(com.jme3.network.message.SerializerRegistrationsMessage@32a92243)
    05:17:58,420 DEBUG [AccountHostedService] startHostingOnConnection(Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ])
    05:17:58,420 TRACE [DefaultServer] send(-2, RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1])
    05:17:58,421 TRACE [DefaultServer] send(-2, RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4])
    05:17:58,421 TRACE [DefaultServer] send(com.jme3.network.message.ClientRegistrationMessage[id=-1, gameName=null, version=0])
    05:17:58,499 TRACE [DefaultServer] Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:58,499 TRACE [DefaultServer] Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:58,500 TRACE [DefaultServer] Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:58,500 TRACE [DefaultServer] Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:58,500 TRACE [DefaultServer] Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=0, args.length=1]
    05:17:58,500 TRACE [DefaultServer] Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ] received:RpcCallMessage[#-1, channel=-2, async, objId=-1, procId=1, args.length=4]
    05:17:58,500 TRACE [DefaultServer] Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ] received:GetEntitySetMessage[0, null, [class example.es.BodyPosition]]
    05:17:58,538 TRACE [DefaultServer] Connection[ id=2, reliable=NioEndpoint[3, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4271 remote=/127.0.0.1:50743]], fast=UdpEndpoint[3, /127.0.0.1:50327] ] received:RpcCallMessage[#0, channel=-2, sync, objId=1, procId=0, args.length=0]
    05:17:58,538 TRACE [DefaultServer] send(RpcResponseMessage[#0, result=This a game server.
    There are many like it
    but this one is mine.])