Resource adapter JMS lookups failing

[jewellgm]

Hello,

I'm porting our application to WildFly 9, and am currently using the CR1 release.  Our application has several resource adapters, and many of those RAs have a dependency on JMS.  It looks like, on faster computers, our resource adapters are being deployed before the JMS connection factories are deployed.  As a result, the lookups for the connection factories are failing.  Is there a way to make those resource adapters deploy after the JMS configuration is deployed?  I see how to create dependencies on other ears through the jboss-all.xml configuration, but I don't know how to do something similar for a pre-requisite that is configured with standalone.xml.

Thanks,

Greg Jewell

[jbertram]

I can't answer your specific question, but I'm curious about your use-case.  Wildfly ships with a JCA resource adapter for the JMS implementation (i.e. HornetQ).  Does that not suit your needs?

[jewellgm]

Justin,

Our resource adapters are being used to communicate to other external systems through a variety of methods.  We're not intending to write our own JMS adapter.  What we're doing, perhaps incorrectly, is using our resource adapter to drop messages on the JMS bus that are received from these external systems.  We're trying to look up the HornetQ InVM connection factory by manually doing JNDI lookups (rather than resource injection).  It appears that our resource adapters are being deployed prior to the JMS adapter provided by WildFly, thereby causing the issue we're seeing.

Thanks again!

[jbertram]

I believe if you actually used resource injection then the dependencies would be set up for you implicitly.

Aside from that I see a few options:

• Avoid JNDI altogether and use the HornetQ core API to programmatically construct the connection factory you need.  This isn't terribly robust because once the connection factory is created it may get used before HornetQ is fully initialized in which case you've simply moved the same problem to a different place.
• Retry the JNDI look-up with a timeout.  This solution lacks elegance, but would almost certainly be effective.
• Change your JCA RA to simply receive the messages from the external system(s) and then you can have an MDB handle those message appropriately (either by putting them on JMS queue or handling them directly without the JMS queue intermediary).

[jewellgm]

Thank you for the suggestions -- I'll refactor some of the code using these ideas to see whether the issues start going away.

[jewellgm]

I tried injecting the connection factory instances by using @Resource(lookup = "ConnectionFactory"), but was getting NullPointerException because the injection apparently failed.  I refactored the code so that the resource adapters don't try to establish the JMS connection immediately on start, but only after we receive the first messages from the external systems, and that seems to help.  Of course, this reverts to the old way of doing manual JNDI lookups.

Now I'm having another problem, though.  We've got many MDBs that are configured through the @MessageDriven annotation.  If I try to deploy the ears simultaneously, I get all kinds of exceptions in the log like this:

[org.hornetq.ra] (default-threads - 6) HQ152005: Failure in HornetQ activation org.hornetq.ra.inflow.HornetQActivationSpec(ra=org.hornetq.ra.HornetQResourceAdapter@219507b2 connectionFactoryLookup=null destination=topic/UpdateTopic destinationType=javax.jms.Topic ack=Auto-acknowledge durable=false clientID=null user=null maxSession=15): java.lang.NullPointerException

    at org.hornetq.ra.inflow.HornetQActivation.getAddress(HornetQActivation.java:598) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQMessageHandler.setup(HornetQMessageHandler.java:165) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQActivation.setup(HornetQActivation.java:340) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQActivation$SetupActivation.run(HornetQActivation.java:819) [hornetq-ra-2.4.7.Final.jar:]

    at org.jboss.jca.core.workmanager.WorkWrapper.run(WorkWrapper.java:226)

    at org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33)

    at org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:808)

    at org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)

    at org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:828)

    at java.lang.Thread.run(Unknown Source) [rt.jar:1.8.0_45]

    at org.jboss.threads.JBossThread.run(JBossThread.java:320)

If I put .skipdeploy files in the deployment directory for all of the ears, and then delete a few at a time after WildFly is started, I don't get these exceptions.

So, a couple of questions:

1.  Is lookup = "ConnectionFactory" correct for the @Resource annotation?  That's the JNDI name that's being used for the manual lookups and it's working as desired.  Again, I'm just using the InVM connection factory, but adding our own topics to standalone.xml.

2.  Why are MDBs failing to start when multiple ears are being deployed simultaneously?

