[SOLVED] Problem with networking on openjdk 10

Troubleshooting networking
1

Hi

I am running to a networking issue after upgrading my linux os.
In my previous linux os I was using oracle jdk 8 and had no issue but after upgrading my linux which comes with openjdk 10 I encountered with following issue.

java.lang.IllegalMonitorStateException: attempt to unlock read lock, not locked by current thread

To get insure it is not a problem with my code I tested it with both network-basic and sim-eth-basic examples from GitHub - Simsilica/Examples: Example applications for various Simsilica libraries, singly or in combination..

There was no issue with network-basic example but with sim-eth-basic I ran to same issue.

Executing: gradle :run
Arguments: [-PmainClass=example.Main, -PcmdLineArgs=, -PjvmLineArgs=, -c, /media/ali/My Passport/Java/jME_NB-PW-11-6-2015/Examples/sim-eth-basic/settings.gradle]

> Task :compileJava UP-TO-DATE
> Task :processResources UP-TO-DATE
> Task :classes UP-TO-DATE
> Task :assets:compileJava NO-SOURCE
> Task :assets:processResources UP-TO-DATE
> Task :assets:classes UP-TO-DATE
> Task :assets:jar UP-TO-DATE

> Task :run
SimEthereal Example
Setting root JUL log level to:INFO
logger config:root
Setting JUL Log: level to:INFO
logger config:com.simsilica.sim
Setting JUL Log:com.simsilica.sim level to:FINER
logger config:example
Setting JUL Log:example level to:FINE
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.jme3.util.ReflectionAllocator (file:/media/ali/My%20Passport/Linux/home/idea/.m2/repository/org/jmonkeyengine/jme3-core/3.3.0-SNAPSHOT/jme3-core-3.3.0-SNAPSHOT.jar) to method sun.nio.ch.DirectBuffer.cleaner()
WARNING: Please consider reporting this to the maintainers of com.jme3.util.ReflectionAllocator
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
18:13:16,599 INFO  [JmeSystem] Running on jMonkeyEngine 3.3-6611
 * Branch: master
 * Git Hash: 4997145
 * Build Date: 2018-09-27
18:13:17,040 INFO  [LwjglContext] LWJGL 2.9.3 context running on thread jME3 Main
 * Graphics Adapter: null
 * Driver Version: null
 * Scaling Factor: 1
18:13:17,079 INFO  [GLRenderer] OpenGL Renderer Information
 * Vendor: Intel Open Source Technology Center
 * Renderer: Mesa DRI Intel(R) Sandybridge Mobile 
 * OpenGL Version: 3.0 Mesa 18.0.0-rc5
 * GLSL Version: 1.30
 * Profile: Compatibility
18:13:17,152 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.MeshLoader
18:13:17,153 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.SkeletonLoader
18:13:17,155 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.MaterialLoader
18:13:17,157 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.ogre.SceneLoader
18:13:17,158 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.blender.BlenderModelLoader
18:13:17,163 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.fbx.FbxLoader
18:13:17,165 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.gltf.GltfLoader
18:13:17,166 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.gltf.BinLoader
18:13:17,167 WARN  [AssetConfig] Cannot find loader com.jme3.scene.plugins.gltf.GlbLoader
18:13:17,171 WARN  [AssetConfig] Cannot find loader com.jme3.audio.plugins.OGGLoader
18:13:17,236 INFO  [DefaultControllerEnvironment] Loading: net.java.games.input.LinuxEnvironmentPlugin
18:13:17,257 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event0): Failed to open device /dev/input/event0 (13)


18:13:17,258 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event1): Failed to open device /dev/input/event1 (13)


18:13:17,258 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event10): Failed to open device /dev/input/event10 (13)


18:13:17,259 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event11): Failed to open device /dev/input/event11 (13)


18:13:17,259 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event12): Failed to open device /dev/input/event12 (13)


