mosquito / aio-pika

AMQP 0.9 client designed for asyncio and humans.
https://aio-pika.readthedocs.org/
Apache License 2.0
1.18k stars 186 forks source link

Unable to set arguments for queue #165

Open Jacobh2 opened 5 years ago

Jacobh2 commented 5 years ago

Hey!

I'm unable to create/connect to a queue when providing arguments to the channel.declare_queue method.

If I don't provide any arguments, the connection works just fine and I can produce and consume messages. But if I create the queue beforehand with the arguments:

{
    'x-message-ttl': 4 * 7 * 24 * 3600 * 1000,
    'x-max-priority': 2
}

and then try to connect without the arguments, then I get an error as expected:

aio_pika.pika.exceptions.ChannelClosed: (406, "PRECONDITION_FAILED - inequivalent arg 'x-message-ttl' for queue 'text' in vhost '/': received none but current is the value '2419200000' of type 'long'")

I then add the needed arguments to my consumer, but it immediately gives me INFO 2018-11-27 12:52:17,269 aio_pika.pika.channel close 422 : Channel.close(0, Normal Shutdown) in the logs

Consumer method:

async def consume():
    connection = await aio_pika.connect_robust(host=HOST)

    async with connection:
        channel = await connection.channel()

        topic_logs_exchange = await channel.declare_exchange(name=EXCHANGE, type=EXCHANGE_TYPE)

        queue = await channel.declare_queue(name=QUEUE, durable=True, arguments={
            'x-message-ttl': 4 * 7 * 24 * 3600 * 1000,
            'x-max-priority': 2
        })

        await queue.bind(exchange=topic_logs_exchange, routing_key=ROUTING_KEY)

        async for message in queue:
            LOGGER.info("New message %s", message.body)

which I start with

asyncio.run(consume(), debug=True)

What am I doing wrong that makes the channel close immediately?

> pip show aio-pika
Name: aio-pika
Version: 4.6.4
Summary: Wrapper for the PIKA for asyncio and humans.
Home-page: UNKNOWN
Author: Dmitry Orlov <me@mosquito.su>
Author-email: me@mosquito.su
License: Apache Software License
Location: /usr/local/lib/python3.7/site-packages
Requires: yarl, shortuuid
Required-by:
> python --version -V
Python 3.7.0 (default, Sep  5 2018, 03:25:31)
[GCC 6.3.0 20170516]

Log:

