RPC weird timeout ( PHP-AMQPLIB Bug ?)

[catharsis3k]

I followed the online examples and wrote client -> server RPC scripts. It works perfectly almost all the time, but seemingly at random I get hit with this error message:

PHP Fatal error:  Uncaught exception 'PhpAmqpLib\Exception\AMQPTimeoutException' with message 'The connection timed out after 45 sec while awaiting incoming data. 1533136572' in php-amqplib/php-amqplib/PhpAmqpLib/Wire/AMQPReader.php:132

I added tons of debug code, including the timestamp in error above but I can't figure out where this is coming from! Right now I believe the php-amqplib package has a bug (?).

I will post below the client steps and server steps along with tcpdump info, maybe someone has a clue. Client IP is 192.168.1.41, server is 192.168.1.24


Client code:

# 5b61ce8ec6ed1 # Start of send function : ( 11:15:26 )

# 5b61ce8ec6ed1 # Start of command publish : ( 11:15:26 )

# 5b61ce8ec6ed1 # Sending ["msieve","api","blah","blah"] 

# 5b61ce8ec6ed1 # Start of command wait : ( 11:15:26 )   ( $channel->wait(null, false, "45"); )

PHP Fatal error:  Uncaught exception 'PhpAmqpLib\Exception\AMQPTimeoutException' with message 'The connection timed out after 45 sec while awaiting incoming data. ( 11:16:12 )' in php-amqplib/php-amqplib/PhpAmqpLib/Wire/AMQPReader.php:132

The timeout is 45 seconds and as you can see, it times out after 46

Server side:

2018-08-01 11:15:13.568709500 waiting for a new frame

2018-08-01 11:15:26.824025500 > 60,60: Basic.deliver

2018-08-01 11:15:26.824028500 waiting for a new frame

2018-08-01 11:15:26.824240500 waiting for a new frame

2018-08-01 11:15:26.824428500 Starting Command ["msieve","api","blah","blah"] at 11:15:26

2018-08-01 11:15:28.010110500 'msieve.cgi '':active script: :1:1533136528

2018-08-01 11:15:28.010174500 Command ["msieve","api","blah","blah"] finished at 11:15:28

2018-08-01 11:15:28.010189500 Command ["msieve","api","blah","blah"] Starting Delivery 11:15:28

2018-08-01 11:15:28.010604500 < [hex]:

