Bug 1029076 - Temporary Topic Subscriptions are removed before the MDBs are closed, causing issues on clustering
Summary: Temporary Topic Subscriptions are removed before the MDBs are closed, causing...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: HornetQ, Quickstarts
Version: 6.2.0
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: CR2
: EAP 6.2.0
Assignee: Clebert Suconic
QA Contact: Jitka Kozana
Russell Dickenson
URL:
Whiteboard:
Depends On: 1030091
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-11-11 15:45 UTC by Jitka Kozana
Modified: 2013-12-15 16:20 UTC (History)
16 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-12-15 16:20:53 UTC
Type: Bug
Embargoed:
csuconic: needinfo-


Attachments (Terms of Use)
server log from the standalone server (88.09 KB, text/x-log)
2013-11-12 06:23 UTC, Jitka Kozana
no flags Details

Description Jitka Kozana 2013-11-11 15:45:42 UTC
EAP 6.2.0.ER7. When undeploying hornetq-clustering quickstart from domain, the following exception is thrown:

16:28:35,190 INFO  [org.jboss.as.process.Server:jdf-hornetqcluster-node2.status] (ProcessController-threads - 4) JBAS012018: Stopping process 'Server:jdf-hornetqcluster-node2'
[Server:jdf-hornetqcluster-node2] 16:28:35,195 ERROR [stderr] (main) java.lang.IllegalStateException
[Server:jdf-hornetqcluster-node2] 16:28:35,195 ERROR [stderr] (main) 	at org.jboss.as.server.mgmt.domain.HostControllerConnectionService.getValue(HostControllerConnectionService.java:143)
[Server:jdf-hornetqcluster-node2] 16:28:35,195 ERROR [stderr] (main) 	at org.jboss.as.server.mgmt.domain.HostControllerConnectionService.getValue(HostControllerConnectionService.java:63)
[Server:jdf-hornetqcluster-node2] 16:28:35,196 ERROR [stderr] (main) 	at org.jboss.msc.service.ServiceControllerImpl.getValue(ServiceControllerImpl.java:1203)
[Server:server-two] 16:28:35,196 ERROR [stderr] (main) java.lang.IllegalStateException
[Server:jdf-hornetqcluster-node2] 16:28:35,196 ERROR [stderr] (main) 	at org.jboss.as.server.DomainServerMain.getRequiredService(DomainServerMain.java:158)
[Server:jdf-hornetqcluster-node2] 16:28:35,196 ERROR [stderr] (main) 	at org.jboss.as.server.DomainServerMain.main(DomainServerMain.java:136)
[Server:jdf-hornetqcluster-node2] 16:28:35,196 ERROR [stderr] (main) 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[Server:server-two] 16:28:35,196 ERROR [stderr] (main) 	at org.jboss.as.server.mgmt.domain.HostControllerConnectionService.getValue(HostControllerConnectionService.java:143)
[Server:jdf-hornetqcluster-node2] 16:28:35,197 ERROR [stderr] (main) 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[Server:jdf-hornetqcluster-node2] 16:28:35,197 ERROR [stderr] (main) 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[Server:server-two] 16:28:35,197 ERROR [stderr] (main) 	at org.jboss.as.server.mgmt.domain.HostControllerConnectionService.getValue(HostControllerConnectionService.java:63)
[Server:jdf-hornetqcluster-node2] 16:28:35,197 ERROR [stderr] (main) 	at java.lang.reflect.Method.invoke(Method.java:601)
[Server:jdf-hornetqcluster-node2] 16:28:35,197 ERROR [stderr] (main) 	at org.jboss.modules.Module.run(Module.java:292)
[Server:jdf-hornetqcluster-node2] 16:28:35,197 ERROR [stderr] (main) 	at org.jboss.modules.Main.main(Main.java:455)
[Server:jdf-hornetqcluster-node2] 16:28:35,198 INFO  [org.jboss.as] (MSC service thread 1-4) JBAS015950: JBoss EAP 6.2.0.GA (AS 7.3.0.Final-redhat-10) stopped in 401ms
[Server:server-two] 16:28:35,197 ERROR [stderr] (main) 	at org.jboss.msc.service.ServiceControllerImpl.getValue(ServiceControllerImpl.java:1203)
[Server:server-two] 16:28:35,198 ERROR [stderr] (main) 	at org.jboss.as.server.DomainServerMain.getRequiredService(DomainServerMain.java:158)
[Server:server-two] 16:28:35,198 ERROR [stderr] (main) 	at org.jboss.as.server.DomainServerMain.main(DomainServerMain.java:136)
[Server:server-two] 16:28:35,198 ERROR [stderr] (main) 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[Server:server-two] 16:28:35,198 ERROR [stderr] (main) 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[Server:server-two] 16:28:35,199 ERROR [stderr] (main) 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[Server:server-two] 16:28:35,199 ERROR [stderr] (main) 	at java.lang.reflect.Method.invoke(Method.java:601)
[Server:server-two] 16:28:35,199 ERROR [stderr] (main) 	at org.jboss.modules.Module.run(Module.java:292)
[Server:server-two] 16:28:35,209 ERROR [stderr] (main) 	at org.jboss.modules.Main.main(Main.java:455)
[Server:jdf-hornetqcluster-node1] 


