Rabbimtmq unack問題分析

weixin_34107955發表於2018-10-04
MQ

一、問題現象

應用程式通過spring amqp 操作rabbitmq，有個手動返回ack的queue，應用程式已經使用 channel.basicAck 返回ack了，但是通過rabbitmq 管理控制檯看到，仍然有大量訊息處於 unack 狀態。

1、rabbit mq日誌

通過 /var/log/rabbitmq/rabbit@host.log 可以看到對應的錯誤資訊
顯示如下:

2018-10-03 19:15:15.653 [error] <0.8578.1> Channel error on connection <0.8298.1> (127.0.0.1:54528 -> 127.0.0.1:5672, vhost: '/', user: 'guest'), channel 3:
operation basic.ack caused a channel exception precondition_failed: unknown delivery tag 4
2、應用程式日誌

應用程式同時伴有如下錯誤日誌:

[ERROR] 2018-10-03 16:43:40.251 - Channel shutdown: channel error; protocol method: #method<channel.close>(reply-code=406, reply-text=PRECONDITION_FAILED - unknown delivery tag 2, class-id=60, method-id=80)
[ERROR] 2018-10-03 16:43:41.256 - Channel shutdown: channel error; protocol method: #method<channel.close>(reply-code=406, reply-text=PRECONDITION_FAILED - unknown delivery tag 3, class-id=60, method-id=80)

二、解決過程

通過日誌可以發現，channel 已經被close掉了，把 cachingConnectionFactory 的 channelCacheSize 改為大於等於目前系統裡 consumer 的個數就可以。

1、xml配置

如果使用application.xml配置 RabbitTemplate ，新增如下配置

<rabbit:connection-factory id="xxxx"
                           host="${payment.rabbitmq.host}" username="${payment.rabbitmq.username}" password="${payment.rabbitmq.password}"
                           port="${payment.rabbitmq.port}" virtual-host="${payment.rabbitmq.virtual_host}" channel-cache-size="期望的size"/>
2、手動使用程式碼控制
CachingConnectionFactory factory = new CachingConnectionFactory();
factory.setHost("localhost");
factory.setChannelCacheSize(期望的size);
3、Tips:

1、spring-rabbit 從 1.6.0.RELEASE 之後，把 預設的 channelCacheSize 從 1 改為了 25。
2、channelCacheSize 一定要大於等於目前的 consumer 個數，在 1.6.0.RELEASE 之前，如果只有 1 個 consumer，不會出現這個問題。
在 1.6.0.RELEASE(含) 以及以後，如果 consumer 個數小於等於25，不會出現問題。建議手動顯式設定。
3、如果使用spring xml配置 consumer，則不會出現這個問題，因為spring 會自動檢查配置，在 SimpleMessageListenerContainer 類裡，如果發現 channelCacheSize 小於當前的 consumer 數量，則會修改 channelCacheSize。

三、原因分析

1、開啟spring 日誌，有看到如下資訊:

