We have a problem migrating an application (packaged as a J2EE ear) using hibernatesearch from JBoss 6.0 final to JBoss 6.1 final.
We are using hibernate search 3.4.1 final and JMS as the backend to lucene - here is the persistence unit:
Code:
<?xml version="1.0" encoding="UTF-8"?>
<!-- Persistence deployment descriptor for dev profile -->
<persistence version="2.0"
xmlns="http://java.sun.com/xml/ns/persistence" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd">
<persistence-unit name="myupPersistenceUnit">
<provider>org.hibernate.ejb.HibernatePersistence</provider>
<jta-data-source>java:/myupDatasource</jta-data-source>
<properties>
<property name="hibernate.cache.use_second_level_cache" value="false"/>
<property name="hibernate.archive.autodetection" value="class"/>
<property name="hibernate.ejb.interceptor" value="up.hibernate.IndexInterceptor" />
<property name="hibernate.dialect" value="up.hibernate.MyUPMySQL5InnoDBDialect" />
<property name="hibernate.transaction.manager_lookup_class" value="org.hibernate.transaction.JBossTransactionManagerLookup"/>
<property name="hibernate.hbm2ddl.auto" value="validate" />
<property name="hibernate.ejb.naming_strategy" value="up.hibernate.NamingStrategy" />
<!-- Run the Hibernate bytecode instrumentation at deployment time, for lazy loading of @ToOne and byte[] properties -->
<property name="hibernate.ejb.use_class_enhancer" value="true"/>
<property name="hibernate.max_fetch_depth" value="1" />
<property name="hibernate.jdbc.batch_size" value="64" />
<!-- HIBERNATE SEARCH-->
<!-- passive slave directory provider that alternates between two slave copies for searches -->
<property name="hibernate.search.default.directory_provider" value="infinispan" />
<!-- infinispan configuration file -->
<property name="hibernate.search.infinispan.cachemanager_jndiname" value="java:infinispan/myup-hibernatesearch"/>
<!-- infinispan chunk size: 32MB -->
<property name="hibernate.search.default.chunk_size" value="33554432"/>
<!-- directory where the indexes will be copied by master and read by passive slave -->
<property name="hibernate.search.default.sourceBase" value="/var/lib/lucene/indexes_slave"/>
<!-- default analyzer -->
<property name="hibernate.search.analyzer" value="up.lucene.UpAnalyzer" />
<!-- cache configuration -->
<property name="hibernate.cache.provider_class" value="org.hibernate.cache.EhCacheProvider" />
<property name="hibernate.cache.use_query_cache" value="true" />
<property name="hibernate.search.worker.backend" value="jms" />
<property name="hibernate.search.worker.jms.connection_factory" value="/ConnectionFactory" />
<property name="hibernate.search.worker.jms.queue" value="queue/hibernatesearch" />
<property name="hibernate.cache.region_prefix" value=""/>
</properties>
</persistence-unit>
</persistence>
These are excerpts for the log:
Code:
17:03:45,645 INFO [HornetQServerImpl] Server is now live
17:03:45,646 INFO [HornetQServerImpl] HornetQ Server version 2.2.5.Final (HQ_2_2_5_FINAL_AS7, 121) [a846291f-0f61-11e1-a002-68b599e97598] started
...
17:04:15,309 ERROR [AbstractKernelController] Error installing to Start: name=persistence.unit:unitName=myup-ear-1.11.1-SNAPSHOT.ear/myup-model-1.11.1-SNAPSHOT.jar#myupPersistenceUnit state=Create: javax.persistence.PersistenceException: [PersistenceUnit: myupPersistenceUnit] Unable to build EntityManagerFactory
at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:915) [:3.6.6.Final]
at org.hibernate.ejb.HibernatePersistence.createContainerEntityManagerFactory(HibernatePersistence.java:74) [:3.6.6.Final]
at org.jboss.jpa.builder.DefaultCEMFBuilder.build(DefaultCEMFBuilder.java:47) [:1.0.2-alpha-4]
at org.jboss.as.jpa.scanner.HackCEMFBuilder.build(HackCEMFBuilder.java:49) [:6.1.0.Final]
at org.jboss.jpa.deployment.PersistenceUnitDeployment.start(PersistenceUnitDeployment.java:275) [:1.0.2-alpha-4]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [:1.6.0_24]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [:1.6.0_24]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [:1.6.0_24]
at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_24]
at org.jboss.reflect.plugins.introspection.ReflectionUtils.invoke(ReflectionUtils.java:60) [jboss-reflect.jar:2.2.1.SP1]
at org.jboss.reflect.plugins.introspection.ReflectMethodInfoImpl.invoke(ReflectMethodInfoImpl.java:168) [jboss-reflect.jar:2.2.1.SP1]
at org.jboss.joinpoint.plugins.BasicMethodJoinPoint.dispatch(BasicMethodJoinPoint.java:66) [jboss-reflect.jar:2.2.1.SP1]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction$JoinpointDispatchWrapper.execute(KernelControllerContextAction.java:257) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.kernel.plugins.dependency.ExecutionWrapper.execute(ExecutionWrapper.java:47) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchExecutionWrapper(KernelControllerContextAction.java:125) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchJoinPoint(KernelControllerContextAction.java:72) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.kernel.plugins.dependency.LifecycleAction.installActionInternal(LifecycleAction.java:202) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:54) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:42) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:379) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:2044) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:1083) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.executeOrIncrementStateDirectly(AbstractController.java:1322) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1246) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1139) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:894) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:641) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer.deploy(BeanMetaDataDeployer.java:182) [:2.2.2.GA]
at org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer.deploy(BeanMetaDataDeployer.java:58) [:2.2.2.GA]
at org.jboss.deployers.spi.deployer.helpers.AbstractSimpleRealDeployer.internalDeploy(AbstractSimpleRealDeployer.java:63) [:2.2.2.GA]
at org.jboss.deployers.spi.deployer.helpers.AbstractRealDeployer.deploy(AbstractRealDeployer.java:55) [:2.2.2.GA]
at org.jboss.deployers.plugins.deployers.DeployerWrapper.deploy(DeployerWrapper.java:179) [:2.2.2.GA]
at org.jboss.deployers.plugins.deployers.DeployersImpl.doDeploy(DeployersImpl.java:1832) [:2.2.2.GA]
at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1550) [:2.2.2.GA]
at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1571) [:2.2.2.GA]
at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1603) [:2.2.2.GA]
at org.jboss.deployers.plugins.deployers.DeployersImpl.install(DeployersImpl.java:1491) [:2.2.2.GA]
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:379) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:2044) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:1083) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.executeOrIncrementStateDirectly(AbstractController.java:1322) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1246) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1139) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:939) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:654) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:1983) [:2.2.2.GA]
at org.jboss.deployers.plugins.deployers.DeployersImpl.process(DeployersImpl.java:1076) [:2.2.2.GA]
at org.jboss.deployers.plugins.main.MainDeployerImpl.process(MainDeployerImpl.java:679) [:2.2.2.GA]
at org.jboss.system.server.profileservice.deployers.MainDeployerPlugin.process(MainDeployerPlugin.java:106) [:6.1.0.Final]
at org.jboss.profileservice.dependency.ProfileControllerContext$DelegateDeployer.process(ProfileControllerContext.java:143) [:0.2.2]
at org.jboss.profileservice.dependency.ProfileDeployAction.deploy(ProfileDeployAction.java:151) [:0.2.2]
at org.jboss.profileservice.dependency.ProfileDeployAction.installActionInternal(ProfileDeployAction.java:94) [:0.2.2]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:54) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:42) [jboss-kernel.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:379) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:2044) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:1083) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.executeOrIncrementStateDirectly(AbstractController.java:1322) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1246) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1139) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:939) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:654) [jboss-dependency.jar:2.2.0.SP2]
at org.jboss.profileservice.dependency.ProfileActivationWrapper$BasicProfileActivation.start(ProfileActivationWrapper.java:190) [:0.2.2]
at org.jboss.profileservice.dependency.ProfileActivationWrapper.start(ProfileActivationWrapper.java:87) [:0.2.2]
at org.jboss.profileservice.dependency.ProfileActivationService.activateProfile(ProfileActivationService.java:215) [:0.2.2]
at org.jboss.profileservice.dependency.ProfileActivationService.activate(ProfileActivationService.java:159) [:0.2.2]
at org.jboss.profileservice.bootstrap.AbstractProfileServiceBootstrap.activate(AbstractProfileServiceBootstrap.java:112) [:0.2.2]
at org.jboss.profileservice.resolver.BasicResolverFactory$ProfileResolverFacade.deploy(BasicResolverFactory.java:87) [:0.2.2]
at org.jboss.profileservice.bootstrap.AbstractProfileServiceBootstrap.start(AbstractProfileServiceBootstrap.java:91) [:0.2.2]
at org.jboss.system.server.profileservice.bootstrap.BasicProfileServiceBootstrap.start(BasicProfileServiceBootstrap.java:132) [:6.1.0.Final]
at org.jboss.system.server.profileservice.bootstrap.BasicProfileServiceBootstrap.start(BasicProfileServiceBootstrap.java:56) [:6.1.0.Final]
at org.jboss.bootstrap.impl.base.server.AbstractServer.startBootstraps(AbstractServer.java:827) [jboss-bootstrap-impl-base.jar:2.1.0-alpha-6]
at org.jboss.bootstrap.impl.base.server.AbstractServer$StartServerTask.run(AbstractServer.java:417) [jboss-bootstrap-impl-base.jar:2.1.0-alpha-6]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_24]
Caused by: org.hibernate.HibernateException: could not init listeners
at org.hibernate.event.EventListeners.initializeListeners(EventListeners.java:205) [:3.6.6.Final]
at org.hibernate.cfg.Configuration.getInitializedEventListeners(Configuration.java:2010) [:3.6.6.Final]
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1872) [:3.6.6.Final]
at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:906) [:3.6.6.Final]
... 79 more
Caused by: org.hibernate.search.SearchException: Unable to lookup Search queue (queue/hibernatesearch) and connection factory (/ConnectionFactory)
at org.hibernate.search.backend.impl.jms.JMSBackendQueueProcessorFactory.prepareJMSTools(JMSBackendQueueProcessorFactory.java:97) [:3.4.1.Final]
at org.hibernate.search.backend.impl.jms.JMSBackendQueueProcessorFactory.initialize(JMSBackendQueueProcessorFactory.java:61) [:3.4.1.Final]
at org.hibernate.search.backend.impl.BatchedQueueingProcessor.<init>(BatchedQueueingProcessor.java:108) [:3.4.1.Final]
at org.hibernate.search.backend.impl.TransactionalWorker.initialize(TransactionalWorker.java:98) [:3.4.1.Final]
at org.hibernate.search.backend.WorkerFactory.createWorker(WorkerFactory.java:69) [:3.4.1.Final]
at org.hibernate.search.spi.SearchFactoryBuilder.buildNewSearchFactory(SearchFactoryBuilder.java:277) [:3.4.1.Final]
at org.hibernate.search.spi.SearchFactoryBuilder.buildSearchFactory(SearchFactoryBuilder.java:144) [:3.4.1.Final]
at org.hibernate.search.event.FullTextIndexEventListener.initialize(FullTextIndexEventListener.java:151) [:3.4.1.Final]
at org.hibernate.event.EventListeners$1.processListener(EventListeners.java:198) [:3.6.6.Final]
at org.hibernate.event.EventListeners.processListeners(EventListeners.java:181) [:3.6.6.Final]
at org.hibernate.event.EventListeners.initializeListeners(EventListeners.java:194) [:3.6.6.Final]
... 82 more
Caused by: javax.naming.NameNotFoundException: ConnectionFactory not bound
at org.jnp.server.NamingServer.getBinding(NamingServer.java:771) [:5.0.5.Final]
at org.jnp.server.NamingServer.getBinding(NamingServer.java:779) [:5.0.5.Final]
at org.jnp.server.NamingServer.getObject(NamingServer.java:785) [:5.0.5.Final]
at org.jnp.server.NamingServer.lookup(NamingServer.java:443) [:5.0.5.Final]
at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:728) [:5.0.5.Final]
at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:688) [:5.0.5.Final]
at javax.naming.InitialContext.lookup(InitialContext.java:392) [:1.6.0_24]
at org.hibernate.search.backend.impl.jms.JMSBackendQueueProcessorFactory.prepareJMSTools(JMSBackendQueueProcessorFactory.java:92) [:3.4.1.Final]
... 92 more
This is the line where the failure occurs.
Code:
factory = ( QueueConnectionFactory ) initialContext.lookup( jmsConnectionFactoryName );
If we start JBoss without the ear, and then deploy it, everything is fine (since the queue is already there and it is resolved by JNDI).
After quite a bit of investigation we have come to the conclusion that the problem is that the JMS ConnectionFactories and Destinations are not deployed before HibernateSearch attempts to look them up using JNDI.
I suppose that in JBoss 6.0 the Destinations were available at the time the persistence unit was deployed.
From the log file, we can see that the HornetQ server (corresponding to the jboss-6.1.0.Final/server/default/deploy/hornetq/hornet-configuration.xml) is started before the exception but JMS connection factories and Queues, defined outside the ear (in jboss-6.1.0.Final/server/default/deploy/hornetq/hornetq-jms.xml) are not yet deployed.
We have tried a number of workarounds, e.g. trying to make a dependencies to the queue from beans in the ear file.
Unfortunatlely this Persistence Unit is part of a jar which needs to be deployed first.
So I can think of some possible solutions:
1. Find a way to force deployment of all JMS destinations before deploying the ear (anyone suggestions on how would be appreciated).
2. Lazily lookup the queue/connection factory when it is first used in JMSBackendQueueProcessorFactory (this requires a patch to hibernate search) looking at the code this should be relatively easy: remove the call to prepareJMSTools() in the constructor (although we would also need to take care of a race condition in setting the queue/connectionfactory).
3. Use a different custom InitialContextFactory which delegates to the real Context but returns null for these (essentially giving lazy loading but with the same potential thread safety issues). The code below can do this but it is a bit of a hack and I'd prefere not to have to use it.
So are we seeing a real problem or have I missed something. If you think it should be fixed with a change to JMSBackendQueueProcessorFactory I can send a patch.
Code:
<property name="hibernate.search.worker.jndi.class" value="up.util.HibernateSearchInitialContextFactory"/>
Code:
public class HibernateSearchInitialContextFactory implements InitialContextFactory {
private static final Logger logger = LoggerFactory.getLogger(HibernateSearchInitialContextFactory.class);
@Override
public Context getInitialContext(final Hashtable<?, ?> environment) throws NamingException {
final InvocationHandler invocationHandler = new InvocationHandler() {
InitialContext initialContext = new InitialContext();
@Override
public Object invoke(final Object proxy, final Method method, final Object[] args) throws Throwable {
Object result;
try {
result = method.invoke(initialContext, args);
} catch (InvocationTargetException e) {
logger.warn("Returning null for JNDI lookup " + (args.length == 1 ? args[0] : null));
return null;
} catch (Exception e) {
throw new RuntimeException("unexpected invocation exception", e);
}
return result;
}
};
final Context proxy = (Context) Proxy.newProxyInstance(InitialContext.class.getClassLoader(),
InitialContext.class.getInterfaces(), invocationHandler);
return proxy;
}
}