According to the README.md, no exception is expected. 

To reproduce this issue, simply follow the instructions in README.md in the hornetq-clustering quickstart.

Comment 1 sgilda 2013-11-11 16:58:29 UTC
Reassigning this one to the owner of the quickstart.

Comment 2 sgilda 2013-11-11 21:40:54 UTC
The script runs 'undeploy --server-groups=jdf-hornetq-clustering-group jboss-helloworld-mdb.war' to remove it from the specific server group. I also get the same errors 'HQ224037: cluster connection Failed to handle message: java.lang.IllegalStateException: Cannot find binding for 3680a1b5-bedf-44cd-80d5-c9c11e553e502a54be8c-4b15-11e3-bc53-65d19a3c428c'.

I also tried 'undeploy --all-relevant-server-groups jboss-helloworld-mdb.war' and got the same result.

It does successfully undeploy the quickstart though.

I think this is a server issue, not a quickstart issue.

Comment 3 sgilda 2013-11-11 23:07:29 UTC
Brian Stansberry checked in a few updates with this commit: 

https://github.com/jboss-developer/jboss-eap-quickstarts/commit/ce414a153d629b1e7c7df7d02359ca2c1a183b95

I'm not sure it fixes this issue though.

Comment 4 Jitka Kozana 2013-11-12 06:19:35 UTC
I have reproduced the issues with standalone mode too. See the attached server.log.

Comment 5 Jitka Kozana 2013-11-12 06:23:19 UTC
Created attachment 822769 [details]
server log from the standalone server

Comment 7 sgilda 2013-11-12 15:07:53 UTC
Restested this with Brian's updates. 

I also tried changing the undeploy domain script to 'undeploy --all-relevant-server-groups jboss-helloworld-mdb.war'. 

The server still shows the 'HQ224037: cluster connection Failed to handle message: java.lang.IllegalStateException: Cannot find binding for <binding-address>' errors, but the undeploy works in all cases.

Still researching this problem.

Comment 8 Miroslav Novak 2013-11-12 15:29:10 UTC
I did reproduce the situation in standalone profile. 

Undeploy of MDBs from 1st server also undeploys destinations HELLOWORLDMDBQueue and HELLOWORLDMDBTopic. (destinations are parts of the deployment)
2nd server gets notification CONSUMER_CLOSED and is calling ClusterConnectionImpl.doConsumerClosed where it tried to find RemoteQueueBinding in its "bindings" set and throws IllegalStateException.