18:13:17,259 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event13): Failed to open device /dev/input/event13 (13)


18:13:17,260 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event14): Failed to open device /dev/input/event14 (13)


18:13:17,260 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event2): Failed to open device /dev/input/event2 (13)


18:13:17,260 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event3): Failed to open device /dev/input/event3 (13)


18:13:17,261 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event4): Failed to open device /dev/input/event4 (13)


18:13:17,261 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event5): Failed to open device /dev/input/event5 (13)


18:13:17,262 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event6): Failed to open device /dev/input/event6 (13)


18:13:17,262 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event7): Failed to open device /dev/input/event7 (13)


18:13:17,263 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event8): Failed to open device /dev/input/event8 (13)


18:13:17,273 INFO  [ControllerEnvironment] Failed to open device (/dev/input/event9): Failed to open device /dev/input/event9 (13)


18:13:17,275 INFO  [ControllerEnvironment] Linux plugin claims to have found 0 controllers

18:13:17,332 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
18:13:17,333 WARN  [ALAudioRenderer] Pausing audio device not supported.
18:13:17,334 INFO  [ALAudioRenderer] Audio effect extension version: 1.0
18:13:17,335 INFO  [ALAudioRenderer] Audio max auxiliary sends: 4
18:13:17,533 INFO  [GuiGlobals] Initializing GuiGlobals with:com.simsilica.lemur.GuiGlobals@481998
18:13:17,551 INFO  [GuiGlobals] Lemur build date:20170212
18:13:17,553 INFO  [BaseStyles] loadStyleResource(com/simsilica/lemur/style/base/glass-styles.groovy)
18:13:18,466 INFO  [BaseStyles] Loading base resource:jar:file:/media/ali/My%20Passport/Linux/home/idea/opt/packages/gradle/caches/modules-2/files-2.1/com.simsilica/lemur-proto/1.9.1/6b36149a2ddcd08ea4cc25c9b673e3bf7c390133/lemur-proto-1.9.1.jar!/com/simsilica/lemur/style/base/glass-styles.groovy
18:13:19,415 INFO  [BaseStyles] Loading extension resources for:com/simsilica/lemur/style/base/glass-styles.groovy
18:13:19,416 INFO  [BaseStyles] Loading extension resource:jar:file:/media/ali/My%20Passport/Linux/home/idea/opt/packages/gradle/caches/modules-2/files-2.1/com.simsilica/lemur/1.10.1/b5842a13eaa190389d66883d3496ddfd65703790/lemur-1.10.1.jar!/com/simsilica/lemur/style/base/glass-styles.groovy
18:13:24,150 INFO  [MainMenuState] Host a game on port:4269
18:13:24,151 INFO  [MainMenuState] Description:
18:13:24,151 INFO  [MainMenuState] This a game server.
There are many like it
but this one is mine.
Bit size:48  mask:ffffffffffff
Bit size:48  mask:ffffffffffff
18:13:24,270 INFO  [GameServer] Initializing game systems...
18:13:24,271 TRACE [GameSystemManager] initialize()
18:13:24,273 TRACE [GameSystemManager] initializing:com.simsilica.sim.TaskDispatcher@76facb91
18:13:24,273 TRACE [GameSystemManager] initializing:example.sim.SimplePhysics@63d2b739
18:13:24,274 TRACE [GameSystemManager] initializing:example.net.server.ZoneNetworkSystem@18c0cd4d
18:13:24,275 INFO  [GameServer] Starting game server...
18:13:24,275 TRACE [GameSystemManager] start()
18:13:24,276 TRACE [GameSystemManager] starting:com.simsilica.sim.TaskDispatcher@76facb91
18:13:24,276 TRACE [GameSystemManager] starting:example.sim.SimplePhysics@63d2b739
18:13:24,276 TRACE [GameSystemManager] starting:example.net.server.ZoneNetworkSystem@18c0cd4d
18:13:24,299 INFO  [StateCollector] Starting state collector.
18:13:24,300 INFO  [GameServer] Game server started.
zone update underflow FPS:58
18:13:26,706 INFO  [HostState] joinGame()
18:13:26,724 INFO  [ConnectionState] Creating game client for:127.0.0.1 4269
18:13:26,726 INFO  [GameClient] Connecting to:127.0.0.1 4269
18:13:26,766 INFO  [SerializerRegistrationsMessage] Skipping registration of SerializerRegistrationsMessage.
18:13:26,773 INFO  [GameClient] Adding services...
18:13:26,799 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]]])
18:13:26,800 DEBUG [AccountClientService] Sharing session callback.
18:13:26,801 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]]])
18:13:26,801 DEBUG [GameSessionClientService] Sharing session callback.
18:13:26,802 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], example.net.chat.client.ChatClientService[serviceManager.class=class com.jme3.network.service.ClientServiceManager]]])
18:13:26,802 DEBUG [ChatClientService] Sharing session callback.
18:13:26,813 INFO  [ConnectionState] Connection established:example.net.client.GameClient@22d7a225
18:13:26,817 INFO  [ConnectionState] Starting client...
18:13:26,817 INFO  [GameClient] start()
18:13:26,827 INFO  [ConnectionState] Client started.
18:13:26,839 INFO  [ConnectionState] Connection established:example.net.client.GameClient@22d7a225
18:13:26,875 INFO  [SerializerRegistrationsMessage] Skipping registration as registry is locked, presumably by a local server process.
18:13:26,885 DEBUG [AccountHostedService] startHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4269 remote=/127.0.0.1:44920]], fast=UdpEndpoint[1, /127.0.0.1:35991] ])
18:13:26,892 ERROR [KernelAdapter] Unhandled error, endpoint:NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4270 remote=/127.0.0.1:36264]], context:Envelope[NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4270 remote=/127.0.0.1:36264]], reliable, 18]
java.lang.IllegalMonitorStateException: attempt to unlock read lock, not locked by current thread
	at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$Sync.unmatchedUnlockException(ReentrantReadWriteLock.java:448) ~[?:?]
	at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(ReentrantReadWriteLock.java:432) ~[?:?]
	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(AbstractQueuedSynchronizer.java:1380) ~[?:?]
	at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java:897) ~[?:?]
	at com.jme3.network.service.rmi.ClassInfoRegistry.getClassInfo(ClassInfoRegistry.java:92) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:131) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:107) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:96) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at example.net.server.AccountHostedService.startHostingOnConnection(AccountHostedService.java:101) ~[main/:?]
	at com.jme3.network.service.AbstractHostedConnectionService.connectionAdded(AbstractHostedConnectionService.java:131) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.HostedServiceManager.addConnection(HostedServiceManager.java:114) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.HostedServiceManager$ConnectionObserver.connectionAdded(HostedServiceManager.java:132) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.DefaultServer.fireConnectionAdded(DefaultServer.java:349) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.DefaultServer.registerClient(DefaultServer.java:447) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.KernelAdapter.dispatch(KernelAdapter.java:173) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.KernelAdapter.createAndDispatch(KernelAdapter.java:241) [jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.KernelAdapter.run(KernelAdapter.java:284) [jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
18:13:26,904 ERROR [ConnectionState] Connection error
com.jme3.network.kernel.ConnectorException: Connector closed.
	at com.jme3.network.base.ConnectorAdapter.run(ConnectorAdapter.java:161) [jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
18:13:26,920 ERROR [ConnectionState] Connection error
com.jme3.network.kernel.ConnectorException: Connector closed.
	at com.jme3.network.base.ConnectorAdapter.run(ConnectorAdapter.java:161) [jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
18:13:26,922 DEBUG [AccountHostedService] stopHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[1, /127.0.0.1:35991] ])
18:13:26,928 DEBUG [GameSessionHostedService] stopHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[1, /127.0.0.1:35991] ])
18:13:26,929 DEBUG [ChatHostedService] stopHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[closed]], fast=UdpEndpoint[1, /127.0.0.1:35991] ])
zone update underflow FPS:59
18:13:27,907 INFO  [ConnectionState] disconnect()
18:13:27,907 INFO  [ConnectionState] Detaching ConnectionState
18:13:27,908 INFO  [GameClient] close()
18:13:27,909 INFO  [ConnectionState] clientDisconnected(com.jme3.network.base.DefaultClient@2133cf3e, null)
18:13:27,924 INFO  [ConnectionState] onDisconnected(null)
18:13:29,243 INFO  [HostState] stopHosting()
18:13:29,244 INFO  [GameServer] Stopping game server...Shutting down.
18:13:29,244 TRACE [GameSystemManager] stop()
18:13:29,244 TRACE [GameSystemManager] stopping:com.simsilica.sim.TaskDispatcher@76facb91
18:13:29,245 TRACE [GameSystemManager] stopping:example.sim.SimplePhysics@63d2b739
18:13:29,245 TRACE [GameSystemManager] stopping:example.net.server.ZoneNetworkSystem@18c0cd4d
18:13:29,245 TRACE [GameSystemManager] terminate()
18:13:29,245 TRACE [GameSystemManager] terminating:com.simsilica.sim.TaskDispatcher@76facb91
18:13:29,245 TRACE [GameSystemManager] terminating:example.sim.SimplePhysics@63d2b739
18:13:29,245 TRACE [GameSystemManager] terminating:example.net.server.ZoneNetworkSystem@18c0cd4d
18:13:29,246 INFO  [StateCollector] Shuttong down state collector.
18:13:29,247 INFO  [GameServer] Game server stopped.

