You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@activemq.apache.org by "Guy Allard (Created) (JIRA)" <ji...@apache.org> on 2011/10/14 05:30:11 UTC
[jira] [Created] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
ACK followed by DISCONNECT Leaves Message Available
---------------------------------------------------
Key: APLO-88
URL: https://issues.apache.org/jira/browse/APLO-88
Project: ActiveMQ Apollo
Issue Type: Bug
Components: apollo-stomp
Environment: Linux, Ubuntu 11.04
Reporter: Guy Allard
An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
# ---------
require 'rubygems'
require 'stomp'
#
c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
c.subscribe "/queue/rtest.01", :ack => :client
c.publish "/queue/rtest.01", "a simple message"
msg = c.receive
c.ack msg.headers['message-id']
# sleep 5
c.disconnect
# ---------
And is (usually) accompanied by:
2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
in apollo.log
Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13165759#comment-13165759 ]
Guy Allard commented on APLO-88:
--------------------------------
Comment 1 tonight ...
For me, current experiments show that the most simple bypass of this behavior is to add a stagger/delay right after putting an ACK on the wire.
Even stagger values like 50ms seem to be reliable.
We will adjust for that in client code unit tests.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13168058#comment-13168058 ]
Guy Allard commented on APLO-88:
--------------------------------
Hiram - Thanks. I thought you wanted to forget this one ... :-)
I will test tomorrow - it is late and I already have about 14 hours of work in today ....
I will comment again later tomorrow .....
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Affects Versions: 1.0-beta6
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Assignee: Hiram Chirino
> Fix For: 1.0
>
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Updated] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Updated) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Guy Allard updated APLO-88:
---------------------------
Attachment: aplo-88-log.txt
Log from a 1.1 client test bed.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Resolved] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Hiram Chirino (Resolved) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Hiram Chirino resolved APLO-88.
-------------------------------
Resolution: Fixed
Guy, I've just committed fix for this and deployed a new SNAPSHOT with the fix. Could you verify it works for you? Thanks!
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Affects Versions: 1.0-beta6
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Assignee: Hiram Chirino
> Fix For: 1.0
>
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Closed] (APLO-88) ACK followed by DISCONNECT Leaves Message
Available
Posted by "Guy Allard (Closed) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Guy Allard closed APLO-88.
--------------------------
Testing with a current build verifies this is complete.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Affects Versions: 1.0-beta6
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Assignee: Hiram Chirino
> Fix For: 1.0
>
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13165769#comment-13165769 ]
Guy Allard commented on APLO-88:
--------------------------------
Comment 2 tonight ...
I spent some time looking at this today:
- Cloned current github: commit e707a72.
- Added warnings to Queue.scala
- Added warnings to StompCodec.scala
- Ran a build, yada yada, ....
Result of that is:
2011-12-08 20:27:39,647 | INFO | OS : Linux 3.0.0-13-generic (Ubuntu 11.10) | console | hawtdispatch-DEFAULT-1
2011-12-08 20:27:39,649 | INFO | JVM : OpenJDK 64-Bit Server VM 1.6.0_23 (Sun Microsystems Inc.) | console | hawtdispatch-DEFAULT-1
2011-12-08 20:27:39,649 | INFO | Apollo : 1.0-SNAPSHOT (at: /home/apollo/apache-apollo-1.0-SNAPSHOT) | console | hawtdispatch-DEFAULT-1
2011-12-08 20:27:39,650 | INFO | OS is restricting the open file limit to: 5120 | console | hawtdispatch-DEFAULT-1
2011-12-08 20:27:39,807 | DEBUG | Starting administration interface | org.apache.activemq.apollo.broker.jetty.JettyWebServer | Apollo Task
2011-12-08 20:27:39,869 | INFO | Starting store: bdb store at /home/apollo/my-broker-snap/data | console | hawtdispatch-DEFAULT-2
2011-12-08 20:27:39,945 | INFO | Accepting connections at: tls://0.0.0.0:62614 | console | hawtdispatch-DEFAULT-1
2011-12-08 20:27:39,952 | INFO | Accepting connections at: tcp://0.0.0.0:62613 | console | hawtdispatch-DEFAULT-1
2011-12-08 20:27:41,303 | INFO | Administration interface available at: https://127.0.0.1:62681/ | console | Apollo Task
2011-12-08 20:27:41,304 | INFO | Administration interface available at: http://127.0.0.1:62680/ | console | Apollo Task
2011-12-08 20:28:57,035 | WARN | returning command: StompFrame(CONNECT,List((login,my), (passcode,mypw), (content-length,0), (content-type,text/plain; charset=UTF-8)),BufferContent({ offset: 89, length: 0, data: "" }),List()) | org.apache.activemq.apollo.stomp.StompCodec | hawtdispatch-DEFAULT-2
2011-12-08 20:28:57,061 | WARN | returning command: StompFrame(SUBSCRIBE,List((ack,client), (destination,/queue/rtest.03), (content-length,0), (content-type,text/plain; charset=UTF-8)),BufferContent({ offset: 197, length: 0, data: "" }),List()) | org.apache.activemq.apollo.stomp.StompCodec | hawtdispatch-DEFAULT-2
2011-12-08 20:28:57,076 | WARN | returning command: StompFrame(SEND,List((current_time,2011-12-08 20:28:57 -0500), (destination,/queue/rtest.03), (content-length,16), (content-type,text/plain; charset=UTF-8)),BufferContent({ offset: 329, length: 16, data: "a simple message" }),List()) | org.apache.activemq.apollo.stomp.StompCodec | hawtdispatch-DEFAULT-2
2011-12-08 20:28:57,133 | DEBUG | created queue: rtest.03 | org.apache.activemq.apollo.broker.Queue | hawtdispatch-DEFAULT-1
2011-12-08 20:28:57,189 | DEBUG | producer route attaching to conusmer. | org.apache.activemq.apollo.broker.DeliveryProducerRoute | hawtdispatch-DEFAULT-3
2011-12-08 20:28:57,267 | WARN | returning command: StompFrame(ACK,List((message-id,my-broker-snap-1-1), (content-length,0), (content-type,text/plain; charset=UTF-8)),BufferContent({ offset: 438, length: 0, data: "" }),List()) | org.apache.activemq.apollo.stomp.StompCodec | hawtdispatch-DEFAULT-2
2011-12-08 20:28:57,270 | WARN | returning command: StompFrame(UNSUBSCRIBE,List((destination,/queue/rtest.03), (content-length,0), (content-type,text/plain; charset=UTF-8)),BufferContent({ offset: 537, length: 0, data: "" }),List()) | org.apache.activemq.apollo.stomp.StompCodec | hawtdispatch-DEFAULT-2
2011-12-08 20:28:57,272 | WARN | returning command: StompFrame(DISCONNECT,List((receipt,/queue/rtest.03 2011-12-08 20:28:57 -0500), (content-length,0), (content-type,text/plain; charset=UTF-8)),BufferContent({ offset: 657, length: 0, data: "" }),List()) | org.apache.activemq.apollo.stomp.StompCodec | hawtdispatch-DEFAULT-2
2011-12-08 20:28:57,290 | WARN | ACK Starts | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-3
2011-12-08 20:28:57,292 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-3
2011-12-08 20:28:57,317 | DEBUG | producer route detaching from conusmer. | org.apache.activemq.apollo.broker.DeliveryProducerRoute | hawtdispatch-DEFAULT-1
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13127621#comment-13127621 ]
Guy Allard commented on APLO-88:
--------------------------------
A 1.1 connection appears to be misbehaving as well. I am attaching a somewhat ugly log from my 1.1 client test bed.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13168478#comment-13168478 ]
Guy Allard commented on APLO-88:
--------------------------------
Hiram - Excellent, thank you, great work. I ran this failing sequence this morning with over 10K iterations, and a reasonable amount of concurrency across several test beds. Zero problems.
I will close this.
Regards, Guy
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Affects Versions: 1.0-beta6
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Assignee: Hiram Chirino
> Fix For: 1.0
>
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Hiram Chirino (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13163186#comment-13163186 ]
Hiram Chirino commented on APLO-88:
-----------------------------------
The safest way for a client to shutdown a connection is to add a receipt header to the DISCONNECT frame and wait for the response. That way you can be assured the server has received all previous frames.
That would also work even if SoLinger was set to 0.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Hiram Chirino (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13163183#comment-13163183 ]
Hiram Chirino commented on APLO-88:
-----------------------------------
Hi Guy,
Is the client setting SoLinger to 0 by any chance?
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13127473#comment-13127473 ]
Guy Allard commented on APLO-88:
--------------------------------
My concern is that there are real world clients that are written like that.
The notable aspect of that code is: the SUBSCRIBE is issued *without* an 'id', as 1.0 allows. If I change this line:
c.subscribe "/queue/rtest.01", :ack => :client, :id => 'rtest.01'
all works as expected.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13162441#comment-13162441 ]
Guy Allard commented on APLO-88:
--------------------------------
After some more experimentation and thought, it appears what is documented to date does not give a totally correct picture.
FWIW, this does still occur with build apache-apollo-1.0-20111203.032948-211-unix-distro.tar.gz.
More experimentation seems to indicate that this is not triggered solely by:
- ACK
- DISCONNECT
but rather by:
- ACK
- DISCONNECT
- socket close/teardown immediately initiated by the client
If a pause (exact timing not reliably determined) is inserted between DISCONNECT and socket close, the issue does not occur.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Commented] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Guy Allard (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13163985#comment-13163985 ]
Guy Allard commented on APLO-88:
--------------------------------
Hiram - The receipt on disconnect was an interesting idea. However actually using it does *not* solve this problem.
I will look at linger in the next few days, and let you know.
However, please note:
- This client code works running with Active MQ, recent release
- This client code works running with RabbitMQ, recent release
IMO, this is a race condition in Apollo. In every case, it is accompanied by a message like:
2011-12-06 18:37:29,768 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-3
where the actual count displayed could be different, depending on how many previous successful tests were run.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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
[jira] [Updated] (APLO-88) ACK followed by DISCONNECT Leaves
Message Available
Posted by "Hiram Chirino (Updated) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/APLO-88?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Hiram Chirino updated APLO-88:
------------------------------
Affects Version/s: 1.0-beta6
Fix Version/s: 1.0
Assignee: Hiram Chirino
I've just created a test case which reproduces. I'm going to start working on the fix. Thanks for all the info.
> ACK followed by DISCONNECT Leaves Message Available
> ---------------------------------------------------
>
> Key: APLO-88
> URL: https://issues.apache.org/jira/browse/APLO-88
> Project: ActiveMQ Apollo
> Issue Type: Bug
> Components: apollo-stomp
> Affects Versions: 1.0-beta6
> Environment: Linux, Ubuntu 11.04
> Reporter: Guy Allard
> Assignee: Hiram Chirino
> Fix For: 1.0
>
> Attachments: aplo-88-log.txt
>
>
> An ACK (client mode) followed by a DISCONNECT with no wait time between the frames appears to leave message on the queue.
> I am seeing this with apache-apollo-1.0-20111012.032531-204-unix-distro.tar.gz and at least one previous snapshot.
> I stumbled on to this while working on a new 1.1 client in go. It occurs with either a 1.0 or 1.1 connection. The go code is very raw and not publicly available yet.
> However it recreates with 1.0 using the Ruby stomp gem. Code to recreate:
> # ---------
> require 'rubygems'
> require 'stomp'
> #
> c = Stomp::Connection.open('my', 'mypw', 'localhost', 62613) # Apollo is here
> c.subscribe "/queue/rtest.01", :ack => :client
> c.publish "/queue/rtest.01", "a simple message"
> msg = c.receive
> c.ack msg.headers['message-id']
> # sleep 5
> c.disconnect
> # ---------
> And is (usually) accompanied by:
> 2011-10-13 22:56:00,041 | DEBUG | Internal protocol error: message delivery acked/nacked multiple times: 1 | org.apache.activemq.apollo.broker.Subscription | hawtdispatch-DEFAULT-1
> in apollo.log
> Calling 'flush' on the socket seems to have no affect (in either Ruby or go).
> If you uncomment the 'sleep' in the above Ruby code, the problem will (usually) *not* occur.
> I do get some slightly different results with the go test bed, but let's start with this ............
--
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