consumer_1  | DEBUG      2018-11-27 12:58:44,794 asyncio                        __init__                             64  : Using selector: EpollSelector
consumer_1  | DEBUG      2018-11-27 12:58:44,796 aio_pika.connection            connect                              221 : Creating a new AMQP connection: amqp://guest:********@rabbitmq:5672//
consumer_1  | DEBUG      2018-11-27 12:58:44,796 aio_pika.pika.callback         add                                  164 : Added: {'callback': functools.partial(<bound method Connection._on_connection_refused of <RobustConnection: "amqp://guest:********@rabbitmq:5672//">>, <Future pending created at /usr/local/lib/python3.7/asyncio/base_events.py:377>), 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,797 aio_pika.pika.callback         add                                  164 : Added: {'callback': functools.partial(<bound method RobustConnection._on_connection_open of <RobustConnection: "amqp://guest:********@rabbitmq:5672//">>, <Future pending created at /usr/local/lib/python3.7/asyncio/base_events.py:377>), 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,797 aio_pika.pika.callback         add                                  164 : Added: {'callback': functools.partial(<bound method RobustConnection._on_connection_lost of <RobustConnection: "amqp://guest:********@rabbitmq:5672//">>, <Future pending created at /usr/local/lib/python3.7/asyncio/base_events.py:377>), 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,797 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Connection._on_connection_start of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | INFO       2018-11-27 12:58:44,800 aio_pika.pika.adapters.base_connection _create_and_connect_to_socket        212 : Connecting to 192.168.224.2:5672
consumer_1  | DEBUG      2018-11-27 12:58:44,802 asyncio                        _run_once                            1712: poll took 0.992 ms: 1 events
consumer_1  | DEBUG      2018-11-27 12:58:44,803 aio_pika.pika.callback         process                              220 : Processing 0:Connection.Start
consumer_1  | DEBUG      2018-11-27 12:58:44,803 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,804 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,804 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Connection._on_connection_start of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,804 aio_pika.pika.callback         process                              234 : Calling <bound method Connection._on_connection_start of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>> for "0:Connection.Start"
consumer_1  | DEBUG      2018-11-27 12:58:44,805 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Connection._on_connection_tune of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,806 asyncio                        _run_once                            1712: poll took 0.405 ms: 1 events
consumer_1  | DEBUG      2018-11-27 12:58:44,806 aio_pika.pika.callback         process                              220 : Processing 0:Connection.Tune
consumer_1  | DEBUG      2018-11-27 12:58:44,807 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,807 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,808 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Connection._on_connection_tune of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,808 aio_pika.pika.callback         process                              234 : Calling <bound method Connection._on_connection_tune of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>> for "0:Connection.Tune"
consumer_1  | DEBUG      2018-11-27 12:58:44,809 aio_pika.pika.connection       _create_heartbeat_checker            1003: Creating a HeartbeatChecker: 60
consumer_1  | DEBUG      2018-11-27 12:58:44,811 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Connection._on_connection_open of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,814 asyncio                        _run_once                            1716: poll 59996.602 ms took 0.758 ms: 1 events
consumer_1  | DEBUG      2018-11-27 12:58:44,816 aio_pika.pika.callback         process                              220 : Processing 0:Connection.OpenOk
consumer_1  | DEBUG      2018-11-27 12:58:44,817 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,818 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,819 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Connection._on_connection_open of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,820 aio_pika.pika.callback         process                              234 : Calling <bound method Connection._on_connection_open of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>> for "0:Connection.OpenOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,822 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Connection._on_connection_closed of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,823 aio_pika.pika.callback         process                              220 : Processing 0:_on_connection_open
consumer_1  | DEBUG      2018-11-27 12:58:44,824 aio_pika.pika.callback         process                              234 : Calling functools.partial(<bound method RobustConnection._on_connection_open of <RobustConnection: "amqp://guest:********@rabbitmq:5672//">>, <Future pending cb=[<TaskWakeupMethWrapper object at 0x7fbd1bf864c8>()] created at /usr/local/lib/python3.7/asyncio/base_events.py:377>) for "0:_on_connection_open"
consumer_1  | DEBUG      2018-11-27 12:58:44,825 aio_pika.connection            _on_connection_open                  173 : Connection ready: <RobustConnection: "amqp://guest:********@rabbitmq:5672//">
consumer_1  | DEBUG      2018-11-27 12:58:44,827 aio_pika.connection            channel                              297 : Creating AMQP channel for connection: <RobustConnection: "amqp://guest:********@rabbitmq:5672//">
consumer_1  | DEBUG      2018-11-27 12:58:44,828 aio_pika.connection            channel                              304 : Channel created: <RobustChannel "amqp://guest:********@rabbitmq:5672//#Not initialized channel">
consumer_1  | DEBUG      2018-11-27 12:58:44,829 aio_pika.adapter               _create_channel                      191 : Creating channel 1
consumer_1  | DEBUG      2018-11-27 12:58:44,829 aio_pika.pika.callback         add                                  164 : Added: {'callback': <function AsyncioConnection._create_channel.<locals>.<lambda> at 0x7fbd1b7e4bf8>, 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,830 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method AsyncioConnection._on_channel_cleanup of <aio_pika.adapter.AsyncioConnection object at 0x7fbd1bf85dd8>>, 'one_shot': True, 'only': <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,830 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_getempty of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,831 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_cancel of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,831 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_flow of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,832 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_close of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,832 aio_pika.pika.channel          _rpc                                 1130: Adding in on_synchronous_complete callback
consumer_1  | DEBUG      2018-11-27 12:58:44,833 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,833 aio_pika.pika.channel          _rpc                                 1135: Adding passed in callback
consumer_1  | DEBUG      2018-11-27 12:58:44,834 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_openok of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,835 asyncio                        _run_once                            1716: poll 59975.137 ms took 1.053 ms: 1 events
consumer_1  | DEBUG      2018-11-27 12:58:44,836 aio_pika.pika.callback         process                              220 : Processing 1:Channel.OpenOk
consumer_1  | DEBUG      2018-11-27 12:58:44,836 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,837 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,837 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,837 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,838 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,838 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Channel._on_openok of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,839 aio_pika.pika.callback         process                              234 : Calling <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>> for "1:Channel.OpenOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,839 aio_pika.pika.channel          _on_synchronous_complete             1088: 0 blocked frames
consumer_1  | DEBUG      2018-11-27 12:58:44,840 aio_pika.pika.callback         process                              234 : Calling <bound method Channel._on_openok of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>> for "1:Channel.OpenOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,842 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_delivery_confirmation of <RobustChannel "amqp://guest:********@rabbitmq:5672//#Not initialized channel">>, 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,842 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_delivery_confirmation of <RobustChannel "amqp://guest:********@rabbitmq:5672//#Not initialized channel">>, 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,842 aio_pika.pika.channel          _rpc                                 1130: Adding in on_synchronous_complete callback
consumer_1  | DEBUG      2018-11-27 12:58:44,843 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,843 aio_pika.pika.channel          _rpc                                 1135: Adding passed in callback
consumer_1  | DEBUG      2018-11-27 12:58:44,844 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_selectok of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,846 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_channel_close of <RobustChannel "amqp://guest:********@rabbitmq:5672//#Not initialized channel">>, 'one_shot': False, 'only': <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,848 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_return of <RobustChannel "amqp://guest:********@rabbitmq:5672//#Not initialized channel">>, 'one_shot': False, 'only': None, 'arguments': None}
consumer_1  | DEBUG      2018-11-27 12:58:44,851 asyncio                        _run_once                            1716: poll 59958.657 ms took 0.130 ms: 1 events
consumer_1  | DEBUG      2018-11-27 12:58:44,853 aio_pika.pika.callback         process                              220 : Processing 1:Confirm.SelectOk
consumer_1  | DEBUG      2018-11-27 12:58:44,854 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,855 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,856 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,858 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,858 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,860 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Channel._on_selectok of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,861 aio_pika.pika.callback         process                              234 : Calling <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>> for "1:Confirm.SelectOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,862 aio_pika.pika.channel          _on_synchronous_complete             1088: 1 blocked frames
consumer_1  | DEBUG      2018-11-27 12:58:44,862 aio_pika.pika.channel          _rpc                                 1130: Adding in on_synchronous_complete callback
consumer_1  | DEBUG      2018-11-27 12:58:44,863 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,863 aio_pika.pika.channel          _rpc                                 1135: Adding passed in callback
consumer_1  | DEBUG      2018-11-27 12:58:44,863 aio_pika.pika.callback         add                                  164 : Added: {'callback': <built-in method set_result of _asyncio.Future object at 0x7fbd1b156ec8>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,864 aio_pika.pika.callback         process                              234 : Calling <bound method Channel._on_selectok of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>> for "1:Confirm.SelectOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,864 aio_pika.pika.channel          _on_selectok                         1078: Confirm.SelectOk Received: <METHOD(['channel_number=1', 'frame_type=1', 'method=<Confirm.SelectOk>'])>
consumer_1  | DEBUG      2018-11-27 12:58:44,865 asyncio                        _run_once                            1716: poll 59944.743 ms took 0.130 ms: 1 events
consumer_1  | DEBUG      2018-11-27 12:58:44,866 aio_pika.pika.callback         process                              220 : Processing 1:Basic.QosOk
consumer_1  | DEBUG      2018-11-27 12:58:44,866 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,866 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,867 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,867 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,867 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,868 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <built-in method set_result of _asyncio.Future object at 0x7fbd1b156ec8>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,868 aio_pika.pika.callback         process                              234 : Calling <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>> for "1:Basic.QosOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,868 aio_pika.pika.channel          _on_synchronous_complete             1088: 0 blocked frames
consumer_1  | DEBUG      2018-11-27 12:58:44,869 aio_pika.pika.callback         process                              234 : Calling <built-in method set_result of _asyncio.Future object at 0x7fbd1b156ec8> for "1:Basic.QosOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,870 aio_pika.pika.channel          _rpc                                 1130: Adding in on_synchronous_complete callback
consumer_1  | DEBUG      2018-11-27 12:58:44,871 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,871 aio_pika.pika.channel          _rpc                                 1135: Adding passed in callback
consumer_1  | DEBUG      2018-11-27 12:58:44,871 aio_pika.pika.callback         add                                  164 : Added: {'callback': <built-in method set_result of _asyncio.Future object at 0x7fbd1b16a148>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,873 asyncio                        _run_once                            1716: poll 59937.203 ms took 0.762 ms: 1 events
consumer_1  | DEBUG      2018-11-27 12:58:44,874 aio_pika.pika.callback         process                              220 : Processing 1:Exchange.DeclareOk
consumer_1  | DEBUG      2018-11-27 12:58:44,874 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,875 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,875 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,876 aio_pika.pika.callback         _use_one_shot_callback               404 : Processing use of oneshot callback
consumer_1  | DEBUG      2018-11-27 12:58:44,876 aio_pika.pika.callback         _use_one_shot_callback               406 : 0 registered uses left
consumer_1  | DEBUG      2018-11-27 12:58:44,876 aio_pika.pika.callback         remove                               269 : Removing callback #0: {'callback': <built-in method set_result of _asyncio.Future object at 0x7fbd1b16a148>, 'one_shot': True, 'only': None, 'arguments': None, 'calls': 0}
consumer_1  | DEBUG      2018-11-27 12:58:44,877 aio_pika.pika.callback         process                              234 : Calling <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>> for "1:Exchange.DeclareOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,877 aio_pika.pika.channel          _on_synchronous_complete             1088: 0 blocked frames
consumer_1  | DEBUG      2018-11-27 12:58:44,878 aio_pika.pika.callback         process                              234 : Calling <built-in method set_result of _asyncio.Future object at 0x7fbd1b16a148> for "1:Exchange.DeclareOk"
consumer_1  | DEBUG      2018-11-27 12:58:44,883 aio_pika.channel               declare_exchange                     243 : Exchange declared <Exchange(message): auto_delete=False, durable=None, arguments={})>
consumer_1  | DEBUG      2018-11-27 12:58:44,886 aio_pika.queue                 declare                              77  : Declaring queue: <Queue(text): auto_delete=False, durable=True, exclusive=False, arguments={'x-message-ttl': 2419200000, 'x-max-priority': 2}>
consumer_1  | DEBUG      2018-11-27 12:58:44,888 aio_pika.pika.channel          _rpc                                 1130: Adding in on_synchronous_complete callback
consumer_1  | DEBUG      2018-11-27 12:58:44,888 aio_pika.pika.callback         add                                  164 : Added: {'callback': <bound method Channel._on_synchronous_complete of <aio_pika.adapter.Channel object at 0x7fbd1b7e0978>>, 'one_shot': True, 'only': None, 'arguments': {'queue': 'text'}, 'calls': 1}
consumer_1  | DEBUG      2018-11-27 12:58:44,890 aio_pika.pika.channel          _rpc                                 1135: Adding passed in callback
consumer_1  | DEBUG      2018-11-27 12:58:44,891 aio_pika.pika.callback         add                                  164 : Added: {'callback': <built-in method set_result of _asyncio.Future object at 0x7fbd1b176048>, 'one_shot': True, 'only': None, 'arguments': {'queue': 'text'}, 'calls': 1}
consumer_1  | INFO       2018-11-27 12:58:44,893 aio_pika.pika.channel          close                                422 : Channel.close(0, Normal Shutdown)
Jacobh2 commented 5 years ago

Ping @mosquito, would you have any ideas on this issue? I have tried again to connect to a rabbitmq queue using topic type and still get the problem where the channel gets closed for some strange reason.

mosquito commented 5 years ago

@Jacobh2 Could you create traffic dump, and send me it?

Jacobh2 commented 5 years ago

I changed the code a bit and was able to get a very interesting error finally:

consumer_1  | Traceback (most recent call last):
consumer_1  |   File "consumer2.py", line 58, in main
consumer_1  |     timeout=10
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/common.py", line 122, in wrap
consumer_1  |     return await func(self, *args, **kwargs)
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/channel.py", line 318, in declare_queue
consumer_1  |     await queue.declare(timeout)
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/common.py", line 122, in wrap
consumer_1  |     return await func(self, *args, **kwargs)
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/queue.py", line 92, in declare
consumer_1  |     exclusive=self.exclusive
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/channel.py", line 698, in queue_declare
consumer_1  |     replies)
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/channel.py", line 1139, in _rpc
consumer_1  |     self._send_method(method_frame)
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/channel.py", line 1150, in _send_method
consumer_1  |     self.connection._send_method(self.channel_number, method_frame, content)
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/connection.py", line 1569, in _send_method
consumer_1  |     self._send_frame(frame.Method(channel_number, method_frame))
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/connection.py", line 1550, in _send_frame
consumer_1  |     marshaled_frame = frame_value.marshal()
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/frame.py", line 74, in marshal
consumer_1  |     pieces = self.method.encode()
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/spec.py", line 1011, in encode
consumer_1  |     data.encode_table(pieces, self.arguments)
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/data.py", line 85, in encode_table
consumer_1  |     tablesize += encode_value(pieces, value)
consumer_1  |   File "/usr/local/lib/python3.7/site-packages/aio_pika/pika/data.py", line 122, in encode_value
consumer_1  |     pieces.append(struct.pack('>ci', b'I', value))
consumer_1  | struct.error: 'i' format requires -2147483648 <= number <= 2147483647
consumer_1  | DEBUG:aio_pika.connection:Closing AMQP connection

It looks like the problem is that this lib isn't following the RabbitMQ's AMQP protocol correctly. The doc says The argument can be of AMQP type short-short-int, short-int, long-int, or long-long-int.

And this error shows that the maximum value allowed is 2147483647, which is a 32 bit signed number, and not a 64 bit which is also allowed.

At first, when I had this issue 2 weeks ago, I also tested another lib, which I found had the exact same issue: https://github.com/Polyconseil/aioamqp/issues/180

Jacobh2 commented 5 years ago

@mosquito It seems like this error is caused because this lib is using an old version of Pika. The current version of Pika have a fix for this issue, whereas the version this lib is using has not

Do you think it is possible to update this lib's version of Pika?

mosquito commented 5 years ago

Actually versions newer then 0.10 are broken. You can find my issues on pika/pika.

Jacobh2 commented 5 years ago

Are you referring to this?

If the case is that this lib don't want to upgrade to keep in sync with the parent lib that it is based on, this lib will fall longer behind other bugfixes, for example this one that I found now. It seems like the authors of pika really wants this and it to be in sync and work together which sounds amazing!

Either way, with the current version of Pika that is being used, this lib is not following the AMQP protocol.

muhrin commented 4 years ago

I'm also experiencing this issues, probably in connection with #197 .

My configuration: aio-pika 6.4.1, and so nothing to do with the pika library now that aio-pika doesn't depend on it anymore.

The fault appeas when using rabbitmq 3.5.7 (as provided by Ubuntu 16.04) but not 3.6.10 (as provided by Ubuntu 18.04). MWE:

import logging
from . import BaseTestCase
log = logging.getLogger(__name__)

class TestCase(BaseTestCase):
    async def test_declare_queue(self):
        connection = await self.create_connection()

        channel = await connection.channel()

        # Declaring queue
        await channel.declare_queue(
            'task_queue',
            exclusive=True,
            arguments={'x-message-ttl': 60000}
        )

Producing the following traceback:

_________________________ TestCase.test_declare_queue __________________________
self = <TaskWrapper: <Task cancelled coro=<rpc() done, defined at /home/travis/virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/channel.py:96>>>
    async def __inner(self):
        try:
>           return await self.task
E           concurrent.futures._base.CancelledError
../../../virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/base.py:25: CancelledError
The above exception was the direct cause of the following exception:
self = <tests.test_amqp.TestCase testMethod=test_declare_queue>
    async def test_declare_queue(self):
        connection = await self.create_connection()

        channel = await connection.channel()

        # Declaring queue
        await channel.declare_queue(
            'task_queue',
            exclusive=True,
>           arguments={'x-message-ttl': 60000}
        )
tests/test_amqp.py:18: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
aio_pika/channel.py:261: in declare_queue
    await queue.declare(timeout=timeout)
aio_pika/queue.py:87: in declare
    ), timeout=timeout
/opt/python/3.6.7/lib/python3.6/asyncio/tasks.py:339: in wait_for
    return (yield from fut)
../../../virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/channel.py:636: in queue_declare
    arguments=arguments,
../../../virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/base.py:168: in wrap
    return await self.create_task(func(self, *args, **kwargs))
../../../virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/base.py:27: in __inner
    raise self.exception from e
/opt/python/3.6.7/lib/python3.6/asyncio/tasks.py:537: in _wrap_awaitable
    return (yield from awaitable.__await__())
../../../virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/base.py:27: in __inner
    raise self.exception from e
/opt/python/3.6.7/lib/python3.6/asyncio/tasks.py:537: in _wrap_awaitable
    return (yield from awaitable.__await__())
../../../virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/base.py:27: in __inner
    raise self.exception from e
../../../virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/connection.py:377: in __reader
    weight, channel, frame = await self.__receive_frame()
../../../virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/connection.py:329: in __receive_frame
    frame_header = await self.reader.readexactly(1)
/opt/python/3.6.7/lib/python3.6/asyncio/streams.py:674: in readexactly
    yield from self._wait_for_data('readexactly')
/opt/python/3.6.7/lib/python3.6/asyncio/streams.py:464: in _wait_for_data
    yield from self._waiter
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
self = <_SelectorSocketTransport closed fd=13>
    def _read_ready(self):
        if self._conn_lost:
            return
        try:
>           data = self._sock.recv(self.max_size)
E           ConnectionResetError: [Errno 104] Connection reset by peer
/opt/python/3.6.7/lib/python3.6/asyncio/selector_events.py:725: ConnectionResetError
----------------------------- Captured stderr call -----------------------------
DEBUG:asyncio:Using selector: EpollSelector
DEBUG:aio_pika.connection:Creating AMQP channel for connection: <Connection: "amqp://guest:******@localhost">
DEBUG:aio_pika.connection:Channel created: <Channel "None#Not initialized channel">
DEBUG:aio_pika.queue:Declaring queue: <Queue(task_queue): auto_delete=False, durable=None, exclusive=True, arguments={'x-message-ttl': 60000}>
DEBUG:aiormq.connection:Reader task exited because:
Traceback (most recent call last):
  File "/home/travis/virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/connection.py", line 377, in __reader
    weight, channel, frame = await self.__receive_frame()
  File "/home/travis/virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/connection.py", line 329, in __receive_frame
    frame_header = await self.reader.readexactly(1)
  File "/opt/python/3.6.7/lib/python3.6/asyncio/streams.py", line 674, in readexactly
    yield from self._wait_for_data('readexactly')
  File "/opt/python/3.6.7/lib/python3.6/asyncio/streams.py", line 464, in _wait_for_data
    yield from self._waiter
  File "/opt/python/3.6.7/lib/python3.6/asyncio/selector_events.py", line 725, in _read_ready
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 104] Connection reset by peer
DEBUG:aio_pika.connection:Closing AMQP connection None
------------------------------ Captured log call -------------------------------
selector_events.py          65 DEBUG    Using selector: EpollSelector
connection.py              184 DEBUG    Creating AMQP channel for connection: <Connection: "amqp://guest:******@localhost">
connection.py              191 DEBUG    Channel created: <Channel "None#Not initialized channel">
queue.py                    81 DEBUG    Declaring queue: <Queue(task_queue): auto_delete=False, durable=None, exclusive=True, arguments={'x-message-ttl': 60000}>
connection.py              412 DEBUG    Reader task exited because:
Traceback (most recent call last):
  File "/home/travis/virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/connection.py", line 377, in __reader
    weight, channel, frame = await self.__receive_frame()
  File "/home/travis/virtualenv/python3.6.7/lib/python3.6/site-packages/aiormq/connection.py", line 329, in __receive_frame
    frame_header = await self.reader.readexactly(1)
  File "/opt/python/3.6.7/lib/python3.6/asyncio/streams.py", line 674, in readexactly
    yield from self._wait_for_data('readexactly')
  File "/opt/python/3.6.7/lib/python3.6/asyncio/streams.py", line 464, in _wait_for_data
    yield from self._waiter
  File "/opt/python/3.6.7/lib/python3.6/asyncio/selector_events.py", line 725, in _read_ready
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 104] Connection reset by peer
connection.py              105 DEBUG    Closing AMQP connection None
=========================== 1 failed in 0.45 seconds ===========================

The full travis log can be found here: https://travis-ci.com/muhrin/aio-pika/jobs/268539430

Is there any way to currently to get such an x-message-ttl configuration working without monkey patching aiormq?

muhrin commented 4 years ago

Just checked with 'x-message-ttl': 66000 and it works fine (https://travis-ci.com/muhrin/aio-pika/jobs/268557081) so indeed the same failure mode as #197 but in this case all the way up to RabbitMQ 3.5.