Deprecated Gradle features were used in this build, making it incompatible with Gradle 5.0.
Use '--warning-mode all' to show the individual deprecation warnings.
See https://docs.gradle.org/4.10.2/userguide/command_line_interface.html#sec:command_line_warnings

BUILD SUCCESSFUL in 31s
5 actionable tasks: 1 executed, 4 up-to-date

I will appreciate if somebody who has java 9/10/11 can test it.

1 Like
2

As far as Iā€™m aware, Jme only supports java 7(?) and 8. Support for 9 onwards requires quite a lot of work.

The general workflow is to provide the relevant Jre with your game, and not to expect the end user to have java installed.

1 Like
3

As far as I know we are not forced to use module system to be able to use java 9 onwards.

And I was able to run jme-examples and network-basic example with no problem. only with SimEthereal example I got that issue.

4

If only the other 99% of the useful information were included then I might be able to commentā€¦

5

The whole stack trace is already included in my first post ā€¦ unless you mean something else ā€¦

putting it here again

18:13:26,875 INFO  [SerializerRegistrationsMessage] Skipping registration as registry is locked, presumably by a local server process.
18:13:26,885 DEBUG [AccountHostedService] startHostingOnConnection(Connection[ id=0, reliable=NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4269 remote=/127.0.0.1:44920]], fast=UdpEndpoint[1, /127.0.0.1:35991] ])
18:13:26,892 ERROR [KernelAdapter] Unhandled error, endpoint:NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4270 remote=/127.0.0.1:36264]], context:Envelope[NioEndpoint[1, java.nio.channels.SocketChannel[connected local=/127.0.0.1:4270 remote=/127.0.0.1:36264]], reliable, 18]
java.lang.IllegalMonitorStateException: attempt to unlock read lock, not locked by current thread
	at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$Sync.unmatchedUnlockException(ReentrantReadWriteLock.java:448) ~[?:?]
	at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(ReentrantReadWriteLock.java:432) ~[?:?]
	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(AbstractQueuedSynchronizer.java:1380) ~[?:?]
	at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java:897) ~[?:?]
	at com.jme3.network.service.rmi.ClassInfoRegistry.getClassInfo(ClassInfoRegistry.java:92) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:131) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:107) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:96) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at example.net.server.AccountHostedService.startHostingOnConnection(AccountHostedService.java:101) ~[main/:?]
	at com.jme3.network.service.AbstractHostedConnectionService.connectionAdded(AbstractHostedConnectionService.java:131) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.HostedServiceManager.addConnection(HostedServiceManager.java:114) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.service.HostedServiceManager$ConnectionObserver.connectionAdded(HostedServiceManager.java:132) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.DefaultServer.fireConnectionAdded(DefaultServer.java:349) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.DefaultServer.registerClient(DefaultServer.java:447) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.KernelAdapter.dispatch(KernelAdapter.java:173) ~[jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.KernelAdapter.createAndDispatch(KernelAdapter.java:241) [jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
	at com.jme3.network.base.KernelAdapter.run(KernelAdapter.java:284) [jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
18:13:26,904 ERROR [ConnectionState] Connection error
com.jme3.network.kernel.ConnectorException: Connector closed.
	at com.jme3.network.base.ConnectorAdapter.run(ConnectorAdapter.java:161) [jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
18:13:26,920 ERROR [ConnectionState] Connection error
com.jme3.network.kernel.ConnectorException: Connector closed.
	at com.jme3.network.base.ConnectorAdapter.run(ConnectorAdapter.java:161) [jme3-networking-3.3.0-SNAPSHOT.jar:3.3-6611]
6

Itā€™s weird. I donā€™t see how that error can happen. In fact, that code (as far as I can tell) is following the example that the JDK uses for write lock/read lock management.

Unless there is some other lock-related exception that is getting hidden by this one, I canā€™t see how a different thread could have gotten the lock.

Edit: JDK reference used in case it helps tracking down the JDK 10 breaking change:
https://docs.oracle.com/javase/7/docs/api/java/util/concurrent/locks/ReentrantReadWriteLock.html

7

Might be because of client and server are running in the same instance?
This error happens right after client joins to server.

8

No, I meanā€¦ the lock code is there for exactly this kind of case. Logically, I cannot see how one thread would be allowed to get past the lock() that the other thread has already grabbed.

Edit: unless one of the other lock calls already threw an exception and so the lock() fails. (as hinted previously)

9

Lets be precise here:

IllegalMonitorStateException: attempt to unlock read lock, not locked by current thread

does not necessarily indicate that another thread has the lock. It simply means that this thread does NOT have the lock.

Per This Stackoverflow Answer, you can get this error in a single-thread situation(WRT the lock) if you accidentally call ReadLock.unlock twice, without re-acquiring the lock in between.

It appears that JMEā€™s ClassInfoRegistry.getClassInfo() is lacking some Catch blocks or guarding.

If either the attempt to grab a write-lock fails at line 72 or any exception is thrown by the inner try block starting on line 73, you will have this double-release issue.

Iā€™d expect that issues with the inner try block would cause a similar exception on line 89 first.

(EDIT: but, the finally block has no access to the original error inside a try - thatā€™s what catch is for! That exception would be swallowed, as would errors in the acquisition of the WriteLock, which is probably what @pspeed meant!)

RE: ā€˜getting past a lock that another thread had already grabbedā€™

  • This code is repeatedly unlocking and re-locking the same resource. the in-code comments even mention that a thread race is a theoretical possibility, and the author just didnā€™t think it was a problem
  • Changes to JVM architecture or libraries could certainly make such a conflict more likely, if they affect the relative timing of different parts of a simple example
2 Likes
10

I wrote the code. The race condition has nothing to do with locks.

Itā€™s super-duper-duper-duper-super-duper-duper-super-duper-duper-duper common to only have try/finally in cases where you expect no exceptions in general.

JDK10 must have added some non-exceptional cases where locks throw exceptions? Else I canā€™t explain it. Folks are welcome to add a catch similar to the following to see what the real exception is:

catch( Exception e ) {
   log the exception
   System.exit(-1); // because everything is totally f$cked now and there is no way to continue
}

Edit: I will also point out that JDK 10 still has the exact same read/write shuffling code example:
https://docs.oracle.com/javase/10/docs/api/java/util/concurrent/locks/ReentrantReadWriteLock.html

ā€¦with no catches.

So something really weird must be happening if that code is throwing exceptions in a way that fouls the locksā€¦ and I suggest that System.exit(-1) is probably the only way to recover.

11

Iā€™ll trust you on that, as I donā€™t know anything about the rest of the related code. I didnā€™t realize that you had written it. That was a bit of speculation on my part regarding why this seems to be JVM version dependent for the OP.

My point was that this:

is not necessarily so. There is a bit of difference between the Javadoc example code, and ClassInfoRegistry

Javadoc shows two sequential try..finally pairs:

try
{...} //Any exceptions thrown here...
finally
{...}  // will bubble up as soon as this block is finished...

try
{...} // And this would never be touched, so any inconsistent state is irrelevant
finally
{...}

ClassInfoRegistry, however, has nested try..finally blocks:
(major squishing for easier reading on the forum)

 try 
{
    if (cacheIsPopulated)
    {
         return cached.value;  // So far, so good  - but what if not cached?
     } else
     {
         lock.readLock().unlock(); // Drop our readLock!!!! (A)
         lock.writeLock().lock();
         try 
         {
              /******************
              * If either of these calls throw _Any Sort_ of exception,
               * the try block bails early..... (B)
              ***********/
              result = new ClassInfo((short)nextClassId.getAndIncrement(), type);
              cache.put(type, result);

              lock.readLock().lock(); // And this line never gets executed. No readLock! (C)
              return result;
         } finally
         {
             lock.writeLock().unlock(); 
         }
    } // The exception from the inner try block causes the outer to throw.
      // Before it does that, however, it will try to run the finally block... (D)

} finally
{
    lock.readLock().unlock(); // Which throws its own exception. We do not _have_ a readLock at this point!
}

The later exception is definitely not caught, so it bubbles to the top, and barfs on the command line. The original issue is swallowed whole, and probably had nothing to do with the lock in the first place.

Iā€™m not set up to do a full build of JME to test this. Hope that this helps the OP/others to track down what is failing thoughā€¦

1 Like
12

Thatā€™s true, it does nest.

ā€¦which does limit where the problems can happen.

Itā€™s either:
lock.writeLock().lock();
or:
new ClassInfo(ā€¦);

And the method becomes quite ugly if you try to untie those try/finally. Iā€™d rather just adopt a Guava dependency and remove it all, really.

14

Anywayā€¦ I look forward to seeing what the real error is if someone tries it. Perhaps we can push the code structure problem for another day if it turns out to be something dumb.

15

Went ahead and add catch block to find error.

public ClassInfo getClassInfo( Class type ) {        
    //return cache.getUnchecked(type); // Guava version

    // More complicated without guava
    lock.readLock().lock();
    try {
        ClassInfo result = cache.get(type);
        if( result != null ) {
            return result;
        }
        // Else we need to create it and store it... so grab the write
        // lock
        lock.readLock().unlock();
        lock.writeLock().lock();
        try {
            // Note: it's technically possible that a race with another thread
            // asking for the same class already created one between our read unlock
            // and our write lock.  No matter as it's cheap to create one and does
            // no harm.  Code is simpler without the double-check.
            result = new ClassInfo((short)nextClassId.getAndIncrement(), type);
            cache.put(type, result);
            
            // Regrab the read lock before leaving... kind of unnecessary but
            // it makes the method cleaner and widens the gap of lock races.
            // Downgrading a write lock to read is ok.
            lock.readLock().lock();
            
            return result;
        } catch(Throwable e) { 
            System.err.println("Bad Error :"); 
            e.printStackTrace();
            System.exit(-1); 
        }finally {
            // Unlock the write lock while still holding onto read
            lock.writeLock().unlock();
        }
        
    } catch(Throwable e) { 
        System.err.println("Bad Error :"); 
        e.printStackTrace();
        System.exit(-1); 
    }finally {
        lock.readLock().unlock();
    }
    
    return null;
}

and here is the output :

java.lang.NoClassDefFoundError: javax/jws/Oneway
	at com.jme3.network.service.rmi.MethodInfo.getCallType(MethodInfo.java:107)
	at com.jme3.network.service.rmi.MethodInfo.<init>(MethodInfo.java:67)
	at com.jme3.network.service.rmi.ClassInfo.toMethodInfo(ClassInfo.java:99)
	at com.jme3.network.service.rmi.ClassInfo.<init>(ClassInfo.java:62)
	at com.jme3.network.service.rmi.ClassInfoRegistry.getClassInfo(ClassInfoRegistry.java:78)
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:131)
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:107)
	at com.jme3.network.service.rmi.RmiRegistry.share(RmiRegistry.java:96)
	at example.net.server.AccountHostedService.startHostingOnConnection(AccountHostedService.java:101)
	at com.jme3.network.service.AbstractHostedConnectionService.connectionAdded(AbstractHostedConnectionService.java:131)
	at com.jme3.network.service.HostedServiceManager.addConnection(HostedServiceManager.java:114)
	at com.jme3.network.service.HostedServiceManager$ConnectionObserver.connectionAdded(HostedServiceManager.java:132)
	at com.jme3.network.base.DefaultServer.fireConnectionAdded(DefaultServer.java:349)
	at com.jme3.network.base.DefaultServer.registerClient(DefaultServer.java:447)
	at com.jme3.network.base.KernelAdapter.dispatch(KernelAdapter.java:173)
	at com.jme3.network.base.KernelAdapter.createAndDispatch(KernelAdapter.java:241)
	at com.jme3.network.base.KernelAdapter.run(KernelAdapter.java:284)
Caused by: java.lang.ClassNotFoundException: javax.jws.Oneway
	at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:582)
	at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:190)
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:499)
	... 17 more
