We have an application, and upgraded from Apache's Servicemix 4.5.3 to Servicemix 6.1.0. We also upgraded from Apache Commons dbcp to dbcp2 and pool2. One thing I noticed after this upgrade, was that bundle start-up and shutdown was very, very slow. So I looked around with Google and found that Spring-DM is deprecated and will be replaced with Blueprint. So I replaced Spring-DM configuration to Blueprint for all the bundles, and now they are much faster in start-up and shutdown.
However I see some different behavior after this operation. For example, We've made Camel Routebuilders and in the configure() method, we get some configuration from the Database. In other cases we have a bean with a setDataSource(..) method and we inject the database connection into it via blueprint, and after storing that connection in a backing fielkd, we do a call to the DB for some extra (cached) initialization.
In this area we now get exceptions with Blueprint, while we never had these with Spring-DM. The MySql Drive class cannot be found. The setDataSource(..) method gets a proxy-class, while the backing service has not been initialized. A call to this proxy class results in an exception and the bundle start fails. If you manually restart the bundle later on, then it works fine; probably because the dependency has then been solved.
Ok, long intro. This is what we do in code.
In the deploy folder, we have a file called jndi.xml, and this is a fragment of its contents:
<blueprint xmlns="http://www.osgi.org/xmlns/blueprint/v1.0.0"
xmlns:cm="http://aries.apache.org/blueprint/xmlns/blueprint-cm/v1.0.0"
>
<cm:property-placeholder id="database.properties" persistent-id="our.database.connection.properties"/>
<bean id="datasourceMain" class="org.apache.commons.dbcp2.managed.BasicManagedDataSource" destroy-method="close">
<property name="driverClassName" value="com.mysql.jdbc.Driver"/>
<property name="url" value="${connection-string}"/>
<property name="username" value="${connection-username}"/>
<property name="password" value="${connection-password}"/>
<property name="maxTotal" value="20"/>
<property name="maxIdle" value="10"/>
<property name="maxWaitMillis" value="5000"/>
<property name="minEvictableIdleTimeMillis" value="2880000"/>
<property name="testWhileIdle" value="true"/>
<property name="validationQuery" value="select 1"/>
<property name="transactionManager" ref="jtaTransactionManager"/>
</bean>
<service id="serviceMade" interface="javax.sql.DataSource" ref="datasourceOurApp">
<service-properties>
<entry key="osgi.jndi.service.name" value="MainDB"/>
</service-properties>
</service>
Then we have a maven compiled bundle, with blueprint.xml initialization in the OSGI-INF.blueprint folder (resources), with this fragment:
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<blueprint xmlns="http://www.osgi.org/xmlns/blueprint/v1.0.0"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="
http://camel.apache.org/schema/blueprint
http://camel.apache.org/schema/blueprint/camel-blueprint-2.16.1.xsd
">
<bean id="ourlogicBean" class="oprg.unimportant.SomeClass">
<property name="dataSource" ref="dataSourceRef"/>
</bean>
<reference id="dataSourceRef" interface="javax.sql.DataSource" filter="(osgi.jndi.service.name=MainDB)"/>
</blueprint>
This is the exception we see in the ServiceMix logfiles:
2016-05-11 10:48:13,915 | ERROR | OURAPP/deploy | BlueprintContainerImpl | 15 - org.apache.aries.blueprint.core - 1.4.4 | Unable to start blueprint container for bundle our-package/1.0.0
org.osgi.service.blueprint.container.ComponentDefinitionException: Error setting property: PropertyDescriptor <name: dataSource, getter: null, setter: [class oprg.unimportant.SomeClass.setDataSource(interface javax.sql.DataSource)]
at org.apache.aries.blueprint.container.BeanRecipe.setProperty(BeanRecipe.java:939)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BeanRecipe.setProperties(BeanRecipe.java:905)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BeanRecipe.setProperties(BeanRecipe.java:886)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BeanRecipe.internalCreate2(BeanRecipe.java:820)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BeanRecipe.internalCreate(BeanRecipe.java:787)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.di.AbstractRecipe$1.call(AbstractRecipe.java:79)[15:org.apache.aries.blueprint.core:1.4.4]
at java.util.concurrent.FutureTask.run(FutureTask.java:262)[:1.7.0_79]
at org.apache.aries.blueprint.di.AbstractRecipe.create(AbstractRecipe.java:88)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BlueprintRepository.createInstances(BlueprintRepository.java:247)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BlueprintRepository.createAll(BlueprintRepository.java:183)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BlueprintContainerImpl.instantiateEagerComponents(BlueprintContainerImpl.java:682)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BlueprintContainerImpl.doRun(BlueprintContainerImpl.java:377)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BlueprintContainerImpl.run(BlueprintContainerImpl.java:269)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:294)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:263)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:253)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500)[9:org.apache.aries.util:1.1.1]
at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433)[9:org.apache.aries.util:1.1.1]
at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725)[9:org.apache.aries.util:1.1.1]
at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463)[9:org.apache.aries.util:1.1.1]
at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422)[9:org.apache.aries.util:1.1.1]
at org.apache.felix.framework.util.SecureAction.invokeBundleEventHook(SecureAction.java:1103)[org.apache.felix.framework-4.2.1.jar:]
at org.apache.felix.framework.util.EventDispatcher.createWhitelistFromHooks(EventDispatcher.java:695)[org.apache.felix.framework-4.2.1.jar:]
at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:483)[org.apache.felix.framework-4.2.1.jar:]
at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4403)[org.apache.felix.framework-4.2.1.jar:]
at org.apache.felix.framework.Felix.startBundle(Felix.java:2092)[org.apache.felix.framework-4.2.1.jar:]
at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:955)[org.apache.felix.framework-4.2.1.jar:]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1245)[7:org.apache.felix.fileinstall:3.5.0]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1217)[7:org.apache.felix.fileinstall:3.5.0]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:509)[7:org.apache.felix.fileinstall:3.5.0]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:358)[7:org.apache.felix.fileinstall:3.5.0]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:310)[7:org.apache.felix.fileinstall:3.5.0]
Caused by: oprg.unimportant.SystemException: Exception thrown in SomeClass.setDataSource
at oprg.unimportant.SomeClass.setDataSource(SomeClass.java:52)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.7.0_79]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)[:1.7.0_79]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.7.0_79]
at java.lang.reflect.Method.invoke(Method.java:606)[:1.7.0_79]
at org.apache.aries.blueprint.utils.ReflectionUtils$MethodPropertyDescriptor.internalSet(ReflectionUtils.java:630)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.utils.ReflectionUtils$PropertyDescriptor.set(ReflectionUtils.java:380)[15:org.apache.aries.blueprint.core:1.4.4]
at org.apache.aries.blueprint.container.BeanRecipe.setProperty(BeanRecipe.java:937)[15:org.apache.aries.blueprint.core:1.4.4]
... 31 more
Caused by: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: Cannot load JDBC driver class 'com.mysql.jdbc.Driver'
at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:575)[244:org.apache.servicemix.bundles.spring-jdbc:3.2.14.RELEASE_1]
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:639)[244:org.apache.servicemix.bundles.spring-jdbc:3.2.14.RELEASE_1]
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:668)[244:org.apache.servicemix.bundles.spring-jdbc:3.2.14.RELEASE_1]
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:676)[244:org.apache.servicemix.bundles.spring-jdbc:3.2.14.RELEASE_1]
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:716)[244:org.apache.servicemix.bundles.spring-jdbc:3.2.14.RELEASE_1]
at org.springframework.jdbc.core.JdbcTemplate.queryForList(JdbcTemplate.java:803)[244:org.apache.servicemix.bundles.spring-jdbc:3.2.14.RELEASE_1]
at oprg.unimportant.SomeClass.setDataSource(SomeClass.java:165)
... 40 more
Caused by: java.sql.SQLException: Cannot load JDBC driver class 'com.mysql.jdbc.Driver'
at org.apache.commons.dbcp2.BasicDataSource.createConnectionFactory(BasicDataSource.java:2138)
at org.apache.commons.dbcp2.managed.BasicManagedDataSource.createConnectionFactory(BasicManagedDataSource.java:138)
at org.apache.commons.dbcp2.BasicDataSource.createDataSource(BasicDataSource.java:2032)
at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
at Proxyee603976_5a24_4518_bfe5_33f1be6168ad.getConnection(Unknown Source)
at Proxy718290c5_58a3_421e_b083_26c576c0433e.getConnection(Unknown Source)
at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)[244:org.apache.servicemix.bundles.spring-jdbc:3.2.14.RELEASE_1]
at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)[244:org.apache.servicemix.bundles.spring-jdbc:3.2.14.RELEASE_1]
... 47 more
Caused by: java.lang.ClassNotFoundException: com.mysql.jdbc.Driver
at java.net.URLClassLoader$1.run(URLClassLoader.java:366)[:1.7.0_79]
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)[:1.7.0_79]
at java.security.AccessController.doPrivileged(Native Method)[:1.7.0_79]
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)[:1.7.0_79]
at java.lang.ClassLoader.loadClass(ClassLoader.java:425)[:1.7.0_79]
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308)[:1.7.0_79]
at java.lang.ClassLoader.loadClass(ClassLoader.java:358)[:1.7.0_79]
at org.apache.commons.dbcp2.BasicDataSource.createConnectionFactory(BasicDataSource.java:2129)
... 54 more
I have witnessed two cases when this problem occurs:
- When the method “setDataSource” in SomeClass does a call to the database;
- When the method “setDataSource” in SomeClass only registers the datasource value in a private backing field, but SomeClass is a (Camel) RouteBuilder and the DB is accessed from the configure() method;
I have set a breakpoint in case 1 above and the value received is non-null. This non-null value is probably the proxy class which is used for Reference Dynamism, which is used in the damping process.
What it looks like is that our bundle, which is running in thread A, receives a proxy to the Jdbc driver, and does a call to the database, while Jdbc initialization is done in thread B and threab B is not ready yet, so you're calling something without backing service. The damping process should block the bundle call to the DB, until the service is ready, so I'm probably doing something wrong in that area.
The issue above happens in several bundles, and act differently on different systems. So if you think you fixed it in one, then it reappears via another one. Unfortunately it is all very unpredictable.
What we already tried is:
- The bundle blueprint has a "<reference " to the DB connection, and I used a reference-listener - sometimes works, sometimes not;
- Added a dependency in "import-packages" in the pom.xml, on pool2, under the maven-bundle-plugin section, coincidently found this, I've seen good results but it does not work consistently;
- Everywhere when possible, used lazy-inits, this works 100% but cannot be applied for the Camel Routebuilder configure() method (I don't know when this is called);
- Used bundle priority to initialize the jndi.xml earlier in the startup process. As we have automated installation, I even install the jndi.xml very early, and before anything else in ServiceMix. Helps a bit.
Things I did not try are: - Move DB-stored configuration to local files - for this release unfeasible, for future an option; - Revert to Spring-DM. Better slow than troublesome. However this is also experimental to me, I've seen it (slow) working on my machine, maybe it has the same problems on other machines. Also I posted this issue on the ServiceMix forum (did not get an answer yet) and they 'strongly' advice not to revert to Spring-DM
I really don't understand why the bundle does not wait until the JDBC driver is initialized completely.
