[
https://issues.apache.org/jira/browse/AMQ-3907?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Timothy Bish closed AMQ-3907.
-----------------------------
Resolution: Fixed
> 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 was sent by Atlassian JIRA
(v6.1.4#6159)
