Details
Description
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:
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
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:
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
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):
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
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.
Attachments
Attachments
Issue Links
- is related to
-
KARAF-7389 Problem installing features with embedded config
-
- Resolved
-