It seems like there are a lot of JMS failures when several ears are started simultaneously.  I can get things to work by slowly deploying them, a few at a time.

[jbertram]

If your using the connection factory to send messages and not consume them then I would recommend using the JmsXA connection factory.

I'm not sure why you're getting the NPEs when deploying.  Could you try using the latest stable release of Wildfly 8?

[jewellgm]

Running against WildFly 8.2.0, everything appears to deploy properly.  Unfortunately, using this version of WildFly doesn't seem to be viable.  There are issues with web services and basic authentication that prevent its usage.  I had another thread for that issue, but was never able to get it resolved.  Once I moved to WildFly 9, the issue went away.

Web service clients always get "403 Forbidden"

[jaikiran]

For the NPE from the HornetQ RA, enable TRACE level logging in the logging subsystem for the org.hornetq.ra package and see what it shows.

[jewellgm]

I'm not seeing anything obvious in the trace-level logs.  There aren't any error messages, just indications of what methods are being called.  Here's a snippet from before and after an exception:

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) getClientID()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) getClientID()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) getClientID()

2015-06-02 08:23:35,284 DEBUG [org.hornetq.ra] (default-threads - 7) Using queue connection DelegatingSession [session=ClientSessionImpl [name=308c09a9-0922-11e5-b6da-03a9da191153, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=304e16ee-0922-11e5-b6da-03a9da191153, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=308c09a4-0922-11e5-b6da-03a9da191153, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=(jms-session=,resource-adapter=inbound,)]@4ed831ef]

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) setup()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) getActivationSpec()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) getMessageSelector()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) isTopic()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) isSubscriptionDurable()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) isTopic()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) getMaxSession()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getMaxSession()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) hashCode()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) getAcknowledgeMode()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 7) getClientID()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getAcknowledgeMode()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getUser()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getUserName()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getUserName()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getPassword()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getPassword()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getPassword()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getPreAcknowledge()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) isPreAcknowledge()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getDupsOKBatchSize()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getDupsOKBatchSize()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getTransactionBatchSize()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getTransactionBatchSize()

2015-06-02 08:23:35,284 WARN  [org.hornetq.ra] (default-threads - 7) HQ152005: Failure in HornetQ activation org.hornetq.ra.inflow.HornetQActivationSpec(ra=org.hornetq.ra.HornetQResourceAdapter@54b9282 connectionFactoryLookup=null destination=topic/UpdateTopic destinationType=javax.jms.Topic ack=Auto-acknowledge durable=false clientID=null user=null maxSession=15): java.lang.NullPointerException

    at org.hornetq.ra.inflow.HornetQActivation.getAddress(HornetQActivation.java:598) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQMessageHandler.setup(HornetQMessageHandler.java:165) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQActivation.setup(HornetQActivation.java:340) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQActivation$SetupActivation.run(HornetQActivation.java:819) [hornetq-ra-2.4.7.Final.jar:]

    at org.jboss.jca.core.workmanager.WorkWrapper.run(WorkWrapper.java:226)

    at org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33)

    at org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:808)

    at org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)

    at org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:828)

    at java.lang.Thread.run(Unknown Source) [rt.jar:1.8.0_45]

    at org.jboss.threads.JBossThread.run(JBossThread.java:320)

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getUseLocalTx()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getUseLocalTx()

2015-06-02 08:23:35,284 TRACE [org.hornetq.ra] (default-threads - 6) getTransactionTimeout()

2015-06-02 08:23:35,284 DEBUG [org.hornetq.ra] (default-threads - 6) Using queue connection DelegatingSession [session=ClientSessionImpl [name=308e539d-0922-11e5-b6da-03a9da191153, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=304e16ee-0922-11e5-b6da-03a9da191153, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=304e16ee-0922-11e5-b6da-03a9da191153, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=()]@163d4021]

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) getClientID()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) getClientID()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) getClientID()

2015-06-02 08:23:35,300 DEBUG [org.hornetq.ra] (default-threads - 6) Using queue connection DelegatingSession [session=ClientSessionImpl [name=308e539d-0922-11e5-b6da-03a9da191153, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=304e16ee-0922-11e5-b6da-03a9da191153, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=304e16ee-0922-11e5-b6da-03a9da191153, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=(jms-session=,resource-adapter=inbound,)]@163d4021]

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) setup()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) getActivationSpec()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) getMessageSelector()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) isTopic()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) isSubscriptionDurable()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) isTopic()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) getMaxSession()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) hashCode()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) getAcknowledgeMode()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 6) getClientID()