[TRACE] 2018-10-03 17:09:45.485 - Returning cached Channel: AMQChannel(amqp://guest@127.0.0.1:5672/,1)
[DEBUG] 2018-10-03 16:56:13.248 - Closing cached Channel: AMQChannel(amqp://guest@127.0.0.1:5672/,1)

2、根據 Closing cached Channel 找到對應的程式碼，看在哪裡執行了channel 的close操作。
搜尋一下，在spring-rabbit原始碼路徑下執行命令： grep -irn 'Closing cached Channel' org
發現程式碼的關閉操作實際上是在 CachedChannelInvocationHandler 的 physicalClose() 方法進行的。
3、通過分析程式碼呼叫鏈路，發現如下流程：
RabbitTemplate 每次執行 execute 方法的時候，在 finally 塊裡最終都會釋放資源，如果目前 CachingConnectionFactory 內部的 channelCacheSize 小於 配置的數量，則進行 邏輯關閉(logicalClose)，即日誌中的 Returning cached Channel，邏輯關閉不會真正的關閉 channel。 如果大於當前數量，則嘗試進行 物理關閉(physicalClose)： 會真正的關閉掉channel。

4、RabbitTemplate.execute 核心程式碼
    private <T> T doExecute(ChannelCallback<T> action, ConnectionFactory connectionFactory) {
        Assert.notNull(action, "Callback object must not be null");
        RabbitResourceHolder resourceHolder = ConnectionFactoryUtils.getTransactionalResourceHolder(
                (connectionFactory != null ? connectionFactory : getConnectionFactory()), isChannelTransacted());
        Channel channel = resourceHolder.getChannel();
        if (this.confirmCallback != null || this.returnCallback != null) {
            addListener(channel);
        }
        try {
            if (logger.isDebugEnabled()) {
                logger.debug("Executing callback on RabbitMQ Channel: " + channel);
            }
            return action.doInRabbit(channel);
        }
        catch (Exception ex) {
            if (isChannelLocallyTransacted(channel)) {
                resourceHolder.rollbackAll();
            }
            throw convertRabbitAccessException(ex);
        }
        finally {
                      //釋放資源
            ConnectionFactoryUtils.releaseResources(resourceHolder);
        }
    }
6、程式碼流程如下:
5329915-b9f1de584e22e356.png
image.png
7、logicalClose 程式碼如下:

通過程式碼可以看到，close 只是把它放回到 channel pool list裡，並沒有做真正的關閉操作。

        private void logicalClose(ChannelProxy proxy) throws Exception {
            if (target == null) {
                return;
            }
            if (this.target != null && !this.target.isOpen()) {
                synchronized (targetMonitor) {
                    if (this.target != null && !this.target.isOpen()) {
                        if (this.channelList.contains(proxy)) {
                            this.channelList.remove(proxy);
                        }
                        this.target = null;
                        return;
                    }
                }
            }
            // Allow for multiple close calls...
            if (!this.channelList.contains(proxy)) {
                if (logger.isTraceEnabled()) {
                    logger.trace("Returning cached Channel: " + this.target);
                }
                this.channelList.addLast(proxy);
            }
        }
8、physicalClose 程式碼,真實的關閉 channel， 會通過 rabbit 包下的 channelN 真正的關閉掉這個channel(向rabbitmq server傳送訊息)
        private void physicalClose() throws Exception {
            if (logger.isDebugEnabled()) {
                logger.debug("Closing cached Channel: " + this.target);
            }
            if (this.target == null) {
                return;
            }
            try {
                if (CachingConnectionFactory.this.active &&
                        (CachingConnectionFactory.this.publisherConfirms ||
                                CachingConnectionFactory.this.publisherReturns)) {
                    ExecutorService executorService = (getExecutorService() != null
                            ? getExecutorService()
                            : CachingConnectionFactory.this.deferredCloseExecutor);
                    final Channel channel = CachedChannelInvocationHandler.this.target;
                    executorService.execute(new Runnable() {

                        @Override
                        public void run() {
                            try {
                                if (CachingConnectionFactory.this.publisherConfirms) {
                                    channel.waitForConfirmsOrDie(5000);
                                }
                                else {
                                    Thread.sleep(5000);
                                }
                            }
                            catch (InterruptedException e) {
                                Thread.currentThread().interrupt();
                            }
                            catch (Exception e) {}
                            finally {
                                try {
                                    if (channel.isOpen()) {
                                        channel.close(); //真實關閉掉這個channel
                                    }
                                }
                                catch (IOException e) {}
                                catch (AlreadyClosedException e) {}
                            }
                        }

                    });
                }
                else {
                    this.target.close();
                }
            }
            catch (AlreadyClosedException e) {
                if (logger.isTraceEnabled()) {
                    logger.trace(this.target + " is already closed");
                }
            }
            finally {
                this.target = null;
            }
        }

    }

四、總結

歸根結底，是因為channel 被關閉了，但是仍然通過這個channel 回覆 ack，在basicAck的時候，會把當前的 channelNumber 一起傳送給rabbitmq server。
有興趣的可以深入瞭解下 rabbitmq server的實現原理。
程式碼在 https://github.com/rabbitmq/rabbitmq-server
rabbitmq 是erlang 開發的，上面的錯誤日誌在

collect_acks(ToAcc, PrefixAcc, Q, DeliveryTag, Multiple) ->
    case queue:out(Q) of
        {{value, UnackedMsg = {CurrentDeliveryTag, _ConsumerTag, _Msg}},
         QTail} ->
            if CurrentDeliveryTag == DeliveryTag ->
                    {[UnackedMsg | ToAcc],
                     case PrefixAcc of
                         [] -> QTail;
                         _  -> queue:join(
                                 queue:from_list(lists:reverse(PrefixAcc)),
                                 QTail)
                     end};
               Multiple ->
                    collect_acks([UnackedMsg | ToAcc], PrefixAcc,
                                 QTail, DeliveryTag, Multiple);
               true ->
                    collect_acks(ToAcc, [UnackedMsg | PrefixAcc],
                                 QTail, DeliveryTag, Multiple)
            end;
        {empty, _} ->
            precondition_failed("unknown delivery tag ~w", [DeliveryTag])
    end.

相關文章