You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@karaf.apache.org by "Jean-Baptiste Onofré (Jira)" <ji...@apache.org> on 2022/06/24 08:55:00 UTC
[jira] [Updated] (KARAF-7453) Race condition in threaded ConnectorServerFactory
[ https://issues.apache.org/jira/browse/KARAF-7453?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jean-Baptiste Onofré updated KARAF-7453:
----------------------------------------
Target Version/s: 4.4.1, 4.3.8
> 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
> 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)