2015-06-02 08:23:35,300 WARN  [org.hornetq.ra] (default-threads - 6) HQ152005: Failure in HornetQ activation org.hornetq.ra.inflow.HornetQActivationSpec(ra=org.hornetq.ra.HornetQResourceAdapter@54b9282 destination=topic/UpdateTopic destinationType=javax.jms.Topic ack=Auto-acknowledge durable=false clientID=null user=null maxSession=15): java.lang.NullPointerException

    at org.hornetq.ra.inflow.HornetQActivation.getAddress(HornetQActivation.java:598) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQMessageHandler.setup(HornetQMessageHandler.java:165) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQActivation.setup(HornetQActivation.java:340) [hornetq-ra-2.4.7.Final.jar:]

    at org.hornetq.ra.inflow.HornetQActivation$SetupActivation.run(HornetQActivation.java:819) [hornetq-ra-2.4.7.Final.jar:]

    at org.jboss.jca.core.workmanager.WorkWrapper.run(WorkWrapper.java:226)

    at org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33)

    at org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:808)

    at org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)

    at org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:828)

    at java.lang.Thread.run(Unknown Source) [rt.jar:1.8.0_45]

    at org.jboss.threads.JBossThread.run(JBossThread.java:320)

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 7) getSetupAttempts()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 7) getSetupAttempts()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 7) getSetupInterval()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 7) getSetupInterval()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 7) hashCode()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 7) getAcknowledgeMode()

2015-06-02 08:23:35,300 TRACE [org.hornetq.ra] (default-threads - 7) getClientID()

2015-06-02 08:23:35,300 DEBUG [org.hornetq.ra] (default-threads - 7) Tearing down org.hornetq.ra.inflow.HornetQActivationSpec(ra=org.hornetq.ra.HornetQResourceAdapter@54b9282 connectionFactoryLookup=null destination=topic/UpdateTopic destinationType=javax.jms.Topic ack=Auto-acknowledge durable=false clientID=null user=null maxSession=15)

2015-06-02 08:23:35,315 TRACE [org.hornetq.ra] (default-threads - 7) getDestination()

2015-06-02 08:23:35,315 TRACE [org.hornetq.ra] (default-threads - 7) getDestination()

2015-06-02 08:23:35,315 DEBUG [org.hornetq.ra] (default-threads - 7) Tearing down complete org.hornetq.ra.inflow.HornetQActivation(spec=org.hornetq.ra.inflow.HornetQActivationSpec mepf=org.jboss.as.ejb3.inflow.JBossMessageEndpointFactory active=true destination=topic/UpdateTopic transacted=true)

[jesper.pedersen]

Maybe related to

https://github.com/hornetq/hornetq/blob/master/hornetq-ra/src/main/java/org/hornetq/ra/inflow/HornetQActivation.java#L265

since the Work is just scheduled, and may not have been executed yet. Justin can dig through it

[jbertram]

I'm not sure how scheduling the work here would lead to this particular NPE.  JCA resource adapters for JMS in JBoss AS have done it this way for time out of mind.

Greg, could you provide a test-case which reproduces this problem?  I have in mind something really simple with little or no dependencies that I can easily use to see the behavior you're seeing.

[jewellgm]

I'm trying to reproduce this, but I'm not having much luck yet.  I don't know if it's even possible to have a simple scenario to reproduce this -- this issue may only arise in cases where many ears that are deploying many things simultaneously.  As I said, if I deploy a few ears at a time it works.  It's only when I try to deploy several ears at once when these failures start happening.

[jbertram]

As simple as possible is what I'm looking for.  If it works when 5 ears but fails with 6 then reproduce it with 6 ears (or whatever).

[jewellgm]

Right now I've got some test code that has two different MDBs, and the MDBs are being deployed in 10 different ear files.  With this configuration, I'm not able to reproduce the failure.  I don't think the issue is caused by the presence of a resource adapter, but I'll give that a try.  I'm not convinced that this is something that I'll be able to reproduce easily -- I don't know what's triggering the problem to begin with.  I'll keep trying, but I'm not very optimistic about artificially reproducing the problem.