Log:
15:53:24,062 ERROR [org.hornetq.core.server] (Thread-4 (HornetQ-client-global-threads-478652261)) HQ224037: cluster connection Failed to handle message: java.lang.IllegalStateException: Cannot find binding for 9fca38c9-876d-499e-91b1-58183ffcdd367c8470ee-4ba8-11e3-ac46-7d5f377d1774
	at org.hornetq.core.server.cluster.impl.ClusterConnectionImpl$MessageFlowRecordImpl.doConsumerClosed(ClusterConnectionImpl.java:1577) [hornetq-server-2.3.10.Final-redhat-1.jar:2.3.10.Final-redhat-1]
	at org.hornetq.core.server.cluster.impl.ClusterConnectionImpl$MessageFlowRecordImpl.onMessage(ClusterConnectionImpl.java:1295) [hornetq-server-2.3.10.Final-redhat-1.jar:2.3.10.Final-redhat-1]
	at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1117) [hornetq-core-client-2.3.10.Final-redhat-1.jar:2.3.10.Final-redhat-1]
	at org.hornetq.core.client.impl.ClientConsumerImpl.access$500(ClientConsumerImpl.java:57) [hornetq-core-client-2.3.10.Final-redhat-1.jar:2.3.10.Final-redhat-1]
	at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1252) [hornetq-core-client-2.3.10.Final-redhat-1.jar:2.3.10.Final-redhat-1]
	at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:107) [hornetq-core-client-2.3.10.Final-redhat-1.jar:2.3.10.Final-redhat-1]
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_35]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_35]
	at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_35]

Scenario:
1. Start 2 servers in HQ cluster
2. Deploy MDB which consumes messages from HELLOWORLDMDBQueue
3. Send some messages to HELLOWORLDMDBQueue
4. Undeploy MDB from 1st server

Result:
IllegalStateException appears in log of 2nd server.

@Andy @Justin
Can you or someone from dev to take a look, please? It's hornetq-clustering quickstart in [1]. Not sure if this is expected behavior. 

[1] http://download.eng.rdu2.redhat.com/devel/candidates/JBEAP/JBEAP-6.2.0.ER7/

Comment 9 Brian Stansberry 2013-11-12 18:37:30 UTC
There's no need to send any messages to the queue or undeploy.

This can be reproduced simply by running domain.sh and then executing the quickstart's install-domain.cli script. Then stop one of the servers; the logs are full of these messages.

Simplest way to stop servers is to shutdown the domain via Ctrl-C in the domain host's console. You'll see it.

You can also stop a single server via CLI

[domain@localhost:9999 /] /host=master/server-config=jdf-hornetqcluster-node1:stop

The script sets up a server group using the full-ha profile, starts a couple servers in it, and deploys a war with two MDBs in it. Very basic MDBs.

Comment 10 Clebert Suconic 2013-11-13 01:39:22 UTC
The MDB is non durably subscribing. At the time the shutdown happens several closes will happen from the several handlers what will issue subsequent removes on the other server.


I'm looking how we could mitigate this better...


As for the example... I believe there wouldn't be an issue if the subscription was durable. (what would make more sense actually with a subscription over clustering for a real case).


if that's true, maybe we could change the quickstart to use a durable subscription, and we could then open a minor issue with non durable subscriptions and clustering.

Comment 11 Clebert Suconic 2013-11-13 03:13:05 UTC
This is a minor issue, non regression....

However since this is showing up on the example, I will fix it...


We could change the topic subscription into durable and this error would go away. but since we will have a CR2 anyways a release won't be a big deal. if it is please let me know and we could change the example.


I will make the session holding the temp queue to be the last one to be closed and this will go away. I have already tested.. will release tomorrow.

Comment 12 Clebert Suconic 2013-11-13 03:14:23 UTC
The issue is that the temp queue is being deleted before the closes.. what's raising the warnings on the clustering. No other issues beyond the warns.

Comment 13 sgilda 2013-11-13 13:02:13 UTC
Clebert, I had assumed you meant adding the following to the HelloWorldQueueMDB and HelloWorldTopicMDB?

@ActivationConfigProperty(propertyName = "subscriptionDurability", propertyValue = "Durable") })

But I tried that and see these errors on the server when it deploys helloworld-mdb:

HQ221034: Waiting to obtain live lock
HQ221035: Live Server Obtained live lock
ERROR [org.hornetq.ra] (default-threads - 2) HQ154003: Unable to reconnect org.hornetq.ra.inflow.HornetQActivationSpec(ra=org.hornetq.ra.HornetQResourceAdapter@da459c8 destination=topic/HELLOWORLDMDBTopic destinationType=javax.jms.Topic ack=Auto-acknowledge durable=true clientID=null user=null maxSession=15): javax.jms.InvalidClientIDException: Cannot create durable subscription for null - client ID has not been set

Then later:

