rabbitmq:3.9.0 docker, client keep complain disconnect from server

[PingHao]

I just pull and ran 3.9.0 container today, and let celery use it for task queue. for every celery task sent out, the celery worker always report a error message it's disconnected from rabbitmq server, then it recover from it. I tried run 3.9.0 and 3.9.0-alpine, same result, and tried on two different server, one centos 7 , another centos8, same error.

however by switch to 3.8.9 image, everything is fine.

here it's linux dmesg output, my guess is somehow the 3.9.0 version cause docker's veth interface temporary down .

[Wed Jul 28 15:27:00 2021] docker0: port 1(vetha2ca9f3) entered blocking state
[Wed Jul 28 15:27:00 2021] docker0: port 1(vetha2ca9f3) entered disabled state
[Wed Jul 28 15:27:00 2021] device vetha2ca9f3 entered promiscuous mode
[Wed Jul 28 15:27:00 2021] IPv6: ADDRCONF(NETDEV_UP): vetha2ca9f3: link is not ready
[Wed Jul 28 15:27:00 2021] eth0: renamed from veth5dd6688
[Wed Jul 28 15:27:00 2021] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[Wed Jul 28 15:27:00 2021] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[Wed Jul 28 15:27:00 2021] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[Wed Jul 28 15:27:00 2021] IPv6: ADDRCONF(NETDEV_CHANGE): vetha2ca9f3: link becomes ready
[Wed Jul 28 15:27:00 2021] docker0: port 1(vetha2ca9f3) entered blocking state
[Wed Jul 28 15:27:00 2021] docker0: port 1(vetha2ca9f3) entered forwarding state
[Wed Jul 28 15:27:00 2021] userif-3: sent link down event.
[Wed Jul 28 15:27:00 2021] userif-3: sent link up event.

[wglambert]

That would be due to #467

Reasoning behind the change #506 (comment)

[PingHao]

That would be due to #467

Reasoning behind the change #506 (comment)

Do you mean it's configuration issue? BTW my test use default config, the command line is
docker run -d --name=rabbitmq -p 5672:5672 -p 15672:15672 rabbitmq:3.9.0

[wglambert]

The environment variables change would be the notable change that we implemented, if it's not related to that then it could be changes having to do with the 3.9 release itself.

$ docker run -d --name=rabbitmq -p 5672:5672 -p 15672:15672 rabbitmq:3.9.0
Unable to find image 'rabbitmq:3.9.0' locally
3.9.0: Pulling from library/rabbitmq
16ec32c2132b: Pull complete 
3adbc39b91c4: Pull complete 
2611ca544d44: Pull complete 
d28525f31fbf: Pull complete 
a505e26510db: Pull complete 
bb9850617192: Pull complete 
30c794338f65: Pull complete 
0ea3c2c93893: Pull complete 
b108568dff1d: Pull complete 
Digest: sha256:6c75795de210cd5efd63a3014bd91c350c8d581d55834ed6217d259f3c14c77a
Status: Downloaded newer image for rabbitmq:3.9.0
19dc39f100bb8083173c9d87665117bcf0b0d852c1e0867137f0dcce9ba6815a

logs

$ docker logs rabbitmq 2>&1 | tail -n 7
2021-07-28 21:38:17.160553+00:00 [info] <0.671.0> Ready to start client connection listeners
2021-07-28 21:38:17.164306+00:00 [info] <0.748.0> started TCP listener on [::]:5672
 completed with 3 plugins.
2021-07-28 21:38:17.458345+00:00 [info] <0.671.0> Server startup complete; 3 plugins started.
2021-07-28 21:38:17.458345+00:00 [info] <0.671.0>  * rabbitmq_prometheus
2021-07-28 21:38:17.458345+00:00 [info] <0.671.0>  * rabbitmq_web_dispatch
2021-07-28 21:38:17.458345+00:00 [info] <0.671.0>  * rabbitmq_management_agent

