[
https://issues.apache.org/jira/browse/KARAF-7453?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jean-Baptiste Onofré resolved KARAF-7453.
-----------------------------------------
Fix Version/s: 4.4.1
4.3.8
Resolution: Fixed
> 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.4.0, 4.3.6
> Environment: Windows 10 and Debian 11, Karaf 4.3.6 and Karaf 4.4.0,
> Java 11
> Reporter: Sampsa Jurvansuu
> Assignee: Jean-Baptiste Onofré
> Priority: Major
> Fix For: 4.4.1, 4.3.8
>
> 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.10#820010)