JBAS018210: Register web context: /jboss-helloworld-mdb
[Server:jdf-hornetqcluster-node2] 07:47:48,382 WARN  [org.hornetq.ra] (default-threads - 2) HQ152005: Failure in HornetQ activation org.hornetq.ra.inflow.HornetQActivationSpec(ra=org.hornetq.ra.HornetQResourceAdapter@6cda46b6 destination=topic/HELLOWORLDMDBTopic destinationType=javax.jms.Topic ack=Auto-acknowledge durable=true clientID=null user=null maxSession=15): javax.jms.InvalidClientIDException: Cannot create durable subscription for null - client ID has not been set
[Server:jdf-hornetqcluster-node2] 	at org.hornetq.ra.inflow.HornetQMessageHandler.setup(HornetQMessageHandler.java:111) [hornetq-ra-2.3.9.Final-redhat-1.jar:2.3.9.Final-redhat-1]

Then later after the server start in the script:

JBAS018559: Deployed "jboss-helloworld-mdb.war" (runtime-name : "jboss-helloworld-mdb.war")
[Server:jdf-hornetqcluster-node2] 07:47:48,488 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss EAP 6.2.0.GA (AS 7.3.0.Final-redhat-9) started in 5021ms - Started 213 of 341 services (127 services are passive or on-demand)
[Server:jdf-hornetqcluster-node1] 07:47:49,583 ERROR [org.hornetq.ra] (default-threads - 2) HQ154003: Unable to reconnect org.hornetq.ra.inflow.HornetQActivationSpec(ra=org.hornetq.ra.HornetQResourceAdapter@da459c8 destination=topic/HELLOWORLDMDBTopic destinationType=javax.jms.Topic ack=Auto-acknowledge durable=true clientID=null user=null maxSession=15): javax.jms.InvalidClientIDException: Cannot create durable subscription for null - client ID has not been set
[Server:jdf-hornetqcluster-node1] 	at org.hornetq.ra.inflow.HornetQMessageHandler.setup(HornetQMessageHandler.java:111) [hornetq-ra-2.3.9.Final-redhat-1.jar:2.3.9.Final-redhat-1]
[Server:jdf-hornetqcluster-node1] 	at org.hornetq.ra.inflow.HornetQActivation.setup(HornetQActivation.java:336) [hornetq-ra-2.3.9.Final-redhat-1.jar:2.3.9.Final-redhat-1]
[Server:jdf-hornetqcluster-node1] 	at org.hornetq.ra.inflow.HornetQActivation.handleFailure(HornetQActivation.java:691) [hornetq-ra-2.3.9.Final-redhat-1.jar:2.3.9.Final-redhat-1]
[Server:jdf-hornetqcluster-node1] 	at org.hornetq.ra.inflow.HornetQActivation$SetupActivation.run(HornetQActivation.java:746) [hornetq-ra-2.3.9.Final-redhat-1.jar:2.3.9.Final-redhat-1]
[Server:jdf-hornetqcluster-node1] 	at org.jboss.jca.core.workmanager.WorkWrapper.run(WorkWrapper.java:218)
[Server:jdf-hornetqcluster-node1] 	at org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33)
[Server:jdf-hornetqcluster-node1] 	at org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:808)
[Server:jdf-hornetqcluster-node1] 	at org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)
[Server:jdf-hornetqcluster-node1] 	at org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:828)
[Server:jdf-hornetqcluster-node1] 	at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_09]
[Server:jdf-hornetqcluster-node1] 	at org.jboss.threads.JBossThread.run(JBossThread.java:122)

Comment 14 Clebert Suconic 2013-11-13 14:07:40 UTC
you need to set clientID before you can set durable...


But no need to change that.. I have a fix already and I will make a release today.. I already tested here with my dev branch and these errors went away.


I can give you instructions to do the same test if you like.

Comment 15 Jitka Kozana 2013-11-26 08:51:18 UTC
I have verified the issue is no longer present in EAP 6.2.0.CR3 quickstarts. When following the instructions in README.md, no errors are logged.

But when the user shuts the domain down before the application is undeployed, other errors were seen in log. Because these errors are not seen when user follows the instructions, I am closing this BZ as VERIFIED. A new BZ#1034619 was opened to track these errors.


Note You need to log in before you can comment on or make changes to this bug.