RabbitMQ 信道(channel)挂掉，但连接仍然存在，同时出现错误：Received remote Channel.Close (406): PRECONDITION_FAILED - unknown delivery tag x 的问题

该问题经过一番试验，发现是消费者(consumer)程序逻辑错误导致：在消息处理的回调函数中多次ack或nack。

开启Python日志，并在回调函数中两次ack得到如下信息：

 

F:\software\Python35\python.exe F:/project/Python/forwardShippingInfo/test_rabbitmq.py
2017-02-07 15:46:49,678 - pika.adapters.select_connection - DEBUG - Using SelectPoller
2017-02-07 15:46:49,679 - pika.callback - DEBUG - Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x000000000338B348>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,679 - pika.callback - DEBUG - Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003287C08>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,679 - pika.callback - DEBUG - Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003AE4488>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,679 - pika.callback - DEBUG - Added: {'callback': <bound method Connection._on_connection_start of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,688 - pika.adapters.base_connection - INFO - Connecting to 192.168.200.230:5672
2017-02-07 15:46:49,704 - pika.callback - DEBUG - Processing 0:Connection.Start
2017-02-07 15:46:49,704 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,705 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,705 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method Connection._on_connection_start of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,705 - pika.callback - DEBUG - Calling <bound method Connection._on_connection_start of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>> for "0:Connection.Start"
2017-02-07 15:46:49,705 - pika.callback - DEBUG - Added: {'callback': <bound method Connection._on_connection_tune of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,709 - pika.callback - DEBUG - Processing 0:Connection.Tune
2017-02-07 15:46:49,709 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,709 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,709 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method Connection._on_connection_tune of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,709 - pika.callback - DEBUG - Calling <bound method Connection._on_connection_tune of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>> for "0:Connection.Tune"
2017-02-07 15:46:49,710 - pika.connection - DEBUG - Creating a HeartbeatChecker: 600
2017-02-07 15:46:49,710 - pika.callback - DEBUG - Added: {'callback': <bound method Connection._on_connection_open of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,713 - pika.callback - DEBUG - Processing 0:Connection.OpenOk
2017-02-07 15:46:49,713 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,713 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,713 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method Connection._on_connection_open of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,713 - pika.callback - DEBUG - Calling <bound method Connection._on_connection_open of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>> for "0:Connection.OpenOk"
2017-02-07 15:46:49,713 - pika.callback - DEBUG - Added: {'callback': <bound method Connection._on_connection_closed of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,713 - pika.callback - DEBUG - Processing 0:_on_connection_open
2017-02-07 15:46:49,713 - pika.callback - DEBUG - Calling <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003287C08>> for "0:_on_connection_open"
2017-02-07 15:46:49,714 - pika.connection - DEBUG - Creating channel 1
2017-02-07 15:46:49,714 - pika.callback - DEBUG - Added: {'callback': <bound method Connection._on_channel_cleanup of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': <pika.channel.Channel object at 0x0000000003AD8BA8>, 'calls': 1}
2017-02-07 15:46:49,714 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_getempty of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,714 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_cancel of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,714 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_flow of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,714 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_close of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,714 - pika.channel - DEBUG - Adding in on_synchronous_complete callback
2017-02-07 15:46:49,714 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,714 - pika.channel - DEBUG - Adding passed in callback
2017-02-07 15:46:49,715 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_openok of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,715 - pika.callback - DEBUG - Added: {'callback': <bound method BlockingChannel._on_consumer_cancelled_by_broker of <pika.adapters.blocking_connection.BlockingChannel object at 0x0000000003AF65F8>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,715 - pika.callback - DEBUG - Added: {'callback': <bound method _CallbackResult.signal_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003AE7E88>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,715 - pika.callback - DEBUG - Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003AE7D08>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,715 - pika.callback - DEBUG - Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003AE7EC8>>, 'arguments': None, 'one_shot': False, 'only': None}
2017-02-07 15:46:49,717 - pika.adapters.blocking_connection - INFO - Created channel=1
2017-02-07 15:46:49,718 - pika.callback - DEBUG - Processing 1:Channel.OpenOk
2017-02-07 15:46:49,718 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,718 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,718 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,719 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,719 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,719 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method Channel._on_openok of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,719 - pika.callback - DEBUG - Calling <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>> for "1:Channel.OpenOk"
2017-02-07 15:46:49,719 - pika.channel - DEBUG - 0 blocked frames
2017-02-07 15:46:49,719 - pika.callback - DEBUG - Calling <bound method Channel._on_openok of <pika.channel.Channel object at 0x0000000003AD8BA8>> for "1:Channel.OpenOk"
2017-02-07 15:46:49,719 - pika.channel - DEBUG - Adding in on_synchronous_complete callback
2017-02-07 15:46:49,719 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,719 - pika.channel - DEBUG - Adding passed in callback
2017-02-07 15:46:49,720 - pika.callback - DEBUG - Added: {'callback': <bound method _CallbackResult.signal_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003A6E208>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,721 - pika.callback - DEBUG - Processing 1:Basic.QosOk
2017-02-07 15:46:49,721 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,722 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,722 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,722 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,722 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,722 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method _CallbackResult.signal_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003A6E208>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,722 - pika.callback - DEBUG - Calling <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>> for "1:Basic.QosOk"
2017-02-07 15:46:49,722 - pika.channel - DEBUG - 0 blocked frames
2017-02-07 15:46:49,722 - pika.callback - DEBUG - Calling <bound method _CallbackResult.signal_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003A6E208>> for "1:Basic.QosOk"
2017-02-07 15:46:49,722 - pika.channel - DEBUG - Adding in on_synchronous_complete callback
2017-02-07 15:46:49,723 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': {'consumer_tag': '2017-02-07 15:46:49 -> 9540'}, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,723 - pika.channel - DEBUG - Adding passed in callback
2017-02-07 15:46:49,723 - pika.callback - DEBUG - Added: {'callback': <bound method Channel._on_eventok of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': {'consumer_tag': '2017-02-07 15:46:49 -> 9540'}, 'one_shot': True, 'only': None, 'calls': 1}
2017-02-07 15:46:49,727 - pika.callback - DEBUG - Processing 1:Basic.ConsumeOk
2017-02-07 15:46:49,727 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,727 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,727 - pika.callback - DEBUG - Comparing {'consumer_tag': '2017-02-07 15:46:49 -> 9540'} to {'consumer_tag': '2017-02-07 15:46:49 -> 9540'}
2017-02-07 15:46:49,727 - pika.callback - DEBUG - Removing callback #1: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': {'consumer_tag': '2017-02-07 15:46:49 -> 9540'}, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,727 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:46:49,727 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:46:49,728 - pika.callback - DEBUG - Comparing {'consumer_tag': '2017-02-07 15:46:49 -> 9540'} to {'consumer_tag': '2017-02-07 15:46:49 -> 9540'}
2017-02-07 15:46:49,728 - pika.callback - DEBUG - Removing callback #1: {'callback': <bound method Channel._on_eventok of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': {'consumer_tag': '2017-02-07 15:46:49 -> 9540'}, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:46:49,728 - pika.callback - DEBUG - Calling <bound method _CallbackResult.signal_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003AE7E88>> for "1:Basic.ConsumeOk"
2017-02-07 15:46:49,728 - pika.callback - DEBUG - Calling <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x0000000003AD8BA8>> for "1:Basic.ConsumeOk"
2017-02-07 15:46:49,728 - pika.channel - DEBUG - 0 blocked frames
2017-02-07 15:46:49,728 - pika.callback - DEBUG - Calling <bound method Channel._on_eventok of <pika.channel.Channel object at 0x0000000003AD8BA8>> for "1:Basic.ConsumeOk"
2017-02-07 15:46:49,728 - pika.channel - DEBUG - Discarding frame <METHOD(['channel_number=1', 'frame_type=1', "method=<Basic.ConsumeOk(['consumer_tag=2017-02-07 15:46:49 -> 9540'])>"])>
2017-02-07 15:47:14,731 - pika.callback - DEBUG - Processing 1:Channel.Close
2017-02-07 15:47:14,731 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:47:14,731 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:47:14,731 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method Channel._on_close of <pika.channel.Channel object at 0x0000000003AD8BA8>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:47:14,733 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:47:14,733 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:47:14,734 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003AE7D08>>, 'arguments': None, 'one_shot': True, 'only': None, 'calls': 0}
2017-02-07 15:47:14,734 - pika.callback - DEBUG - Calling <bound method Channel._on_close of <pika.channel.Channel object at 0x0000000003AD8BA8>> for "1:Channel.Close"
2017-02-07 15:47:14,734 - pika.channel - INFO - <METHOD(['channel_number=1', 'frame_type=1', "method=<Channel.Close(['class_id=60', 'method_id=80', 'reply_code=406', 'reply_text=PRECONDITION_FAILED - unknown delivery tag 1'])>"])>
2017-02-07 15:47:14,734 - pika.channel - WARNING - Received remote Channel.Close (406): PRECONDITION_FAILED - unknown delivery tag 1
2017-02-07 15:47:14,734 - pika.callback - DEBUG - Processing 1:_on_channel_cleanup
2017-02-07 15:47:14,734 - pika.callback - DEBUG - Processing use of oneshot callback
2017-02-07 15:47:14,734 - pika.callback - DEBUG - 0 registered uses left
2017-02-07 15:47:14,735 - pika.callback - DEBUG - Removing callback #0: {'callback': <bound method Connection._on_channel_cleanup of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>>, 'arguments': None, 'one_shot': True, 'only': <pika.channel.Channel object at 0x0000000003AD8BA8>, 'calls': 0}
2017-02-07 15:47:14,735 - pika.callback - DEBUG - Calling <bound method Connection._on_channel_cleanup of <pika.adapters.select_connection.SelectConnection object at 0x0000000003A760B8>> for "1:_on_channel_cleanup"
2017-02-07 15:47:14,735 - pika.connection - DEBUG - Removed channel 1
2017-02-07 15:47:14,735 - pika.callback - DEBUG - Clearing out '1' from the stack
2017-02-07 15:47:14,735 - pika.callback - DEBUG - Calling <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x0000000003AE7D08>> for "1:Channel.Close"

由unknown delivery tag很容易想到回调函数中唯二使用delivery tag的方法(ack/nack)，对代码进行review找到逻辑错误，得以解决。　　

可以看到这种情况下，连接存在，信道消失发生的原因。

当然还有一些情况会发生这种情况，这里只是说明下其中的一个情况，及其问题的查找方法。