$ dmesg | tail -n 40
[1762768.075546] vethafda9e2: renamed from eth0
[1762768.181036] docker0: port 1(veth870c6c0) entered disabled state
[1762768.185918] device veth870c6c0 left promiscuous mode
[1762768.185925] docker0: port 1(veth870c6c0) entered disabled state
[1762771.085338] device veth6bedd7e entered promiscuous mode
[1762771.186829] IPVS: Creating netns size=2104 id=267523
[1762771.385393] eth0: renamed from veth99505e1
[1762771.408687] docker0: port 1(veth6bedd7e) entered forwarding state
[1762771.408697] docker0: port 1(veth6bedd7e) entered forwarding state
[1762771.676983] veth99505e1: renamed from eth0
[1762771.725400] docker0: port 1(veth6bedd7e) entered disabled state
[1762771.755758] docker0: port 1(veth6bedd7e) entered disabled state
[1762771.761515] device veth6bedd7e left promiscuous mode
[1762771.761524] docker0: port 1(veth6bedd7e) entered disabled state
[1762780.751245] IPv6: ADDRCONF(NETDEV_UP): pwdbr-7b78f1a7: link is not ready
[1762786.845599] device veth50ec4ab entered promiscuous mode
[1762786.845860] IPv6: ADDRCONF(NETDEV_UP): veth50ec4ab: link is not ready
[1762786.863959] device vethph776c62229 entered promiscuous mode
[1762786.864182] IPv6: ADDRCONF(NETDEV_UP): vethph776c62229: link is not ready
[1762786.864209] pwdbr-7b78f1a7: port 1(vethph776c62229) entered forwarding state
[1762786.864217] pwdbr-7b78f1a7: port 1(vethph776c62229) entered forwarding state
[1762786.864579] pwdbr-7b78f1a7: port 1(vethph776c62229) entered disabled state
[1762786.944071] IPVS: Creating netns size=2104 id=267524
[1762787.345174] eth0: renamed from vethpp776c62229
[1762787.389305] IPv6: ADDRCONF(NETDEV_CHANGE): vethph776c62229: link becomes ready
[1762787.389488] pwdbr-7b78f1a7: port 1(vethph776c62229) entered forwarding state
[1762787.389495] pwdbr-7b78f1a7: port 1(vethph776c62229) entered forwarding state
[1762787.389541] IPv6: ADDRCONF(NETDEV_CHANGE): pwdbr-7b78f1a7: link becomes ready
[1762787.413566] eth1: renamed from veth020c604
[1762787.437034] IPv6: ADDRCONF(NETDEV_CHANGE): veth50ec4ab: link becomes ready
[1762787.437268] docker_gwbridge: port 35(veth50ec4ab) entered forwarding state
[1762787.437324] docker_gwbridge: port 35(veth50ec4ab) entered forwarding state
[1762802.396018] pwdbr-7b78f1a7: port 1(vethph776c62229) entered forwarding state
[1762802.460046] docker_gwbridge: port 35(veth50ec4ab) entered forwarding state
[1762810.011981] device veth3f8aa51 entered promiscuous mode
[1762810.285015] IPVS: Creating netns size=2104 id=267525
[1762810.696385] eth0: renamed from veth7d9c013
[1762810.761363] docker0: port 1(veth3f8aa51) entered forwarding state
[1762810.761385] docker0: port 1(veth3f8aa51) entered forwarding state
[1762825.788024] docker0: port 1(veth3f8aa51) entered forwarding state

[PingHao]

Just test with python pika 1.2.0, the producer and consumer works fine with rabbitmq 3.9.0. so guess it's may related to celery (as rabbitmq client)?
anyway same python environment works fine with 3.8.9, it's seems to me 3.9.0 have some compatibility issue with python package amqp.

$pip list
amqp (5.0.6)
billiard (3.6.4.0)
cached-property (1.5.2)
celery (5.1.2)
click (7.1.2)
click-didyoumean (0.0.3)
click-plugins (1.1.1)
click-repl (0.2.0)
importlib-metadata (4.6.1)
kombu (5.1.0)
pip (9.0.3)
prompt-toolkit (3.0.19)
pytz (2021.1)
setuptools (39.2.0)
six (1.16.0)
typing-extensions (3.10.0.0)
vine (5.0.0)
wcwidth (0.2.5)
zipp (3.5.0)

the error message

