一、问题现象
应用程序通过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、代码流程如下:
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.
