search

cloudamqp / amqproxy

An intelligent AMQP proxy, with connection and channel pooling/reusing
https://www.cloudamqp.com
MIT License
342 stars 50 forks source link

Symfony 7 application log flooded with `UPSTREAM_DISCONNECTED` errors #162

Closed ghost closed 4 months ago

ghost commented 4 months ago

Upgraded to AMQProxy v2.0.0-rc.3 after https://github.com/cloudamqp/amqproxy/issues/157 was closed; however, Symfony 7 message consumers now flood the application log with the error below... does not happen when AMQProxy is bypassed:

RabbitMQ 3.13.2 PHP 8.2 Application: Mbin 1.5.3 - main branch (https://github.com/MbinOrg/mbin)

Symfony application log:

{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-09T15:27:57.842485+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-09T15:27:58.009160+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-09T15:27:58.097759+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-09T15:27:58.098612+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-09T15:27:58.116939+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-09T15:27:58.196919+00:00","extra":{}}

AMQProxy log flooded with adding upstream connections:


May 09 15:29:03 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44718"] Adding upstream connection
May 09 15:29:03 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44776"] Adding upstream connection
May 09 15:29:04 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44840"] Adding upstream connection
May 09 15:29:05 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45356"] Adding upstream connection
May 09 15:29:05 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45426"] Adding upstream connection
May 09 15:29:05 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45550"] Adding upstream connection
May 09 15:29:05 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45610"] Adding upstream connection
May 09 15:29:05 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45666"] Adding upstream connection
May 09 15:29:07 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:52494"] Adding upstream connection
May 09 15:29:14 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53068"] Adding upstream connection
May 09 15:29:14 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53126"] Adding upstream connection
May 09 15:29:15 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53608"] Adding upstream connection
May 09 15:29:15 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53630"] Adding upstream connection
May 09 15:29:15 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53650"] Adding upstream connection
May 09 15:29:15 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53748"] Adding upstream connection
May 09 15:29:15 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53830"] Adding upstream connection
May 09 15:29:17 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44768"] Adding upstream connection
May 09 15:29:18 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44860"] Adding upstream connection
May 09 15:29:18 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44938"] Adding upstream connection
May 09 15:29:18 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45186"] Adding upstream connection
May 09 15:29:18 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45230"] Adding upstream connection
May 09 15:29:18 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45350"] Adding upstream connection
May 09 15:29:18 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45412"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45556"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45794"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45824"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45890"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:46126"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:46286"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:46398"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:46438"] Adding upstream connection
May 09 15:29:19 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:46516"] Adding upstream connection
May 09 15:29:26 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:47492"] Adding upstream connection
May 09 15:29:29 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:43948"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44242"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44566"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44614"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44690"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44714"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44930"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45044"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45164"] Adding upstream connection
May 09 15:29:31 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45206"] Adding upstream connection
May 09 15:29:32 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45722"] Adding upstream connection
May 09 15:29:32 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45774"] Adding upstream connection
May 09 15:29:32 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45886"] Adding upstream connection
May 09 15:29:32 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:45972"] Adding upstream connection
May 09 15:29:32 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:46046"] Adding upstream connection
May 09 15:29:32 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:46116"] Adding upstream connection
May 09 15:29:36 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:46998"] Adding upstream connection
May 09 15:29:36 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:47126"] Adding upstream connection
May 09 15:29:36 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:47190"] Adding upstream connection
May 09 15:29:36 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:47274"] Adding upstream connection
May 09 15:29:36 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:47424"] Adding upstream connection
May 09 15:29:36 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:47512"] Adding upstream connection
May 09 15:29:36 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:47666"] Adding upstream connection
May 09 15:29:36 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:47752"] Adding upstream connection
May 09 15:29:44 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:52510"] Adding upstream connection
May 09 15:29:44 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:52532"] Adding upstream connection
May 09 15:29:44 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:52670"] Adding upstream connection
May 09 15:29:44 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:52840"] Adding upstream connection
May 09 15:29:45 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:52916"] Adding upstream connection
May 09 15:29:46 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53478"] Adding upstream connection
May 09 15:29:46 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53682"] Adding upstream connection
May 09 15:29:46 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53824"] Adding upstream connection
May 09 15:29:46 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:53994"] Adding upstream connection
May 09 15:29:54 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:55264"] Adding upstream connection
May 09 15:29:54 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:55308"] Adding upstream connection
May 09 15:30:01 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:43482"] Adding upstream connection
May 09 15:30:01 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:43680"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:43758"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:43834"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:43848"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44248"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44366"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44674"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44818"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44908"] Adding upstream connection
May 09 15:30:02 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:44930"] Adding upstream connection
May 09 15:30:39 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:41494"] Adding upstream connection
May 09 15:30:48 mbin-prod-01 amqproxy[793]: amq_proxy.channel_pool[remote_address: "127.0.0.1:38314"] Adding upstream connection
carlhoerberg commented 4 months ago

Thank you for reporting! Working on a fix

melroy89 commented 4 months ago

Confirmed.

{"message":"Error thrown while running command \"messenger:consume old async outbox deliver inbox resolve receive failed --time-limit=86400\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin.melroy.org/html/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin.melroy.org/html/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume old async outbox deliver inbox resolve receive failed --time-limit=86400","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-10T19:14:38.520352+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume old async outbox deliver inbox resolve receive failed --time-limit=86400\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin.melroy.org/html/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin.melroy.org/html/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume old async outbox deliver inbox resolve receive failed --time-limit=86400","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-10T19:14:38.757775+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume old async outbox deliver inbox resolve receive failed --time-limit=86400\". Message: \"Server channel error: 500, message: UPSTREAM_DISCONNECTED\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":0,"file":"/var/www/kbin.melroy.org/html/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED","code":500,"file":"/var/www/kbin.melroy.org/html/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume old async outbox deliver inbox resolve receive failed --time-limit=86400","message":"Server channel error: 500, message: UPSTREAM_DISCONNECTED"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-10T19:14:38.848143+00:00","extra":{}}
carlhoerberg commented 4 months ago

v2.0.0-rc.4 is out, should fix this

ghost commented 4 months ago

@carlhoerberg thanks, carl. v2.0.0-rc.4 seems to fix that error, but now i'm seeing the following error after updating:

application log:

{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:42.643460+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:42.643758+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:42.827618+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:42.870173+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:42.871952+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,19523,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,19523,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,19523,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,19523,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:42.874239+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:42.880425+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:42.888412+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPQueueException","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}","code":501,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"Server channel error: 501, message: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088}"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T01:50:43.162130+00:00","extra":{}}

amqproxy log:


May 11 01:50:31 mbin-prod-01 amqproxy[3956165]: amq_proxy.upstream[remote_address: "127.0.0.1:5672"] Upstream closed connection: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,18527,4088} 501
May 11 01:50:31 mbin-prod-01 amqproxy[3956165]: amq_proxy.channel_pool[remote_address: "127.0.0.1:52766"] Adding upstream connection
May 11 01:50:42 mbin-prod-01 amqproxy[3956165]: amq_proxy.upstream[remote_address: "127.0.0.1:5672"] Upstream closed connection: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088} 501
May 11 01:50:42 mbin-prod-01 amqproxy[3956165]: amq_proxy.channel_pool[remote_address: "127.0.0.1:56988"] Adding upstream connection
May 11 01:50:42 mbin-prod-01 amqproxy[3956165]: amq_proxy.upstream[remote_address: "127.0.0.1:5672"] Upstream closed connection: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,19523,4088} 501
May 11 01:50:42 mbin-prod-01 amqproxy[3956165]: amq_proxy.channel_pool[remote_address: "127.0.0.1:57048"] Adding upstream connection
May 11 01:51:11 mbin-prod-01 amqproxy[3956165]: amq_proxy.upstream[remote_address: "127.0.0.1:5672"] Upstream closed connection: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,12562,4088} 501
May 11 01:51:11 mbin-prod-01 amqproxy[3956165]: amq_proxy.channel_pool[remote_address: "127.0.0.1:49452"] Adding upstream connection
May 11 01:51:11 mbin-prod-01 amqproxy[3956165]: amq_proxy.upstream[remote_address: "127.0.0.1:5672"] Upstream closed connection: FRAME_ERROR - type 2, all octets = <<>>: {frame_too_large,19523,4088} 501
May 11 01:51:11 mbin-prod-01 amqproxy[3956165]: amq_proxy.channel_pool[remote_address: "127.0.0.1:49520"] Adding upstream connection
carlhoerberg commented 4 months ago