[2021-07-28 17:52:22,696: WARNING/MainProcess] consumer: Connection to broker lost. Trying to re-establish the connection...
Traceback (most recent call last):
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/celery/worker/consumer/consumer.py", line 326, in start
    blueprint.start(self)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/celery/bootsteps.py", line 116, in start
    step.start(parent)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/celery/worker/consumer/consumer.py", line 618, in start
    c.loop(*c.loop_args())
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/celery/worker/loops.py", line 81, in asynloop
    next(loop)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/kombu/asynchronous/hub.py", line 361, in create_loop
    cb(*cbargs)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/kombu/transport/base.py", line 235, in on_readable
    reader(loop)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/kombu/transport/base.py", line 217, in _read
    drain_events(timeout=0)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/amqp/connection.py", line 523, in drain_events
    while not self.blocking_read(timeout):
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/amqp/connection.py", line 529, in blocking_read
    return self.on_inbound_frame(frame)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/amqp/method_framing.py", line 53, in on_frame
    callback(channel, method_sig, buf, None)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/amqp/connection.py", line 536, in on_inbound_method
    method_sig, payload, content,
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/amqp/abstract_channel.py", line 143, in dispatch_method
    listener(*args)
  File "/home/testuser/venv-celery/lib64/python3.6/site-packages/amqp/connection.py", line 666, in _on_close
    (class_id, method_id), ConnectionError)
amqp.exceptions.InternalError: (0, 0): (541) INTERNAL_ERROR
[2021-07-28 17:52:22,699: WARNING/MainProcess] /home/testuser/venv-celery/lib64/python3.6/site-packages/celery/worker/consumer/consumer.py:361: CPending
DeprecationWarning:
In Celery 5.1 we introduced an optional breaking change which
on connection loss cancels all currently executed tasks with late acknowledgement enabled.
These tasks cannot be acknowledged as the connection is gone, and the tasks are automatically redelivered back to the queue.
You can enable this behavior using the worker_cancel_long_running_tasks_on_connection_loss setting.
In Celery 5.1 it is set to False by default. The setting will be set to True by default in Celery 6.0.

  warnings.warn(CANCEL_TASKS_BY_DEFAULT, CPendingDeprecationWarning)

[michaelklishin]

@PingHao you don't have to guess. See node logs and the connectivity troubleshooting for clues.

There are no Python library incompatibilities in RabbitMQ 3.9.0 as there are no AMQP 0-9-1 protocol changes of any kind.
This image, however, dropped support for a whole lot of environment variables. Most likely for your environment,
it means a remote connection for the default user is tried. Node logs will tell.

[PingHao]

@michaelklishin Thanks your feedback. I was use 'guest' user. however, just tried create new user, give permission then ran with it, the problem still same. here are docker logs shows what's happening with user "testuser", the reason given as "reached_max_restart_intensity", not sure how to overcome that.

btw I also test with pika python client, a simple producer and consumer pair keep push message, that's works fine, without any error produced in rabbitmq log.

2021-07-29 16:09:13.268329+00:00 [info] <0.29159.0> accepting AMQP connection <0.29159.0> (172.20.132.124:60570 -> 172.17.0.2:5672)
2021-07-29 16:09:13.269991+00:00 [info] <0.29159.0> connection <0.29159.0> (172.20.132.124:60570 -> 172.17.0.2:5672): user 'testuser' authenticated and granted access to vhost '/'
2021-07-29 16:09:13.276074+00:00 [info] <0.29167.0> accepting AMQP connection <0.29167.0> (172.20.132.124:60572 -> 172.17.0.2:5672)
2021-07-29 16:09:13.277329+00:00 [info] <0.29167.0> connection <0.29167.0> (172.20.132.124:60572 -> 172.17.0.2:5672): user 'testuser' authenticated and granted access to vhost '/'
2021-07-29 16:09:13.287770+00:00 [info] <0.29184.0> accepting AMQP connection <0.29184.0> (172.20.132.124:60574 -> 172.17.0.2:5672)
2021-07-29 16:09:13.289180+00:00 [info] <0.29184.0> connection <0.29184.0> (172.20.132.124:60574 -> 172.17.0.2:5672): user 'testuser' authenticated and granted access to vhost '/'

