Error while reading queue with AMQP 1.0

[apares]

Hi guys,

I'm pretty new to amqp rabbitmq and so on. 

I'm setting up a test plateform with amqp 1.0 in the following configuration :

- rabbitmq server on a windows machine with amqp plugin 1.0 enabled.

- qpid proton C lib compiled on an other linux plateform.

It seems working for now except when reading to a queue which ends with an error. I'm using send and receive example program from qpid libs.

Logs from rabbitmq gives me the same kind of error output message that one from proton but I did not understand what's going on ...

=INFO REPORT==== 22-Feb-2016::16:35:56 ===

accepting AMQP connection <0.2911.0> (192.168.103.6:50121 -> 192.168.101.118:5672)

=INFO REPORT==== 22-Feb-2016::16:35:56 ===

closing AMQP connection <0.2911.0> (192.168.103.6:50121 -> 192.168.101.118:5672)

=INFO REPORT==== 22-Feb-2016::16:35:59 ===

accepting AMQP connection <0.2938.0> (192.168.103.6:50314 -> 192.168.101.118:5672)

=WARNING REPORT==== 22-Feb-2016::16:35:59 ===

Closing session for connection <0.2938.0>:

{'v1_0.error',{symbol,<<"amqp:invalid-field">>}, {utf8,<<"Unrecognised state: undefined\nDisposition was: {'v1_0.disposition',true,\n {uint,0},\n {uint,0},\n true,undefined,undefined}\n">>}, undefined}

=WARNING REPORT==== 22-Feb-2016::16:36:04 ===

closing AMQP connection <0.2938.0> (192.168.103.6:50314 -> 192.168.101.118:5672):

client unexpectedly closed TCP connection

I observed that the queue still receives messages but when I launch the receive script all messages stays in the queue and never been erased

I tought that when I read one, it will be erased because my tests with amqp 0.9 and python client script behave this way

If someone could help to understand where this error comes from ...

[Gordon Sim]

Just to confirm, this is when receving messages from the queue? When
running the proton examples, try running with PN_TRACE_FRM=1. That will
give a trace of the protocol interaction which is useful in identifying
issues.

My guess is that it is due to default behaviour in the proton example
where the transfers are 'settled' (i.e. acknowledged) without any
specific status, and the broker in this case does not like that.

[apares]

Yes this error is when receiving messages from the queue.
Here is the log with 'PN_TRACE_FRM=1'
/build$ ./recv amqp://192.168.101.118/queue2
Connected to 192.168.101.118:5672
[0x9b8150]:  -> SASL
[0x9b8150]:0 -> @sasl-init(65) [mechanism=:ANONYMOUS, initial-response=b""]
[0x9b8150]:  <- SASL
[0x9b8150]:0 <- @sasl-mechanisms(64) [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS, :AMQPLAIN, :PLAIN]]
[0x9b8150]:0 <- @sasl-outcome(68) [code=0]
[0x9b8150]:  -> AMQP
[0x9b8150]:0 -> @open(16) [container-id="8310b1de-0b98-4ce8-b3db-964d20854316", hostname="192.168.101.118"]
[0x9b8150]:0 -> @begin(17) [next-outgoing-id=0, incoming-window=2147483647, outgoing-window=0]
[0x9b8150]:0 -> @attach(18) [name="receiver-xxx", handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="queue2", durable=0, timeout=0, dynamic=false], target=@target(41) [address="queue2", durable=0, timeout=0, dynamic=false], initial-delivery-count=0]
[0x9b8150]:0 -> @flow(19) [incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=0, link-credit=1024, drain=false]
[0x9b8150]:  <- AMQP
[0x9b8150]:0 <- @open(16) [container-id="rab...@PC0068.xxxxx.xxxx", idle-time-out=60000, properties={:"cluster_name"="rab...@PC0068.xxxxx.xxxx", :copyright="Copyright (C) 2007-2015 Pivotal Software, Inc.", :information="Licensed under the MPL.  Seehttp://www.rabbitmq.com/", :platform="Erlang/OTP", :product="RabbitMQ", :version="3.6.0"}]
[0x9b8150]:0 <- @begin(17) [remote-channel=0, next-outgoing-id=0, incoming-window=65535, outgoing-window=65535, handle-max=4294967295]
[0x9b8150]:0 <- @attach(18) [name="receiver-xxx", handle=0, role=false, snd-settle-mode=0, rcv-settle-mode=0, source=@source(40) [address="queue2", durable=0, timeout=0, dynamic=false, default-outcome=@released(38) [], outcomes=@PN_SYMBOL[:"amqp:accepted:list", :"amqp:rejected:list", :"amqp:released:list"]], initial-delivery-count=0]
[0x9b8150]:0 <- @flow(19) [next-incoming-id=0, incoming-window=65535, next-outgoing-id=0, outgoing-window=65535, handle=0, delivery-count=0, link-credit=1024, available=0, drain=false]
[0x9b8150]:0 <- @transfer(20) [handle=0, delivery-id=0, delivery-tag=b"\x00\x00\x00\x00\x00\x00\x00\x01", message-format=0, settled=false, more=false, resume=false, aborted=false, batchable=false] (95) "\x00Sp\xc0\x07\x05BP\x04@B@\x00Ss\xd0\x00\x00\x00@\x00\x00\x00\x0d@@\xa1\x1damqp://192.168.101.118/queue2@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa1\x06test12"
[0x9b8150]:0 <- @transfer(20) [handle=0, delivery-id=1, delivery-tag=b"\x00\x00\x00\x00\x00\x00\x00\x02", message-format=0, settled=false, more=false, resume=false, aborted=false, batchable=false] (97) "\x00Sp\xc0\x07\x05BP\x04@B@\x00Ss\xd0\x00\x00\x00@\x00\x00\x00\x0d@@\xa1\x1damqp://192.168.101.118/queue2@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa1\x08hzqfsefq"
Address: amqp://192.168.101.118/queue2
Subject: (no subject)
Content: "test12"
Address: amqp://192.168.101.118/queue2
Subject: (no subject)
Content: "hzqfsefq"
[0x9b8150]:0 -> @disposition(21) [role=true, first=0, last=0, settled=true]
[0x9b8150]:0 -> @disposition(21) [role=true, first=1, last=1, settled=true]
[0x9b8150]:0 <- @end(23) [error=@error(29) [condition=:"amqp:invalid-field", description="Unrecognised state: undefined\x0aDisposition was: {'v1_0.disposition',true,\x0a                                     {uint,0},\x0a                                     {uint,0},\x0a                                     true,undefined,undefined}\x0a"]]
SESSION ERROR (amqp:invalid-field) Unrecognised state: undefined
Disposition was: {'v1_0.disposition',true,
                                     {uint,0},
                                     {uint,0},
                                     true,undefined,undefined}