Ok, Thank you! Will look at it as soon as i can

carlhoerberg commented 4 months ago

Sorry about that, fixed in v2.0.0-rc.5

ghost commented 4 months ago

No worries, the only issue I have left after upgrading to v2.0.0-rc.5:

application log:

{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"invalid AMQP data\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"invalid AMQP data"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T12:36:14.171923+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"invalid AMQP data\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"invalid AMQP data"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T12:36:14.172414+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"invalid AMQP data\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"invalid AMQP data"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T12:36:14.172710+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"invalid AMQP data\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"invalid AMQP data"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T12:36:14.251249+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"invalid AMQP data\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"invalid AMQP data"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T12:36:14.251435+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"invalid AMQP data\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"invalid AMQP data"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T12:36:14.255146+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"invalid AMQP data\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"invalid AMQP data"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T12:36:14.254950+00:00","extra":{}}
{"message":"Error thrown while running command \"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600\". Message: \"invalid AMQP data\"","context":{"exception":{"class":"Symfony\\Component\\Messenger\\Exception\\TransportException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/AmqpReceiver.php:56","previous":{"class":"AMQPException","message":"invalid AMQP data","code":0,"file":"/var/www/kbin/vendor/symfony/amqp-messenger/Transport/Connection.php:432"}},"command":"messenger:consume scheduler_default old async outbox deliver inbox resolve receive failed --time-limit=3600","message":"invalid AMQP data"},"level":500,"level_name":"CRITICAL","channel":"console","datetime":"2024-05-11T12:36:14.256661+00:00","extra":{}}