2018-08-01 11:15:28.010606500 0000  01 00 01 00 00 00 1C 00  3C 00 28 00 00 05 73 68   ........ <.(...sh

2018-08-01 11:15:28.010608500 0010  65 6C 6C 0E 63 6F 6D 6D  61 6E 64 2E 72 65 73 75   ell.comm and.resu

2018-08-01 11:15:28.010610500 0020  6C 74 00 CE 02 00 01 00  00 00 1C 00 3C 00 00 00   lt.▒.... ....<...

2018-08-01 11:15:28.010612500 0030  00 00 00 00 00 00 1F 04  00 0D 35 62 36 31 63 65   ........ ..5b61ce

2018-08-01 11:15:28.010614500 0040  38 65 63 37 38 39 31 CE  03 00 01 00 00 00 1F 5B   8ec7891▒ .......[

2018-08-01 11:15:28.010628500 0050  22 61 63 74 69 76 65 20  73 63 72 69 70 74 3A 20   "active  script:

2018-08-01 11:15:28.010630500 0060  65 6D 61 69 6C 61 72 72  61 79 22 2C 31 5D CE      emailarr ay",1]▒

2018-08-01 11:15:28.010632500

2018-08-01 11:15:28.010706500 Command ["msieve","api","blah","blah"] basic_published at 11:15:28

2018-08-01 11:15:28.010799500 < 60,80:: Basic.ack

2018-08-01 11:15:28.010801500 < [hex]:

2018-08-01 11:15:28.010803500 0000  01 00 01 00 00 00 0D 00  3C 00 50 00 00 00 00 00   ........ <.P.....

2018-08-01 11:15:28.010805500 0010  00 02 43 00 CE                                     ..C.▒

2018-08-01 11:15:28.010807500

2018-08-01 11:15:28.010820500 < 60,80:: Basic.ack

2018-08-01 11:15:28.010830500 Command ["msieve","api","blah","blah"] basic_ack at 11:15:28

2018-08-01 11:15:28.010914500 waiting for any method

TCPDUMP ( client side ):

11:15:26.823436 IP 192.168.1.41.64922 > 192.168.1.24.5672: Flags [P.], seq 701:882, ack 733, win 1026, options [nop,nop,TS val 2891410654 ecr 2335968489], length 181

E.....@.@..}...).......(d..:.........m.....

.Wl..<..........<.(...shell.command.run........<.<.........H...application/json.5b61ce8ec7891.command.result.......H["msieve","api","blah","blah"].

But I don't see a response from the server!!

TCPDUMP ( server side )

I see the same packet as above, but no TCP packet being sent down the wire from the server to the client, despite the server-side script outputting debug information showing it should have been sent

RABBITMQLOGS:

2018-08-01 11:15:26.715 [info] <0.9804.2> accepting AMQP connection <0.9804.2> (192.168.1.41:64922 -> 192.168.1.24:5672)

2018-08-01 11:15:26.813 [info] <0.9804.2> connection <0.9804.2> (192.168.1.41:64922 -> 192.168.1.24:5672): user 'atech' authenticated and granted access to vhost '/'

2018-08-01 11:16:12.719 [info] <0.9804.2> closing AMQP connection <0.9804.2> (192.168.1.41:64922 -> 192.168.1.24:5672, vhost: '/', user: 'atech')

Has anyone encountered such an issue ?

[catharsis3k]

I would like to add that after more testing it seems unlikely that it's a PHP-AMQPLIB bug. I ran TCPDUMP between PHP Server and RabbitMQ process and it does forward the packets. It's the RabbitMQ process that doesn't send it further out back to the client

16:27:51.490133 IP 192.168.1.24.5672 > 192.168.1.24.34623: Flags [P.], seq 27803:28027, ack 17209, win 1276, options [nop,nop,TS val 2134985372 ecr 3712647025], length 224

E.....@.@............(.?..e=.f.............

.AJ..J.q......?.<.<.amq.ctag-NQqdjBr0lvdBSUlhGxL6cQ.......=..shell.command.run.......<.<.........M...application/json.5b6217c77690f.command.result.......M["msieve","api","blah","blah"].

16:27:53.808932 IP 192.168.1.24.34623 > 192.168.1.24.5672: Flags [P.], seq 17209:17320, ack 28027, win 1276, options [nop,nop,TS val 3712667275 ecr 2134985372], length 111

E.....@.@............?.(.f....f............

.J...AJ.........<.(...shell.command.result..........<.............5b6217c77690f........["active script: ",1].

How can I further debug the internals of RabbitMQ to see what it does with this response once it receives it ?

[Luke Bakken]

Hello,

Could you please let us know what version of RabbitMQ and PHP you are using? Are you using PHP with a web server or by running your scripts using the php command itself?

Providing all of your code so we can reproduce the issue, or a smaller set of code that reproduces it reliably will be the fastest way to get an answer.

Thanks,

Luke

[catharsis3k]

PHP-AMQPLIB is 2.7.2 on both client & server

RabbitMQ is 3.7.6

Client-side is Web-PHP

Server-side is a standalone PHP daemon.

The problem seemingly happens at random, I have no sure way to reproduce it except to give it a long repetitive task and wait for it to break. As I said above, this is the latest observed behavior: Server-side PHP Daemon sends the response info to Rabbit MQ as observed via TCPDUMP but RabbitMQ doesn't send it back to the client-side PHP. Then the client-side PHP times out after my set 45 seconds.

This is the server-side php code:

require $apipath . '/vendor/autoload.php';

use

PhpAmqpLib\Connection\AMQPStreamConnection,

PhpAmqpLib\Message\AMQPMessage;

define('AMQP_DEBUG', true);

// one connection

list($user, $pwd, $host, $port) = $_ = conf('rabbitmq.credentials.user, rabbitmq.credentials.password, rabbitmq.host, rabbitmq.port');

$connection = new AMQPStreamConnection($host, $port, $user, $pwd,'/',false,'AMQPLAIN',null,'en_US',3.0,180.0,null,false,0);

echo 'Connected to rabbitmq', PHP_EOL;

$RunCallback = function($req) use($connection){

    $Publish = function($data) use($req) {

        print "Command ".$req->body." Starting Delivery ".time()."\n";

        $channel = $req->delivery_info['channel'];

        $arguments = ['correlation_id' => $req->get('correlation_id')];

        $msg = new AMQPMessage(json_encode($data), $arguments);

        $channel->basic_publish($msg, 'shell', $req->get('reply_to'));

        print "Command ".$req->body." basic_published at ".time()."\n";

        $channel->basic_ack($req->delivery_info['delivery_tag']);

        print "Command ".$req->body." basic_ack at ".time()."\n";

    };

    $channel = $req->delivery_info['channel'];

    $routing_key = $req->get('routing_key');

    switch ($routing_key) {

        case 'command.run':

            $RunClass = '\Polaris\\Shell\\Run\\Command';

        break;

        default:

            $Publish(['invalid command', 1]);

            return;

        break;

    }

    $Method = new \ReflectionMethod($RunClass, 'execute');

    $args = json_decode($req->body, true);

    print "Starting Command ".$req->body." at ".time()."\n";

    $data = $Method->invokeArgs(new $RunClass, [$args]);

    print "Command ".$req->body." finished at ".time()."\n";

    // send back result

    $Publish($data);

};

$queues = ['command_run_queue' => 'command.run'];

// one channel

$channel = $connection->channel();

$channel->basic_qos(null, 1, null);

$channel->exchange_declare('shell', 'direct');

foreach ($queues as $queue_name => $bind_key) {

    $channel->queue_declare($queue_name, false, false, false, false);

    $channel->queue_bind($queue_name, 'shell', $bind_key);

    $channel->basic_consume($queue_name, '', false, false, false, false, $RunCallback);

}

while(count($channel->callbacks)) {

    $channel->wait();

}

$channel->close();

$connection->close();

[Luke Bakken]

Rabbit MQ as observed via TCPDUMP but RabbitMQ doesn't send it back to the client-side PHP.

Do you see the message enqueued in RabbitMQ at all? If RabbitMQ can't deliver the message to any queues, the message will be dropped. I strongly suspect that is what is happening here. Search the RabbitMQ docs for "unroutable" or "dropped" messages.

Thanks,

Luke

[catharsis3k]

I have full tracing enabled via the Tracing plugin. I see the message arriving within RabbitMQ but nothing after. Shouldn't there be a log entry if it was dropped ?

Below is a failed message. It's from PHP server to RabbitMQ. Please see below for a normal one.

2018-08-02 16:05:19:845: Message published

Node:         rabbit@central2

Connection:   192.168.1.24:18957 -> 192.168.1.24:5672

Virtual host: /

User:         gtech

Channel:      1

Exchange:     shell

Routing keys: [<<"command.result">>]

Routed queues: [<<"command_result_queue_5b632bbc66ddc">>]

Properties:   [{<<"correlation_id">>,longstr,<<"5b632bbc66dc6">>}]

Payload:

["active script:",1]

Working example. From PHP Server to Rabbit MQ, from RabbitMQ to PHP Client

================================================================================

2018-08-02 16:05:04:772: Message published

Node:         rabbit@central2

Connection:   192.168.1.24:18957 -> 192.168.1.24:5672

Virtual host: /

User:         gtech

Channel:      1

Exchange:     shell

Routing keys: [<<"command.result">>]

Routed queues: [<<"command_result_queue_5b632bac77281">>]

Properties:   [{<<"correlation_id">>,longstr,<<"5b632bac7725e">>}]

Payload:

["active script: ",1]

================================================================================

2018-08-02 16:05:04:772: Message received

Node:         rabbit@central2

Connection:   192.168.1.41:44739 -> 192.168.1.24:5672

Virtual host: /

User:         gtech

Channel:      1

Exchange:     shell

Routing keys: [<<"command.result">>]

Queue:        command_result_queue_5b632bac77281

Properties:   [{<<"correlation_id">>,longstr,<<"5b632bac7725e">>}]

Payload:

["active script: ",1]

[Luke Bakken]

Hello,

No, the tracing plugin doesn't log dropped messages. You'll see a publish.* message, but no corresponding deliver.* one, I believe (https://www.rabbitmq.com/firehose.html)

You can read more about detecting this scenario here: https://github.com/rabbitmq/rabbitmq-dotnet-client/issues/298

Please see the use of the mandatory flag here: https://www.rabbitmq.com/reliability.html#producer

Thanks,

Luke

[catharsis3k]

Thanks for that. I modified the code to use the mandatory flag: $channel->basic_publish($msg, 'shell', $req->get('reply_to'),1);

However the same behavior is happening and there is no exception raised.

Isn't there a way to configure RabbitMQ to just log and say: dropped this packet because XXX ? Seems like a fairly useful feature to me

[Luke Bakken]

At this point I'm not sure what's happening. I'm not sure how the PHP library behaves if a mandatory message isn't routable. Since the response is asynchronous to the publish the basic_publish call won't be able to throw an exception (depending on implementation). I recommend writing a small test application to confirm behavior.

You can configure RabbitMQ to route those messages to another destination via an Alternate Exchange: http://www.rabbitmq.com/ae.html

Be sure to have a queue bound to that exchange to receive the messages.

If the message is truly being published to a queue, and the consumer not receiving it, you should see messages accumulate in that queue. Have you observed this?

On Friday, August 3, 2018 at 7:07:33 AM UTC-7, catharsis3k

[catharsis3k]

I will try that too. I don't think it's a PHP library issue, or else I would have seen a packet in TCPDUMP from RabbitMQ sending the exception, but there is no such thing. I will try the Alternate Exchange and get back. Thank you!

[catharsis3k]

I have done that. There is no message accumulating in the 'test1' queue, despite the error showing up. Is it possible at this point this is a RabbitMQ bug ?

I setup a new exchange called 'my-ae'.

I setup the exchange to post to queue 'test1'

I setup the 'shell' exchange to have an AE of 'my-ae' via policy

Listing bindings for vhost /...

        exchange        amq.gen-ASEkA7-knMmEZ8vLjg1L4w  queue   amq.gen-ASEkA7-knMmEZ8vLjg1L4w  []

        exchange        command_run_queue       queue   command_run_queue       []

        exchange        test1   queue   test1   []

amq.rabbitmq.trace      exchange        amq.gen-ASEkA7-knMmEZ8vLjg1L4w  queue   #       []

my-ae   exchange        test1   queue           []

shell   exchange        command_run_queue       queue   command.run     []

Listing exchanges for vhost / ...

amq.match       headers

amq.rabbitmq.trace      topic

my-ae   direct

amq.fanout      fanout

amq.topic       topic

amq.headers     headers

        direct

amq.rabbitmq.log        topic

shell   direct

amq.direct      direct

Listing queues for vhost / ...

amq.gen-ASEkA7-knMmEZ8vLjg1L4w  0

command_run_queue       0

test1   0

Listing policies for vhost "/" ...

/       AE      ^shell$ all     {"alternate-exchange":"my-ae"}  0

[Michael Klishin]

I am confident in saying that this is almost certainly not a RabbitMQ bug. "No messages accumulating in a queue" almost

certainly mean those messages are not routed anywhere due to insufficient bindings or routing

key mismatches.

See the Listing bindings… section in the output. Are the bindings for the "test1" queue what your applications expect?

It is trivial to verify by registering a return handler and publishing messages as mandatory [1][2].

1. https://groups.google.com/forum/#!searchin/rabbitmq-users/messages$20are$20not$20routed$20mandatory%7Csort:date/rabbitmq-users/-LfhLUE9Y3I/fvp3BgcOAwAJ

2. https://github.com/php-amqplib/php-amqplib/blob/master/demo/amqp_publisher_with_confirms_mandatory.php

--
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

[catharsis3k]

Hi Michael,

Thanks for chiming in. 'test1' is not used by my application at all. I actually went through the following steps:

- Setup an Alternate Exchange for my main exchange in order to trap unroutable messages.

- test1 queue is bound to this 'AE'.

No application is consuming the messages from 'test1' so they should accumulate there, no ? Yet I see nothing and messages still disappear from my main exchange.

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]

They have to be routed there in order to accumulate. That was my point :)

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.

[catharsis3k]

Ok, but the doc page for AE says:

Whenever an exchange with a configured AE cannot route a message to any queue, it publishes the message to the specified AE instead.

So doesn't the routing happen automatically for my AE ?

My exchange can't route a message, it routes it to AE, AE pushes it into my 'test1' queue. At least that's how I understood it. What am I doing wrong ?

[Michael Klishin]

An AE is just a different exchange. It therefore routes using the same semantics:

type, routing key of the message, bindings (if applicable: some exchanges use hashing for routing, for example).

No magic is involved.

--

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.

[Luke Bakken]

Hello,

Something isn't quite adding up in the output you've provided. In your output, I see queues named with suffixes that appear to be random strings, like this;

command_result_queue_5b632bac77281

I don't see these queues in the binding list or queues list. In addition, the shell exchange is a direct exchange, meaning that messages will be routed to queues bound to that exchange if and only if the routing key of the message exactly matches the routing key of the bound queue. The messages you've posted show routing keys named like this:

command.result

Which, based on the exchanges and bindings you've shown, won't go anywhere, not even the alternate exchange, since your alternate exchange is also a direct exchange.

The first thing you should do is change your alternate exchange to a fanout exchange, since the routing keys will be ignored, and then re-bind the test1 queue to this exchange.

As Michael said earlier, there is little chance that this is a RabbitMQ bug and is still most likely an exchange type / queue binding / routing key misunderstanding or error.

Thanks,

Luke

[catharsis3k]

Why would I use fanout for an RPC model where I just want one worker to complete the task ?

The queues are created for each command I execute and they are not durable

$callback_queue = 'command_result_queue_' . uniqid();

$callback_bind_key = 'command.result';

$channel->queue_declare($callback_queue, false, false, true, false);

$channel->queue_bind($callback_queue, 'shell', $callback_bind_key);

$channel->basic_consume($callback_queue, '', false, false, false, false, [$this, 'respond']);

$data = json_encode($payload);

$msg = new AMQPMessage($data, ['correlation_id' => $this->id, 'reply_to' => $callback_bind_key, 'content_type' => 'application/json']);

This works, as I stated originally, 99.9% of the time. It's just on long repetitive tasks where something goes wrong. 

Lastly, since I've set that AE policy, wasn't that policy supposed to trap unroutable messages in the main exchange and deliver them to the AE ?

[Luke Bakken]

Hello,

Why would I use fanout for an RPC model where I just want one worker to complete the task ?

Please carefully re-read what I wrote. I suggested that you change your alternate exchange type to fanout, since the current exchange type for your alternate exchange (direct) won't route messages as you think it does. See my explanation below.

  

Lastly, since I've set that AE policy, wasn't that policy supposed to trap unroutable messages in the main exchange and deliver them to the AE ?

Your AE policy does specify an alternate exchange for unroutable messages, but the destination exchange must be able to route them! Since your destination exchange (my-ae) is a direct exchange, it will only publish messages to bound queues whose routing key matches the incoming messages' routing key. This is why I suggested changing it to fanout, since all messages are published to all bound queues (only one queue in your case, test1), no matter the routing key or other message attributes.

This works, as I stated originally, 99.9% of the time. It's just on long repetitive tasks where something goes wrong.

In this error case, perhaps your client's socket connection is timing out, which means your exclusive queue will disappear prior to receiving a response. Without being able to see all your code or have more detailed reproduction information, I'm speculating at this point.

Thanks,

Luke