Mailing-List: contact users-help@activemq.apache.org; run by ezmlm
Precedence: bulk
Reply-To: users@activemq.apache.org
Received-SPF: unknown (nike.apache.org: error in processing during lookup of
 stephen.vincent@sas.com)
Date: Mon, 4 Feb 2013 10:27:45 -0800 (PST)
From: "Steve.V." <stephen.vincent@sas.com>
To: users@activemq.apache.org
Message-ID: <1360002465855-4662738.post@n4.nabble.com>
Subject: Async client...IllegalStateException: REDISPATCHING,initial,resumed
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Transfer-Encoding: 7bit

Running release 5.7.0.

I have some REST API client tests that run fine most of the time.  However,
we have a few tests that fail roughly 10% of the time when run against a
server running on UNIX.   The following are excerpts from the log.  I see a
bunch of these:
-----------
2013-02-04 13:02:50,853 | DEBUG | Async client internal exception occurred
with no exception listener registered: java.lang.IllegalStateException:
REDISPATCHING,initial,resumed |
 org.apache.activemq.ActiveMQConnection | ActiveMQ Session Task-1
java.lang.IllegalStateException: REDISPATCHING,initial,resumed
        at
org.eclipse.jetty.server.AsyncContinuation.dispatch(AsyncContinuation.java:408)
        at
org.eclipse.jetty.server.AsyncContinuation.resume(AsyncContinuation.java:815)
        at
org.apache.activemq.web.MessageServlet$Listener.onMessageAvailable(MessageServlet.java:409)
        at
org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1343)
        at
org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131)
        at
org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202)
        at
org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:129)
        at
org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:47)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
-----------

followed by:
-----------
2013-02-04 13:02:50,833 | DEBUG | Received 0 message(s) |
org.apache.activemq.web.MessageServlet | qtp13043068-36 -
/demo/message?destination=testq&type=queue&clientId=16F53C00-6
EF5-11E2-81B4-0E72C1E2DF3C&readTimeout=1
2013-02-04 13:02:50,829 | DEBUG | default:memory:queue://testq:memory: usage
change from: 18% of available memory, to: 17% of available memory |
org.apache.activemq.usage.Usage |
 ActiveMQ VMTransport: vm://localhost#15-1
2013-02-04 13:02:50,865 | DEBUG | scope null||/demo/message @
o.e.j.w.WebAppContext{/fileserver,file:/c/bb04na1a/vol/sas3rd/wky/mva-v940/h6i/apache/apache-activemq-5.7.0/webapps/
fileserver/} | org.eclipse.jetty.server.handler.ContextHandler |
qtp13043068-36 -
/demo/message?destination=testq&type=queue&clientId=16F53C00-6EF5-11E2-81B4-0E72C1E2DF3C&readTim
eout=1
2013-02-04 13:02:50,865 | DEBUG | RESPONSE /demo/message  204 handled=true |
org.eclipse.jetty.server.Server | qtp13043068-36 -
/demo/message?destination=testq&type=queue&clientI
d=16F53C00-6EF5-11E2-81B4-0E72C1E2DF3C&readTimeout=1
-----------


Then when my test disconnects via &action=unsubscribe, I see the following:
------------------------
2013-02-04 13:02:50,880 | DEBUG | default:memory:queue://testq:memory: usage
change from: 12% of available memory, to: 11% of available memory |
org.apache.activemq.usage.Usage  
 ActiveMQ VMTransport: vm://localhost#15-1
2013-02-04 13:02:50,882 | DEBUG | default:memory:queue://testq:memory: usage
change from: 11% of available memory, to: 10% of available memory |
org.apache.activemq.usage.Usage  
 ActiveMQ VMTransport: vm://localhost#15-1
