Sampsa Jurvansuu created KARAF-7453:
---------------------------------------
Summary: Race condition in threaded ConnectorServerFactory
Key: KARAF-7453
URL: https://issues.apache.org/jira/browse/KARAF-7453
Project: Karaf
Issue Type: Bug
Components: karaf
Affects Versions: 4.3.6, 4.4.0
Environment: Windows 10 and Debian 11, Karaf 4.3.6 and Karaf 4.4.0,
Java 11
Reporter: Sampsa Jurvansuu
Attachments: ConnectorServerFactory-1.java
When launching a vanilla Karaf 4.3.6/4.4.0 with default configuration, it
appears that the ConnectorServerFactory of org.apache.karaf.management.server
bundle is first initialized, then destroyed, and then again initialized all
within a time period of a fraction of a second. To demonstrate the timings of
the execution, we have added log outputs as presented in the attached
ConnectorServerFactory.java file. A typical output is as follows:
{code:java}
2022-06-22T08:56:52,810 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 40 - org.apache.karaf.management.server - 4.4.0 | Running
ConnectorServerFactory.init()
2022-06-22T08:56:52,839 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 40 - org.apache.karaf.management.server - 4.4.0 | Finished
ConnectorServerFactory.init()
2022-06-22T08:56:52,839 | DEBUG | JMX Connector Thread
[service:jmx:rmi://127.0.0.1:44444/jndi/rmi://127.0.0.1:1099/karaf-root] |
ConnectorServerFactory | 40 - org.apache.karaf.management.server -
4.4.0 | Starting ConnectorServer
2022-06-22T08:56:52,842 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 40 - org.apache.karaf.management.server - 4.4.0 | Running
ConnectorServerFactory.destroy()
2022-06-22T08:56:52,843 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 40 - org.apache.karaf.management.server - 4.4.0 | Stopping
ConnectorServer
2022-06-22T08:56:52,920 | DEBUG | JMX Connector Thread
[service:jmx:rmi://127.0.0.1:44444/jndi/rmi://127.0.0.1:1099/karaf-root] |
ConnectorServerFactory | 40 - org.apache.karaf.management.server -
4.4.0 | Started ConnectorServer
2022-06-22T08:56:52,924 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 40 - org.apache.karaf.management.server - 4.4.0 | Stopped
ConnectorServer
2022-06-22T08:56:52,926 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 40 - org.apache.karaf.management.server - 4.4.0 | Finished
ConnectorServerFactory.destroy()
2022-06-22T08:56:52,926 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 40 - org.apache.karaf.management.server - 4.4.0 | Running
ConnectorServerFactory.init()
2022-06-22T08:56:52,940 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 40 - org.apache.karaf.management.server - 4.4.0 | Finished
ConnectorServerFactory.init()
2022-06-22T08:56:52,940 | DEBUG | JMX Connector Thread
[service:jmx:rmi://127.0.0.1:44444/jndi/rmi://127.0.0.1:1099/karaf-root] |
ConnectorServerFactory | 40 - org.apache.karaf.management.server -
4.4.0 | Starting ConnectorServer
2022-06-22T08:56:52,950 | DEBUG | JMX Connector Thread
[service:jmx:rmi://127.0.0.1:44444/jndi/rmi://127.0.0.1:1099/karaf-root] |
ConnectorServerFactory | 40 - org.apache.karaf.management.server -
4.4.0 | Started ConnectorServer {code}
In this typical run everything ends up working fine. Though we can already see
some risky overlapping of the JMX server still booting up, while already
starting to destroy it.
However, when running the Karaf with more bundles and overall more complicated
configuration (using version 4.3.6 in this case), it happens that occasionally
(approx. 1 out of 10 runs) the thread execution is timed slightly differently
leading to following output:
{code:java}
2022-06-22T09:31:29,856 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 382 - org.apache.karaf.management.server - 4.3.6 | Running
ConnectorServerFactory.init()
2022-06-22T09:31:29,883 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 382 - org.apache.karaf.management.server - 4.3.6 | Finished
ConnectorServerFactory.init()
2022-06-22T09:31:29,887 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 382 - org.apache.karaf.management.server - 4.3.6 | Running
ConnectorServerFactory.destroy()
2022-06-22T09:31:29,887 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 382 - org.apache.karaf.management.server - 4.3.6 | Stopping
ConnectorServer
2022-06-22T09:31:29,892 | DEBUG | JMX Connector Thread
[service:jmx:rmi://<server-name>:44444/jndi/rmi://<server-name>:1099/karaf-server]
| ConnectorServerFactory | 382 - org.apache.karaf.management.server
- 4.3.6 | Starting ConnectorServer
2022-06-22T09:31:29,888 | WARN | activator-1-thread-1 | Activator
| 382 - org.apache.karaf.management.server - 4.3.6 | Error destroying
ConnectorServerFactory
java.rmi.NoSuchObjectException: object not exported
at sun.rmi.transport.ObjectTable.unexportObject(ObjectTable.java:151)
~[?:?]
at
java.rmi.server.UnicastRemoteObject.unexportObject(UnicastRemoteObject.java:457)
~[?:?]
at
javax.management.remote.rmi.RMIJRMPServerImpl.unexport(RMIJRMPServerImpl.java:168)
~[?:?]
at
javax.management.remote.rmi.RMIJRMPServerImpl.closeServer(RMIJRMPServerImpl.java:233)
~[?:?]
at
javax.management.remote.rmi.RMIServerImpl.close(RMIServerImpl.java:406) ~[?:?]
at
javax.management.remote.rmi.RMIConnectorServer.stop(RMIConnectorServer.java:612)
~[?:?]
at
org.apache.karaf.management.ConnectorServerFactory.destroy(ConnectorServerFactory.java:490)
~[bundleFile:?]
at
org.apache.karaf.management.internal.Activator.doStop(Activator.java:239)
[bundleFile:?]
at
org.apache.karaf.util.tracker.BaseActivator.run(BaseActivator.java:310)
[bundleFile:?]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[?:?]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2022-06-22T09:31:29,897 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 382 - org.apache.karaf.management.server - 4.3.6 | Running
ConnectorServerFactory.init()
2022-06-22T09:31:29,966 | DEBUG | activator-1-thread-1 | ConnectorServerFactory
| 382 - org.apache.karaf.management.server - 4.3.6 | Finished
ConnectorServerFactory.init()
2022-06-22T09:31:29,972 | DEBUG | JMX Connector Thread
[service:jmx:rmi://<server-name>:44444/jndi/rmi://<server-name>:1099/karaf-server]
| ConnectorServerFactory | 382 - org.apache.karaf.management.server
- 4.3.6 | Starting ConnectorServer
2022-06-22T09:31:30,113 | DEBUG | JMX Connector Thread
[service:jmx:rmi://<server-name>:44444/jndi/rmi://<server-name>:1099/karaf-server]
| ConnectorServerFactory | 382 - org.apache.karaf.management.server
- 4.3.6 | Started ConnectorServer{code}
As seen from the above log, the factory gets destroyed already before the first
initialization is executed in the separate thread. This conflict also outputs
the following stack trace to the stdout/stderr (supposedly because the
exception thrown in the separate thread is not caught by the main activator
thread):
{code:java}
Jun 22 09:31:29 <server-name> karaf[76019]: Exception in thread "JMX Connector
Thread
[service:jmx:rmi://<server-name>:44444/jndi/rmi://<server-name>:1099/karaf-server]"
java.lang.RuntimeException: Could not start JMX connector server
Jun 22 09:31:29 <server-name> karaf[76019]: at
org.apache.karaf.management.ConnectorServerFactory.lambda$init$0(ConnectorServerFactory.java:444)
Jun 22 09:31:29 <server-name> karaf[76019]: at
java.base/java.lang.Thread.run(Thread.java:829)
Jun 22 09:31:29 <server-name> karaf[76019]: Caused by: java.io.IOException: The
server has been stopped.
Jun 22 09:31:29 <server-name> karaf[76019]: at
java.management.rmi/javax.management.remote.rmi.RMIConnectorServer.start(RMIConnectorServer.java:420)
Jun 22 09:31:29 <server-name> karaf[76019]: at
org.apache.karaf.management.ConnectorServerFactory.lambda$init$0(ConnectorServerFactory.java:427)
Jun 22 09:31:29 <server-name> karaf[76019]: ... 1 more {code}
In this scenario, even though the second initialization appears to finish
normally, the JMX server is not actually in a functional state and cannot be
reached, requiring a manual restart of either the bundle or the whole Karaf
instance.
A workaround for the issue is to disable the threading for the
ConnectorServerFactory. However, it would be more desirable to be able to run
the JMX server reliably in the threaded mode.
--
This message was sent by Atlassian Jira
(v8.20.7#820007)
