Consumer tag=None4

[Nikos Skalis]

Hi guys,

Would you be so kind to advise me on the following:

When I deploy a celery worker/consumer in RabbitMQ management plugin  I see the consumer labeled with

Consumer tag=None4

And when the producer sends a message in RabbitMQ server logs, I see the following 

client unexpectedly closed TCP connection

And that is happening only when Consumer tag=None4

Could you please advise what consumer tag labeled with None4 actually means ?

Many Thanks,

Nikos

[Michael Klishin]

Can you please post a page or so of logs before the "client unexpectedly closed TCP connection" part?

There can be something interesting there.

"None4" suggests that it is computed from a value that is None. Technically for RabbitMQ, "None4" is as good

as any other ASCII string as long as it is unique across the consumers on that channel.

How Celery computes consumer tags and what value ends up being None, I don't know.

If there is a way to enable debug logging for Celery, I'd highly recommend doing so.

Taking and inspecting a traffic capture [1] would provide a lot of valuable information as well.

1. https://www.rabbitmq.com/amqp-wireshark.html

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[Nikos Skalis]

Thanks Michael for looking into it.

Please find attached the logs from rabbitmq+celery.

I will send the .pcap file via a separate email.

Many Thanks.

Nikos

On Monday, July 3, 2017 at 8:06:52 AM UTC+2, Michael Klishin wrote:

Can you please post a page or so of logs before the "client unexpectedly closed TCP connection" part?

There can be something interesting there.

"None4" suggests that it is computed from a value that is None. Technically for RabbitMQ, "None4" is as good

as any other ASCII string as long as it is unique across the consumers on that channel.

How Celery computes consumer tags and what value ends up being None, I don't know.

If there is a way to enable debug logging for Celery, I'd highly recommend doing so.

Taking and inspecting a traffic capture [1] would provide a lot of valuable information as well.

1. https://www.rabbitmq.com/amqp-wireshark.html

On Sun, Jul 2, 2017 at 10:17 PM, Nikos Skalis <nskalis....@gmail.com> wrote:

Hi guys,

Would you be so kind to advise me on the following:

When I deploy a celery worker/consumer in RabbitMQ management plugin  I see the consumer labeled with

Consumer tag=None4

And when the producer sends a message in RabbitMQ server logs, I see the following 

client unexpectedly closed TCP connection

And that is happening only when Consumer tag=None4

Could you please advise what consumer tag labeled with None4 actually means ?

Many Thanks,

Nikos

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Michael Klishin]

These logs reveal nothing interesting: so far it looks like the client indeed closes TCP connection,

intentionally or not, without closing AMQP 0-9-1 connection.

Let's see what traffic capture reveals next.

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Michael Klishin]

Nikos shared a traffic capture with me off-list.

So far my findings are:

 * RabbitMQ sends no connection.close frames or any other errors, in fact.

 * The TCP (and thus AMQP 0-9-1) connection that sends the suspiciously looking basic.consume with tag = None4

   and the connection that is abruptly closed by a client less than 200 ms after establishing are two separate connections (same source and destination IP, same destination port but source ports: 40217 vs. 40221). In other words,

   they can't be related if my reading of the capture is correct.

[Michael Klishin]

Posting my capture review findings with Nikos' permission after editing out 3 IP address octets:

According to the capture, there are no errors sent by RabbitMQ.

A client with port 40217

consumes with consumer tag = None4:

59 2017-07-03 08:23:22.877534 XXX.XXX.XXX.238 40217 XXX.XXX.XXX.241 5672 AMQP 107 Basic.Consume q=c.nl-ams09b-ri1 

Later a client connects from port 40221:

78 2017-07-03 08:23:38.717850 XXX.XXX.XXX.238 40221 XXX.XXX.XXX.241 5672 AMQP 74 Protocol-Header 1-0-9

and after a fraction of a second client 40221 initiates TCP connection closure:

97 2017-07-03 08:23:38.837056 XXX.XXX.XXX.238 40221 XXX.XXX.XXX.241 5672 TCP 66 40221 → 5672 [FIN, ACK] Seq=39826 Ack=666 Win=30336 Len=0 TSval=2550405829 TSecr=602000349

so those events (basic.consume with a suspiciously looking consumer

tag and unexpected TCP connection closure) do not happen on the same

TCP connection, and thus cannot belong to the same AMQP 0-9-1

connection.

So far it looks like an issue on Celery's end, e.g. an unhandled exception. Those often lead

clients to close TCP connection e.g. because their OS process

terminated without a chance to close AMQP 0-9-1 connection.

Nikos suggests that Celery indeed can open more than one connection per worker and those connections

use different OS processes.