v2.0.0-rc.5 log:

May 11 12:32:10 mbin-prod-01 systemd[1]: amqproxy.service: Deactivated successfully.
May 11 12:32:10 mbin-prod-01 systemd[1]: Stopped AMQProxy server for connection and channel pooling.
May 11 12:32:14 mbin-prod-01 systemd[1]: Started AMQProxy server for connection and channel pooling.
May 11 12:32:14 mbin-prod-01 amqproxy[2198046]: amq_proxy.server Proxy upstream: localhost:5672
May 11 12:32:14 mbin-prod-01 amqproxy[2198046]: amq_proxy.server Proxy listening on 127.0.0.1:5673
May 11 12:32:14 mbin-prod-01 amqproxy[2198046]: amq_proxy.channel_pool[remote_address: "127.0.0.1:41766"] Adding upstream connection

No errors in the amqproxy log... but the application does not generate these errors when amqproxy is bypassed... so I'm not sure what's going on, I'll try to investigate further.

carlhoerberg commented 4 months ago

Hmm, ok, then I need a wireshark/tcpdump dump to see what's going on: 

tcpdump -i <interface> -s 65535 -w <file> "port 5672 or port 5673"
ghost commented 4 months ago

See amqproxy_v2.0.0-rc.5_debug.pcap.zip attached.

I also included mbin_amqproxy_bypassed_debug.zip to see what a "normal" datastream looks like for reference. Interestingly, there is hardly any data passing when amqproxy is enabled... I guess because the Symfony application can't establish an AMQP connection with it.

amqproxy_v2.0.0-rc.5_debug.pcap.zip

mbin_amqproxy_bypassed_debug.zip

carlhoerberg commented 4 months ago

Thank you! I released v2.0.0-rc.6, but i doubt that will fix this issue. It's not possible to start the tcpdump earlier? Now it looks like it's just a couple of idle connections sitting doing nothing. What I would like to see is the data on the wire just before "invalid AMQP data".

ghost commented 4 months ago

Absolutely, see attached.

amqproxy_mbin_bootup.zip

carlhoerberg commented 4 months ago

Ok, the only thing i could see was that Basic.Get responses (Basic.Get-Ok, Header and Body frames) wasn't sent in the same TCP packet. When the client got a Basic.Get-Ok it immdeltly closed the socket. I changed that in v2.0.0-rc.7. Would you like to test again? And do the same type of tcpdump recording if it doesn't solve it?

carlhoerberg commented 4 months ago

or! now i see, looks like the headers of delivered/get message is larger than 4096bytes, so it's exceeds the max frame size...

carlhoerberg commented 4 months ago

working on a solution for that

carlhoerberg commented 4 months ago

v2.0.0-rc.8 is out that should fix this large Header frames! (But still allow clients with low frame_max)

ghost commented 4 months ago

Thanks for all the hard work! I'll open a new issue should I see something unexpected, but so far so good with v2.0.0-rc.8!