[0x9b8150]:0 -> @end(23) []
[0x9b8150]:0 -> 
[0x9b8150]:0 -> 
[0x9b8150]:0 -> 
[0x9b8150]:0 -> 
[0x9b8150]:0 -> 
[0x9b8150]:0 -> 

As you can see there are 2 messages in this queue (named queue2) but they stays here forever. I can't understand all this log output put I hope we will have a better analyse of this.

Thanks.

[apares]

Is there someone here to help me understand this log and the problem associated ?

thanks

On Tuesday, February 23, 2016 at 11:10:47 AM UTC+1, apares wrote:

Yes this error is when receiving messages from the queue.
Here is the log with 'PN_TRACE_FRM=1'
/build$ ./recv amqp://192.168.101.118/queue2
Connected to 192.168.101.118:5672
[0x9b8150]:  -> SASL
[0x9b8150]:0 -> @sasl-init(65) [mechanism=:ANONYMOUS, initial-response=b""]
[0x9b8150]:  <- SASL
[0x9b8150]:0 <- @sasl-mechanisms(64) [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS, :AMQPLAIN, :PLAIN]]
[0x9b8150]:0 <- @sasl-outcome(68) [code=0]
[0x9b8150]:  -> AMQP
[0x9b8150]:0 -> @open(16) [container-id="8310b1de-0b98-4ce8-b3db-964d20854316", hostname="192.168.101.118"]
[0x9b8150]:0 -> @begin(17) [next-outgoing-id=0, incoming-window=2147483647, outgoing-window=0]
[0x9b8150]:0 -> @attach(18) [name="receiver-xxx", handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="queue2", durable=0, timeout=0, dynamic=false], target=@target(41) [address="queue2", durable=0, timeout=0, dynamic=false], initial-delivery-count=0]
[0x9b8150]:0 -> @flow(19) [incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=0, link-credit=1024, drain=false]
[0x9b8150]:  <- AMQP

[0x9b8150]:0 <- @open(16) [container-id="rabbit@PC0068.xxxxx.xxxx", idle-time-out=60000, properties={:"cluster_name"="rab...@PC0068.xxxxx.xxxx", :copyright="Copyright (C) 2007-2015 Pivotal Software, Inc.", :information="Licensed under the MPL.  Seehttp://www.rabbitmq.com/", :platform="Erlang/OTP", :product="RabbitMQ", :version="3.6.0"}]

[Michael Klishin]

On 25 February 2016 at 17:18:05, apares (theto...@gmail.com) wrote:
> Is there someone here to help me understand this log and the problem
> associated ?

Not without investigating first. It can  be a compatibility issue of some kind in the plugin.
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Gordon Sim]

On 25/02/16 14:18, apares wrote:
> Is there someone here to help me understand this log and the problem
> associated ?

Sorry for delayed response...

> On Tuesday, February 23, 2016 at 11:10:47 AM UTC+1, apares wrote:
> [0x9b8150]:0 -> @disposition(21) [role=true, first=0, last=0,
> settled=true]
> [0x9b8150]:0 -> @disposition(21) [role=true, first=1, last=1,
> settled=true]

I suspect this is the issue. The dispositions above do not specify a
'state' (which is an optional field), nor was a default outcome specified.

I' assuming you are using the proton messenger API, where this is
default behaviour. You can alter it by using
pn_messenger_set_incoming_window to set a non-zero window and the using
pn_messenger_accept to explicitly accept the messages.

[Gordon Sim]

On 25/02/16 17:07, Gordon Sim wrote:
> On 25/02/16 14:18, apares wrote:
>> Is there someone here to help me understand this log and the problem
>> associated ?
>
> Sorry for delayed response...
>
>> On Tuesday, February 23, 2016 at 11:10:47 AM UTC+1, apares wrote:
>> [0x9b8150]:0 -> @disposition(21) [role=true, first=0, last=0,
>> settled=true]
>> [0x9b8150]:0 -> @disposition(21) [role=true, first=1, last=1,
>> settled=true]
>
> I suspect this is the issue. The dispositions above do not specify a
> 'state' (which is an optional field), nor was a default outcome specified.

Correction to that last bit, rabbitmq *is* setting a default outcome, of
'released'. So the dispositions above would be expected to release (not
accept) the messages. Since you want to accept them you should change as
below anyway.