16

I guess maybe they removed the class?

https://docs.oracle.com/javase/7/docs/api/javax/jws/Oneway.html

ā€¦thatā€™s too bad.

17

Yes that is removed as part of JavaEE modules.

Then what is the best way to deal with this in jme side ?
The only class uses Oneway annotation is MethodInfo.java

Edit:
Canā€™t we just remove that part from getCallType () ?

18

Then we have to add our own annotation that means the same thing. A shame, really.

Oh, and break all of JME code pre JDK10 that uses this. I donā€™t know how many there are but surely I added it for some reason.

I guess I probably used it in code that didnā€™t want to depend on ā€œAll of JME networkingā€ just to get the Asynchronous annotation. So even rolling our own doesnā€™t solve the issue, I guess.

19

For the moment I could solve this problem by adding javax.jws maven artifact to my project dependencies.

// https://mvnrepository.com/artifact/javax.jws/javax.jws-api
    compile group: 'javax.jws', name: 'javax.jws-api', version: '1.1'
4 Likes
20

No need for all that.

That either.

The class is still installed with a full standard jvm, itā€™s just in an optional module that is not loaded to the classpath by default. Have the launcher check the jvm version, and on 9+, add --add-modules java.xml.ws to the jvm options.

If you really want to go nuclear, use java.se.ee instead, which is a catch-all module that grabs everything that used to be on the default classpath. Itā€™s deprecated,a itā€™s only intended to keep legacy systems running until the maintainers have time to move to the module system.

21

slightly unrelated, but where have you come by this information? Myself and many others might like to ready themselves in the future when upgrading past 1.8.