2021-07-29 16:09:34.399347+00:00 [info] <0.29234.0> accepting AMQP connection <0.29234.0> (172.20.132.124:60640 -> 172.17.0.2:5672)
2021-07-29 16:09:34.400991+00:00 [info] <0.29234.0> connection <0.29234.0> (172.20.132.124:60640 -> 172.17.0.2:5672): user 'testuser' authenticated and granted access to vhost '/'
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0> ** Generic server <0.29174.0> terminating
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0> ** Last message in was {'$gen_cast',
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                            {method,{'basic.ack',1,false},none,noflow}}
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0> ** When Server state == {ch,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          {conf,running,rabbit_framing_amqp_0_9_1,1,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           <0.29159.0>,<0.29172.0>,<0.29159.0>,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           <<"172.20.132.124:60570 -> 172.17.0.2:5672">>,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           undefined,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           {user,<<"testuser">>,[],
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                            [{rabbit_auth_backend_internal,none}]},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           <<"/">>,<<"celery">>,<0.29160.0>,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           [{<<"consumer_cancel_notify">>,bool,true},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                            {<<"connection.blocked">>,bool,true},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                            {<<"authentication_failure_close">>,bool,true}],
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           none,0,134217728,1800000,#{},1000000000},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          {lstate,<0.29173.0>,true},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          none,2,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          {1,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           {[{pending_ack,1,<<"None4">>,1627574974403,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                              {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                              9}],
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                            []}},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          {state,#{},erlang},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          #{<<"None4">> =>
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                             {{amqqueue,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                               {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                               true,false,none,[],<0.1555.0>,[],[],[],
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                               undefined,undefined,[],[],live,0,[],<<"/">>,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                               #{user => <<"guest">>},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                               rabbit_classic_queue,#{}},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                              {false,0,false,[]}}},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          #{{resource,<<"/">>,queue,<<"celery">>} =>
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                             {1,{<<"None4">>,nil,nil}}},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          {state,fine,5000,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           #Ref<0.1730965543.1237057538.227857>},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          false,1,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          {rabbit_confirms,undefined,#{}},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          [],[],none,flow,[],
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          {rabbit_queue_type,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           #{{resource,<<"/">>,queue,<<"celery">>} =>
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                              {ctx,rabbit_classic_queue,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                               {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                               {rabbit_classic_queue,<0.1555.0>,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                                {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                                #{}}}},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                           #{<0.1555.0> =>
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                              {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                             <0.29178.0> =>
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                              {resource,<<"/">>,queue,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                               <<"b8688b85-cd24-3a77-803f-c47bff07dbeb.reply.celery.pidbox">>}}},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                          #Ref<0.1730965543.1237057538.227856>,false}
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0> ** Reason for termination ==
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0> ** {function_clause,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>        [{rabbit_channel,'-notify_limiter/2-fun-0-',
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>             [{pending_ack,1,<<"None4">>,1627574974403,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                  {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>                  9},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>              0],
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>             [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>         {lists,foldl,3,[{file,"lists.erl"},{line,1267}]},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>         {rabbit_channel,notify_limiter,2,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>             [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>         {rabbit_channel,ack,2,[{file,"src/rabbit_channel.erl"},{line,2057}]},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>         {rabbit_channel,handle_method,3,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>             [{file,"src/rabbit_channel.erl"},{line,1343}]},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>         {rabbit_channel,handle_cast,2,
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>             [{file,"src/rabbit_channel.erl"},{line,644}]},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>         {gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1067}]},
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>         {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}
2021-07-29 16:09:34.408530+00:00 [erro] <0.29174.0>
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>   crasher:
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     initial call: rabbit_channel:init/1
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     pid: <0.29174.0>
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     registered_name: []
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     exception exit: {function_clause,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                         [{rabbit_channel,'-notify_limiter/2-fun-0-',
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                              [{pending_ack,1,<<"None4">>,1627574974403,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                                   {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                                   9},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                               0],
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                              [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          {lists,foldl,3,[{file,"lists.erl"},{line,1267}]},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          {rabbit_channel,notify_limiter,2,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                              [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          {rabbit_channel,ack,2,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                              [{file,"src/rabbit_channel.erl"},{line,2057}]},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          {rabbit_channel,handle_method,3,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                              [{file,"src/rabbit_channel.erl"},{line,1343}]},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          {rabbit_channel,handle_cast,2,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                              [{file,"src/rabbit_channel.erl"},{line,644}]},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          {gen_server2,handle_msg,2,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                              [{file,"src/gen_server2.erl"},{line,1067}]},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          {proc_lib,wake_up,3,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                              [{file,"proc_lib.erl"},{line,236}]}]}
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>       in function  gen_server2:terminate/3 (src/gen_server2.erl, line 1183)
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     ancestors: [<0.29171.0>,<0.29163.0>,<0.29158.0>,<0.29157.0>,<0.830.0>,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   <0.829.0>,<0.828.0>,<0.826.0>,<0.825.0>,rabbit_sup,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   <0.222.0>]
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     message_queue_len: 0
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     messages: []
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     links: [<0.29171.0>]
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     dictionary: [{credit_blocked,[]},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   {rand_seed,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                       {#{jump => #Fun<rand.3.92093067>,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          max => 288230376151711743,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                          next => #Fun<rand.5.92093067>,type => exsplus},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                        [463472712153784|143667563729387478]}},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   {process_name,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                       {rabbit_channel,
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                           {<<"172.20.132.124:60570 -> 172.17.0.2:5672">>,1}}},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   {{xtype_to_module,direct},rabbit_exchange_type_direct},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   {{queue_stats,{resource,<<"/">>,queue,<<"celery">>}},none},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   {msg_size_for_gc,83},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   {permission_cache_can_expire,false},
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>                   {channel_operation_timeout,15000}]
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     trap_exit: true
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     status: running
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     heap_size: 10958
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     stack_size: 29
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>     reductions: 92501
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>   neighbours:
2021-07-29 16:09:34.409461+00:00 [erro] <0.29174.0>
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0> Error on AMQP connection <0.29159.0> (172.20.132.124:60570 -> 172.17.0.2:5672, vhost: '/', user: 'testuser', state: running), channel 1:
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>  {function_clause,
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>     [{rabbit_channel,'-notify_limiter/2-fun-0-',
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>          [{pending_ack,1,<<"None4">>,1627574974403,
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>               {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>               9},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>           0],
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>          [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>      {lists,foldl,3,[{file,"lists.erl"},{line,1267}]},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>      {rabbit_channel,notify_limiter,2,
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>          [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>      {rabbit_channel,ack,2,[{file,"src/rabbit_channel.erl"},{line,2057}]},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>      {rabbit_channel,handle_method,3,
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>          [{file,"src/rabbit_channel.erl"},{line,1343}]},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>      {rabbit_channel,handle_cast,2,
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>          [{file,"src/rabbit_channel.erl"},{line,644}]},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>      {gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1067}]},
2021-07-29 16:09:34.410641+00:00 [erro] <0.29159.0>      {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>     supervisor: {<0.29171.0>,rabbit_channel_sup}
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>     errorContext: child_terminated
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>     reason: {function_clause,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                 [{rabbit_channel,'-notify_limiter/2-fun-0-',
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                      [{pending_ack,1,<<"None4">>,1627574974403,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                           {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                           9},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                       0],
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                      [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                  {lists,foldl,3,[{file,"lists.erl"},{line,1267}]},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                  {rabbit_channel,notify_limiter,2,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                      [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                  {rabbit_channel,ack,2,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                      [{file,"src/rabbit_channel.erl"},{line,2057}]},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                  {rabbit_channel,handle_method,3,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                      [{file,"src/rabbit_channel.erl"},{line,1343}]},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                  {rabbit_channel,handle_cast,2,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                      [{file,"src/rabbit_channel.erl"},{line,644}]},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                  {gen_server2,handle_msg,2,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                      [{file,"src/gen_server2.erl"},{line,1067}]},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                  {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>     offender: [{pid,<0.29174.0>},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                {id,channel},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                {mfargs,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                    {rabbit_channel,start_link,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                        [1,<0.29159.0>,<0.29172.0>,<0.29159.0>,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                         <<"172.20.132.124:60570 -> 172.17.0.2:5672">>,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                         rabbit_framing_amqp_0_9_1,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                         {user,<<"testuser">>,[],
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                             [{rabbit_auth_backend_internal,none}]},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                         <<"/">>,
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                         [{<<"consumer_cancel_notify">>,bool,true},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                          {<<"connection.blocked">>,bool,true},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                          {<<"authentication_failure_close">>,bool,true}],
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                         <0.29160.0>,<0.29173.0>]}},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                {restart_type,intrinsic},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                {shutdown,70000},
2021-07-29 16:09:34.410316+00:00 [erro] <0.29171.0>                {child_type,worker}]
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0> Non-AMQP exit reason '{function_clause,
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                           [{rabbit_channel,'-notify_limiter/2-fun-0-',
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                [{pending_ack,1,<<"None4">>,1627574974403,
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                     {resource,<<"/">>,queue,<<"celery">>},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                     9},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                 0],
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                            {lists,foldl,3,[{file,"lists.erl"},{line,1267}]},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                            {rabbit_channel,notify_limiter,2,
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                [{file,"src/rabbit_channel.erl"},{line,2124}]},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                            {rabbit_channel,ack,2,
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                [{file,"src/rabbit_channel.erl"},{line,2057}]},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                            {rabbit_channel,handle_method,3,
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                [{file,"src/rabbit_channel.erl"},{line,1343}]},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                            {rabbit_channel,handle_cast,2,
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                [{file,"src/rabbit_channel.erl"},{line,644}]},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                            {gen_server2,handle_msg,2,
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                [{file,"src/gen_server2.erl"},{line,1067}]},
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                            {proc_lib,wake_up,3,
2021-07-29 16:09:34.410777+00:00 [warn] <0.29159.0>                                [{file,"proc_lib.erl"},{line,236}]}]}'
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>     supervisor: {<0.29171.0>,rabbit_channel_sup}
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>     errorContext: shutdown
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>     reason: reached_max_restart_intensity
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>     offender: [{pid,<0.29174.0>},
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                {id,channel},
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                {mfargs,
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                    {rabbit_channel,start_link,
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                        [1,<0.29159.0>,<0.29172.0>,<0.29159.0>,
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                         <<"172.20.132.124:60570 -> 172.17.0.2:5672">>,
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                         rabbit_framing_amqp_0_9_1,
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                         {user,<<"testuser">>,[],
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                             [{rabbit_auth_backend_internal,none}]},
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                         <<"/">>,
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                         [{<<"consumer_cancel_notify">>,bool,true},
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                          {<<"connection.blocked">>,bool,true},
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                          {<<"authentication_failure_close">>,bool,true}],
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                         <0.29160.0>,<0.29173.0>]}},
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                {restart_type,intrinsic},
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                {shutdown,70000},
2021-07-29 16:09:34.410801+00:00 [erro] <0.29171.0>                {child_type,worker}]
2021-07-29 16:09:34.412600+00:00 [info] <0.29159.0> closing AMQP connection <0.29159.0> (172.20.132.124:60570 -> 172.17.0.2:5672, vhost: '/', user: 'testuser')
2021-07-29 16:09:34.423140+00:00 [info] <0.29257.0> accepting AMQP connection <0.29257.0> (172.20.132.124:60642 -> 172.17.0.2:5672)
2021-07-29 16:09:34.424454+00:00 [info] <0.29257.0> connection <0.29257.0> (172.20.132.124:60642 -> 172.17.0.2:5672): user 'testuser' authenticated and granted access to vhost '/'
2021-07-29 16:09:34.425229+00:00 [info] <0.29167.0> closing AMQP connection <0.29167.0> (172.20.132.124:60572 -> 172.17.0.2:5672, vhost: '/', user: 'testuser')
2021-07-29 16:09:34.430869+00:00 [info] <0.29269.0> accepting AMQP connection <0.29269.0> (172.20.132.124:60644 -> 172.17.0.2:5672)
2021-07-29 16:09:34.432178+00:00 [info] <0.29269.0> connection <0.29269.0> (172.20.132.124:60644 -> 172.17.0.2:5672): user 'testuser' authenticated and granted access to vhost '/'

[michaelklishin]

@PingHao this is likely rabbitmq/rabbitmq-server#3230. Avoiding setting global QoS prefetch and using "regular" (per-channel) prefetch instead should side step this exception.

[mathieu-lemay]

It seems like the issue was fixed in 3.9.1.

[PingHao]

@mathieu-lemay Thanks. that's correct, the problem is gone on 3.9.1