Stephen Vincent created AMQ-3907:
------------------------------------
Summary: Restful HTTP MessageServlet causing trouble. May be a
garbage collection issue.
Key: AMQ-3907
URL: https://issues.apache.org/jira/browse/AMQ-3907
Project: ActiveMQ
Issue Type: Bug
Components: Broker
Affects Versions: 5.6.0
Environment: 32-bit Windows
Reporter: Stephen Vincent
Priority: Critical
I am developing a C-based client that uses the RESTful HTTP protocol to POST
and GET messages to and from an ActiveMQ broker. I have seen my test run
successfully. However, if I run it multiple times back to back in succession,
it will usually encounter failures. The test has two steps, where the first
POSTs a number of messages on the queue, then the second step GETs them back
off. When it encounters trouble, it is usually in the first step when posting
messages. When that encounters failures, it appears to be having trouble
re-connecting, and kicks-out of that first step, proceeding on to the second
step where it GETs the messages off of the queue. When the first step
encounters trouble, the second step usually just gets a portion of the messages
before getting a 204(No content). The 204 notifies my test that it is time to
terminate. I have seen the following in some of the server debug logs:
-------------------------------------
2012-06-27 07:44:04,007 | DEBUG | Async client internal exception occurred with
no exception listener registered: java.lang.IllegalStateException:
REDISPATCHING,initial,resumed | org.apache.activemq.ActiveMQConnection |
ActiveMQ Session Task-2
java.lang.IllegalStateException: REDISPATCHING,initial,resumed
at
org.eclipse.jetty.server.AsyncContinuation.dispatch(AsyncContinuation.java:403)
at
org.eclipse.jetty.server.AsyncContinuation.resume(AsyncContinuation.java:810)
at
org.apache.activemq.web.MessageServlet$Listener.onMessageAvailable(MessageServlet.java:368)
at
org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1320)
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:122)
at
org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
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)
-------------------------------------
I am thinking that the garbage collector is not able to keep-up, and the broker
has trouble when running out of memory.
I have also seen messages like this:
-------------------------------------
2012-06-27 07:33:01,435 | DEBUG | Main:memory:queue://myqueue:memory: usage
change from: 67% of available memory, to: 68% of available memory |
org.apache.activemq.usage.Usage | VMTransport: vm://localhost#71
-------------------------------------
When the second step terminates prematurely due to the 204 status, the rest of
the messages are gone. Maybe my "consumer.prefetchSize=1" is ignored, and the
consumer on the server-side grabs the rest of the messages. Any ideas?
Another thing I notice, is that the HTTP client code I use reports the
following for every message it posts:
"Web server requires that we close the current connection and obtain a new
connection to continue." Is that normal, or can I change some configuration
setting to prevent that?
My test program is a SAS program. Note: since my client code in question is
not yet production, you will not be able to run the test even if you do have a
current version of SAS. Here is my test program:
-------------------------------------
data _null_;
file '' device=activemq lrecl=54
url='http://d22275:8161/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTimeToLive=100000'
;
do i = 1 to 2000;
d = datetime();
put i z5. +1 'This is a test msg sent at' +1 d datetime21.2;
end;
run;
data _null_;
infile '' device=activemq lrecl=54 timeout=1000
url='http://d22275:8161/demo/message/myqueue?type=queue&consumer.prefetchSize=1'
;
input;
run;
-------------------------------------
That first DATA step POSTs 2000 messages to a queue, and the second DATA step
GETs them back off. If I change the write loop to just POST 2 messages and I
turn on some client-side debug/trace logging, you can see what I am sending and
receiving across the wire. Here is an excerpt from the log:
-------------------------------------
INFO 1 data _null_;
INFO 2 file '' device=activemq lrecl=54
INFO 3
url='http://d22275:8161/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PE
INFO 3 ! RSISTENT&JMSTimeToLive=100000'
INFO 4 ;
INFO 5 do i = 1 to 2;
INFO 6 d = datetime();
INFO 7 put i z5. +1 'This is a test msg sent at' +1 d
datetime21.2;
INFO 8 end;
INFO 9 run;
INFO
DEBUG Attempting to connect to Web server 10.23.11.16:8161.
INFO NOTE: The file '' is:
INFO
INFO
URL=http://d22275:8161/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTi
INFO meToLive=100000&clientId=839E8906-E338-4FDE-9818-665B14944874,
INFO LRECL=54,TIMEOUT=-1
INFO
DEBUG Executing POST request.
DEBUG >>> POST
/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTimeToLive=100000&clientId=839E8906-E338-4FDE-9818-665B14944874
HTTP/1.1
DEBUG >>> Content-Type: APPLICATION/X-WWW-FORM-URLENCODED
DEBUG Cache file name used is C:\DOCUME~1\sav\LOCALS~1\Temp\SAS Temporary
Files\SAS_util000100001004_d22275\ut1004000002.utl
DEBUG >>> Content-Length: 59
DEBUG >>> Host: d22275:8161
DEBUG >>> User-Agent: SAS/9
DEBUG >>>
TRACE >>> 341c000: 62 6f 64 79 3d 30 30 30 30 31 20 54 68 69 73 20 |body=00001
This |
TRACE >>> 341c010: 69 73 20 61 20 74 65 73 74 20 6d 73 67 20 73 65 |is a test
msg se|
TRACE >>> 341c020: 6e 74 20 61 74 20 30 31 4a 55 4c 32 30 31 32 3a |nt at
01JUL2012:|
TRACE >>> 341c030: 31 38 3a 32 36 3a 34 33 2e 36 39 |18:26:43.69
|
DEBUG <<< HTTP/1.1 200 OK
DEBUG <<< Set-Cookie: JSESSIONID=1f4dfw7mbb4611ilhiznnkifi3;Path=/demo
DEBUG <<< Expires: Thu, 01 Jan 1970 00:00:00 GMT
DEBUG <<< messageID: ID:d22275-1028-1341175648962-3:24:1:1:1
DEBUG <<< Content-Length: 0
DEBUG <<< Server: Jetty(7.6.1.v20120215)
DEBUG <<<
DEBUG Request POST returns status 200.
DEBUG Executing POST request.
DEBUG Web server requires that we close the current connection and obtain a new
connection to continue.
DEBUG Attempting to connect to Web server 10.23.11.16:8161.
DEBUG >>> POST
/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTimeToLive=100000&clientId=839E8906-E338-4FDE-9818-665B14944874
HTTP/1.1
DEBUG >>> Content-Type: APPLICATION/X-WWW-FORM-URLENCODED
DEBUG Cache file name used is C:\DOCUME~1\sav\LOCALS~1\Temp\SAS Temporary
Files\SAS_util000100001004_d22275\ut1004000003.utl
DEBUG >>> Content-Length: 59
DEBUG >>> Host: d22275:8161
DEBUG >>> Cookie: $Version=1;JSESSIONID=1f4dfw7mbb4611ilhiznnkifi3;$Path=/demo
DEBUG >>> User-Agent: SAS/9
DEBUG >>>
TRACE >>> 3422000: 62 6f 64 79 3d 30 30 30 30 32 20 54 68 69 73 20 |body=00002
This |
TRACE >>> 3422010: 69 73 20 61 20 74 65 73 74 20 6d 73 67 20 73 65 |is a test
msg se|
TRACE >>> 3422020: 6e 74 20 61 74 20 30 31 4a 55 4c 32 30 31 32 3a |nt at
01JUL2012:|
TRACE >>> 3422030: 31 38 3a 32 36 3a 34 33 2e 37 30 |18:26:43.70
|
DEBUG <<< HTTP/1.1 200 OK
DEBUG <<< messageID: ID:d22275-1028-1341175648962-3:24:1:1:2
DEBUG <<< Content-Length: 0
DEBUG <<< Server: Jetty(7.6.1.v20120215)
DEBUG <<<
DEBUG Request POST returns status 200.
DEBUG Attempting to connect to Web server 10.23.11.16:8161.
DEBUG Executing POST request.
DEBUG >>> POST
/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTimeToLive=100000&clientId=839E8906-E338-4FDE-9818-665B14944874&action=unsubscribe
HTTP/1.1
DEBUG >>> Content-Type: application/x-www-form-urlencoded
DEBUG Cache file name used is C:\DOCUME~1\sav\LOCALS~1\Temp\SAS Temporary
Files\SAS_util000100001004_d22275\ut1004000004.utl
DEBUG >>> Content-Length: 0
DEBUG >>> Host: d22275:8161
DEBUG >>> Cookie: $Version=1;JSESSIONID=1f4dfw7mbb4611ilhiznnkifi3;$Path=/demo
DEBUG >>> User-Agent: SAS/9
DEBUG >>>
DEBUG <<< HTTP/1.1 200 OK
DEBUG <<< Content-Length: 0
DEBUG <<< Server: Jetty(7.6.1.v20120215)
DEBUG <<<
DEBUG Request POST returns status 200.
DEBUG Destroying connection to Web server d22275:8161.
INFO NOTE: 2 records were written to the file ''.
INFO The minimum record length was 54.
INFO The maximum record length was 54.
DEBUG Destroying connection to Web server d22275:8161.
INFO NOTE: DATA statement used (Total process time):
INFO real time 0.17 seconds
INFO cpu time 0.00 seconds
INFO
INFO
INFO 10
INFO 11 data _null_;
INFO 12 infile '' device=activemq lrecl=54 timeout=1000
INFO 13
url='http://d22275:8161/demo/message/myqueue?type=queue&consumer.prefetchSize=
INFO 13 ! 1'
INFO 14 ;
INFO 15 input;
INFO 16 run;
INFO
DEBUG Attempting to connect to Web server 10.23.11.16:8161.
INFO NOTE: The infile '' is:
INFO
INFO
URL=http://d22275:8161/demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BA
INFO B771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000,
INFO 2 The SAS System
18:26 Sunday, July 1, 2012
INFO
INFO LRECL=54,TIMEOUT=1000
INFO
DEBUG Executing GET request.
DEBUG >>> GET
/demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BAB771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000
HTTP/1.1
DEBUG >>> Host: d22275:8161
DEBUG >>> Accept: */*
DEBUG >>> Accept-Charset: iso-8859-1,*,utf-8
DEBUG >>> Accept-Encoding: identity
DEBUG >>> Accept-Language: en
DEBUG >>> User-Agent: SAS/9
DEBUG >>>
DEBUG <<< HTTP/1.1 200 OK
DEBUG <<< Set-Cookie: JSESSIONID=171xnui5b43xz1wpgghnpgtiws;Path=/demo
DEBUG <<< Expires: Thu, 01 Jan 1970 00:00:00 GMT
DEBUG <<< Content-Type: text/xml;charset=UTF-8
DEBUG <<< destination: queue://myqueue
DEBUG <<< id: ID:d22275-1028-1341175648962-3:24:1:1:1
DEBUG <<< Content-Length: 54
DEBUG <<< Server: Jetty(7.6.1.v20120215)
DEBUG <<<
TRACE <<< 415a740: 30 30 30 30 31 20 54 68 69 73 20 69 73 20 61 20 |00001 This
is a |
TRACE <<< 415a750: 74 65 73 74 20 6d 73 67 20 73 65 6e 74 20 61 74 |test msg
sent at|
TRACE <<< 415a760: 20 30 31 4a 55 4c 32 30 31 32 3a 31 38 3a 32 36 |
01JUL2012:18:26|
TRACE <<< 415a770: 3a 34 33 2e 36 39 |:43.69
|
DEBUG Request GET returns status 200.
DEBUG Executing GET request.
DEBUG >>> GET
/demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BAB771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000
HTTP/1.1
DEBUG >>> Host: d22275:8161
DEBUG >>> Accept: */*
DEBUG >>> Accept-Charset: iso-8859-1,*,utf-8
DEBUG >>> Accept-Encoding: identity
DEBUG >>> Accept-Language: en
DEBUG >>> Cookie: $Version=1;JSESSIONID=171xnui5b43xz1wpgghnpgtiws;$Path=/demo
DEBUG >>> User-Agent: SAS/9
DEBUG >>>
DEBUG <<< HTTP/1.1 200 OK
DEBUG <<< Content-Type: text/xml;charset=UTF-8
DEBUG <<< destination: queue://myqueue
DEBUG <<< id: ID:d22275-1028-1341175648962-3:24:1:1:2
DEBUG <<< Content-Length: 54
DEBUG <<< Server: Jetty(7.6.1.v20120215)
DEBUG <<<
TRACE <<< 415a740: 30 30 30 30 32 20 54 68 69 73 20 69 73 20 61 20 |00002 This
is a |
TRACE <<< 415a750: 74 65 73 74 20 6d 73 67 20 73 65 6e 74 20 61 74 |test msg
sent at|
TRACE <<< 415a760: 20 30 31 4a 55 4c 32 30 31 32 3a 31 38 3a 32 36 |
01JUL2012:18:26|
TRACE <<< 415a770: 3a 34 33 2e 37 30 |:43.70
|
DEBUG Request GET returns status 200.
DEBUG Executing GET request.
DEBUG >>> GET
/demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BAB771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000
HTTP/1.1
DEBUG >>> Host: d22275:8161
DEBUG >>> Accept: */*
DEBUG >>> Accept-Charset: iso-8859-1,*,utf-8
DEBUG >>> Accept-Encoding: identity
DEBUG >>> Accept-Language: en
DEBUG >>> Cookie: $Version=1;JSESSIONID=171xnui5b43xz1wpgghnpgtiws;$Path=/demo
DEBUG >>> User-Agent: SAS/9
DEBUG >>>
DEBUG <<< HTTP/1.1 204 No Content
DEBUG <<< Content-Type: text/xml;charset=UTF-8
DEBUG <<< Server: Jetty(7.6.1.v20120215)
DEBUG <<<
DEBUG Request GET returns status 204.
DEBUG Attempting to connect to Web server 10.23.11.16:8161.
DEBUG Executing POST request.
DEBUG >>> POST
/demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BAB771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000&action=unsubscribe
HTTP/1.1
DEBUG >>> Content-Type: application/x-www-form-urlencoded
DEBUG Cache file name used is C:\DOCUME~1\sav\LOCALS~1\Temp\SAS Temporary
Files\SAS_util000100001004_d22275\ut1004000005.utl
DEBUG >>> Content-Length: 0
DEBUG >>> Host: d22275:8161
DEBUG >>> Cookie: $Version=1;JSESSIONID=171xnui5b43xz1wpgghnpgtiws;$Path=/demo
DEBUG >>> User-Agent: SAS/9
DEBUG >>>
DEBUG <<< HTTP/1.1 200 OK
DEBUG <<< Content-Length: 0
DEBUG <<< Server: Jetty(7.6.1.v20120215)
DEBUG <<<
DEBUG Request POST returns status 200.
DEBUG Destroying connection to Web server d22275:8161.
INFO NOTE: 2 records were read from the infile ''.
INFO The minimum record length was 54.
INFO The maximum record length was 54.
DEBUG Destroying connection to Web server d22275:8161.
-------------------------------------
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
