Return-Path: X-Original-To: apmail-activemq-dev-archive@www.apache.org Delivered-To: apmail-activemq-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id A42CD10C5A for ; Mon, 25 Nov 2013 10:49:47 +0000 (UTC) Received: (qmail 70506 invoked by uid 500); 25 Nov 2013 10:49:45 -0000 Delivered-To: apmail-activemq-dev-archive@activemq.apache.org Received: (qmail 69991 invoked by uid 500); 25 Nov 2013 10:49:39 -0000 Mailing-List: contact dev-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@activemq.apache.org Delivered-To: mailing list dev@activemq.apache.org Received: (qmail 69871 invoked by uid 99); 25 Nov 2013 10:49:36 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 25 Nov 2013 10:49:36 +0000 Date: Mon, 25 Nov 2013 10:49:36 +0000 (UTC) From: "Grzegorz Grzybek (JIRA)" To: dev@activemq.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (AMQ-3907) Restful HTTP MessageServlet causing trouble. May be a garbage collection issue. MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/AMQ-3907?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13831350#comment-13831350 ] Grzegorz Grzybek commented on AMQ-3907: --------------------------------------- I've recreated your scenario and received the same problems - 2000 POSTS works fine, then single GET dequeues all 2000 messages and then everything breaks. The difference with working version (5.9.0) was the lines added in commit https://github.com/apache/activemq/commit/de49f2e8 - see AMQ-4629. regards Grzegorz Grzybek > 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#6144)