2013-02-04 13:02:50,884 | DEBUG | default:memory:queue://testq:memory: usage
change from: 10% of available memory, to: 9% of available memory |
org.apache.activemq.usage.Usage |
ActiveMQ VMTransport: vm://localhost#15-1
2013-02-04 13:02:51,751 | DEBUG | Stopping connection: vm://localhost#14 |
org.apache.activemq.broker.TransportConnection | ActiveMQ
BrokerService[localhost] Task-3
2013-02-04 13:02:51,751 | DEBUG | Forcing shutdown of ExecutorService:
java.util.concurrent.ThreadPoolExecutor@1fd25ce |
org.apache.activemq.util.ThreadPoolUtils | ActiveMQ Broke
rService[localhost] Task-3
2013-02-04 13:02:51,751 | DEBUG | Stopped transport: vm://localhost#14 |
org.apache.activemq.broker.TransportConnection | ActiveMQ
BrokerService[localhost] Task-3
2013-02-04 13:02:51,753 | DEBUG | Connection Stopped: vm://localhost#14 |
org.apache.activemq.broker.TransportConnection | ActiveMQ
BrokerService[localhost] Task-3
2013-02-04 13:02:51,753 | INFO  | Connector vm://localhost Stopped |
org.apache.activemq.broker.TransportConnector | qtp13043068-40 -
http://h6i94t01:8161/demo/message?destinatio
n=testq&type=queue&clientId=16F53C00-6EF5-11E2-81B4-0E72C1E2DF3C&readTimeout=1&action=unsubscribe
2013-02-04 13:02:51,753 | DEBUG | scope null||/demo/message @
o.e.j.w.WebAppContext{/fileserver,file:/c/bb04na1a/vol/sas3rd/wky/mva-v940/h6i/apache/apache-activemq-5.7.0/webapps/
fileserver/} | org.eclipse.jetty.server.handler.ContextHandler |
qtp13043068-40 -
http://h6i94t01:8161/demo/message?destination=testq&type=queue&clientId=16F53C00-6EF5-11E2-81B4-
0E72C1E2DF3C&readTimeout=1&action=unsubscribe
2013-02-04 13:02:51,753 | DEBUG | RESPONSE /demo/message  200 handled=true |
org.eclipse.jetty.server.Server | qtp13043068-40 -
http://h6i94t01:8161/demo/message?destination=test
q&type=queue&clientId=16F53C00-6EF5-11E2-81B4-0E72C1E2DF3C&readTimeout=1&action=unsubscribe
2013-02-04 13:02:51,753 | DEBUG | Enabled read interest
SCEP@315068{l(/10.24.8.124:64537)<->r(/10.24.8.124:8161),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true
,i=1r}-{AsyncHttpConnection@1961a84,g=HttpGenerator{s=4,h=0,b=-1,c=-1},p=HttpParser{s=0,l=5,c=1},r=13}
| org.eclipse.jetty.server.AsyncHttpConnection | qtp13043068-40
2013-02-04 13:02:51,753 | DEBUG | ishut
SCEP@315068{l(/10.24.8.124:64537)<->r(/10.24.8.124:8161),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{AsyncHtt
pConnection@1961a84,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=-3},r=13}
| org.eclipse.jetty.io.nio.ChannelEndPoint | qtp13043068-40
2013-02-04 13:02:51,753 | DEBUG | filled -1/0 |
org.eclipse.jetty.http.HttpParser | qtp13043068-40
2013-02-04 13:02:51,753 | DEBUG | Disabled read interest while writing
response
SCEP@315068{l(/10.24.8.124:64537)<->r(/10.24.8.124:8161),d=true,open=true,ishut=true,oshut=false,r
b=false,wb=false,w=true,i=1r}-{AsyncHttpConnection@1961a84,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=0,l=0,c=-3},r=13}
| org.eclipse.jetty.server.AsyncHttpConnection | q
tp13043068-40
2013-02-04 13:02:51,753 | DEBUG | close
SCEP@315068{l(/10.24.8.124:64537)<->r(/10.24.8.124:8161),d=true,open=true,ishut=true,oshut=false,rb=false,wb=false,w=true,i=1r}-{AsyncHttp
Connection@1961a84,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=0,l=0,c=-3},r=13}
| org.eclipse.jetty.io.nio.ChannelEndPoint | qtp13043068-40
2013-02-04 13:02:51,754 | DEBUG | destroyEndPoint
SCEP@315068{l(null)<->r(/10.24.8.124:8161),d=false,open=false,ishut=true,oshut=true,rb=false,wb=false,w=true,i=1!}-{AsyncHttpCon
nection@1961a84,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=0,l=0,c=-3},r=13}
| org.eclipse.jetty.io.nio | qtp13043068-34 Selector0
2013-02-04 13:02:51,754 | DEBUG | closed
AsyncHttpConnection@1961a84,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=0,l=0,c=-3},r=13
| org.eclipse.jetty.server.AbstractHttpCo
nnection | qtp13043068-34 Selector0
2013-02-04 13:02:53,535 | DEBUG | Checkpoint started. |
org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal
Checkpoint Worker
2013-02-04 13:02:53,572 | DEBUG | Checkpoint done. |
org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal
Checkpoint Worker
2013-02-04 13:02:58,124 | DEBUG | queue://requestq expiring messages .. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[localhost]
Scheduler
2013-02-04 13:02:58,126 | DEBUG | requestq toPageIn: 0, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 26, dequeueCount: 26 |
org.apache.activemq.broker.region.Queue | Active
MQ Broker[localhost] Scheduler
2013-02-04 13:02:58,127 | DEBUG | queue://requestq expiring messages done. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[localhost]
Scheduler
2013-02-04 13:02:58,164 | DEBUG | Checkpoint started. |
org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal
Checkpoint Worker
2013-02-04 13:02:58,181 | DEBUG | Checkpoint done. |
org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal
Checkpoint Worker
2013-02-04 13:02:58,194 | DEBUG | queue://testq expiring messages .. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[localhost]
Scheduler
2013-02-04 13:02:58,194 | DEBUG | testq toPageIn: 0, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 790, dequeueCount: 790 |
org.apache.activemq.broker.region.Queue | ActiveM
Q Broker[localhost] Scheduler
------------------------

Btw, the test runs fine when the broker is running on my PC instead of a
UNIX machine.  One difference is that the broker running on UNIX has its
kahadb directory is on a non-local NFS mounted directory.  Is it acceptable
to have the Kahadb database on a NFS mounted disk?


-----
Stephen Vincent
--
View this message in context: http://activemq.2283324.n4.nabble.com/Async-client-IllegalStateException-REDISPATCHING-initial-resumed-tp4662738.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.