写在前面：这个分析记录其实是在2019年做的，当时被MQ问题折腾的挺惨，好在最终在和几个同事攻关后，问题得到解决。近期忙碌于各种材料，回头看看自己曾经处理过的问题，略有所感，发出来共勉

记一次OpenStack RPC断连问题分析过程

一、 问题背景

(一) 问题表现

1. cinder-volume日志中，出现RabbitMQ连接异常中断并触发重连的日志，
   日志内容类似IOError: Socket closed
2. cinder-volume日志中，出现reset by peer日志，error: [Errno 104] Connection reset by peer
3. cinder-volume日志中，出现Too many heartbeat missed日志, 日志内容类似A recoverable connection/channel error occurred, trying to reconnect: Too many heartbeats missed
4. cinder-volume进程无法消费MQ消息，无法提供服务

(二) 现网日志

结合现网下载的cinder-volume日志进行分析，日志时间为1月20日 03:18:11 至 1月29日 19:55:42之间。
由于问题4未保留现场日志，且无现场状态记录，分析难度较大，本文档会根据已掌握信息对问题进行推测。

二、 问题初步分析

(一) 问题1、2

针对问题1中报Errno 32, Broken pipe，此问题常见原因有以下：
当第一次向一个对端已经close的socket写数据的时候会收到reset报文。当再次向这个socket写数据的时候，就会抛出Broken pipe。根据TCP的约定，当收到reset包的时候，上层必须要做出处理，将socket文件描述符进行关闭，其实也意味着pipe会关闭，因此会抛出这个异常。
针对问题2中报connection reset by peer，此问题常见的原因有以下2点：

1. 建立了socket连接的两端A和B，其中一端主动关闭或因异常原因crash，但另外一段依然在发送数据，所发送的第一个数据包会引发该异常（即问题1中的reset）
2. Socket一端退出，但退出时未主动关闭连接，另一端从连接中读取数据时抛出该异常
   问题1和2从原理层面分析具有相似性，均为socket连接中某一端关闭，而另一端依旧进行数据读或写时触发。
   OpenStack组件通过oslo-messaging库（调用kombu）与RabbitMQ Server进行交互。在问题1和2中，RabbitMQ Server进程及cinder volume进程均正常，因此排除某一端进程crash而触发以上报错的场景。推测是一端因为某些原因主动关闭了连接，而对方未明确感知时触发以上错误。
   而从RabbitMQ自身机制及oslo.messaging连接维护机制来看，只有Heartbeat异常时，才会触发某一端主动关闭连接。

(二) 问题3

该错误日志，由oslo.messaging库暴露。触发该问题的原因在heartbeat_check时，抛出异常，而导致发生该错误。
cinder volume每初始化一个rpc send类型的连接时，oslo.messaging都会启动一个heartbeat协程，该协程周期性执行heartbeat_check： 包括发送heartbeat消息给服务端，从服务端接收heartbeat消息等，以确保与RabbitMQ Server的连接正常。这些协程归属于cinder-volume主线程，由cinder-volume主线程统一调度运行。
oslo.messaging heartbeat_check机制，程序调用栈为：oslo.messaging:heartbeat_check ->> kombu:heartbeat_check ->> py-amqp:heartbeat_tick。heartbeat_check执行周期为15秒（与生产环境配置有关），在执行周期内如果发现满足发送heartbeat消息的条件，则会向服务端发送heartbeat；如果在规定时间内，没有收到服务端发的heartbeat或未消费成功，则认为heartbeat丢失。
发送heartbeat流程为：每间隔heartbeat时间发送一个heartbeat数据包，heartbeat数据包为8 byte的空数据；判断服务端heartbeat是否正常逻辑为：如果超过两个heartbeat周期没有收到heartbeat数据，则会报Too many heartbeats missed错误。

三、 日志分析

由于生产环境出问题的进程为后端是ceph存储的cinder-volume进程，因此从日志文件中过滤出ceph相关进程的日志进行分析。涉及到的进程数有3个
以报错较多的22998子进程为例来进行分析。

(一) Too many heartbeats missed

从日志开始有大量“A recoverable connection/channel error occurred, trying to reconnect: Too many heartbeats missed”报错，比较有规律，基本间隔在15s执行一次，每次涉及到27行此类日志。日志内容如下：

Too many heartbeats missed

由于每个connection在进行heartbeat，会按照配置指定时间(算法为：heartbeat_timeout_threshold/rate/2 = 15秒)休眠。在相同时间点内，共有27行此类日志，因此可以确定共有27个connection正在进行heartbeat_check，且heartbeat失败。说明已经超过heartbeat超时时间没有接收到或处理服务端heartbeat信息。造成该问题发生的主要原因有两方面： 一为RabbitMQ server压力较大，未能及时发送heartbeat消息。不过从生产环境运行情况来看，RabbitMQ server运行良好，发生这种情况的可能性不大，除非RabbitMQ本身存在缺陷，这个有待于进一步分析。二是cinder-volume未及时处理heartbeat消息。分析py-amqp的源码可知，cinder-volume与RabbitMQ server的每个connection，py-amqp都会为其维护一个读计数器。当从queue中读取到新的数据帧时，则计数器加1。heartbeat_tick在处理时，如果发现计数器计数发生了变化，则认为从server端正常接收到了heartbeat消息；反之则认为没有收到消息。因此，造成未及时处理或读取heartbeat消息的关键在于，触发计数器值发生变化的read_frame逻辑没有执行成功。

计数器

由以上代码段可以看出，在执行read_frame时报异常，会导致循环退出，从而造成bytes_recv计数器不增加。
read_frame逻辑如下：

read_frame

read_frame2

正常情况下，在出现上述报错后，oslo.messaging会进行ensure_connection操作，以保证连接恢复，并在恢复成功后打印“Reconnected to AMQP server on xx”日志。但从生产环境日志来看，在出现大量heartbeats missed日志后，在较长时间内没有reconnect成功，因此导致了周期性刷heartbeat missed日志。

(二) Broken pipe

以上有规律的日志，从日志开始一直持续到09:51分，发生了如下错误：

Broken pipe

结合日志及cinder-volume处理逻辑，可以分析出此处收到了删除volume的请求，在删除成且更新完数据库后，会有notify消息通知卷删除事件，需要发送rpc消息，正好发现连接已经处于不可用状态，因此报了截图错误。oslo.messaging自身具备自愈机制，会在发生以上错误时，触发重连。并在1秒重连成功后重新发送消息。

reconnect

因此，在发生heartbeat missed的事件时，由于oslo.messaging自身具备重试机制，一般情况下不会影响cinder-volume的正常运行。
在之后的日志中，可以观察到，打印“A recoverable connection/channel error occurred, trying to reconnect: Too many heartbeats missed”的日志连接变为26个。代码逻辑与日志表现一致。

26个记录

观察后续日志，在09:56:50时，也触发了2个Socket closed错误，并且触发2条重连成功的日志。在此后，heartbeat missed的日志连接数变为24个。截止10:02:17，共发生4次错误及重连，因此剩余23个异常连接。

(三) Connection reset by peer

在00:08:07--00:10:01中间，没有任何日志打印，说明heartbeat_check没有正常进行，因为如正常进行时，异常连接的heartbeat_check会继续打印heartbeat missed日志。结合RabbitMQ Heartbeat原理[见附1]来看，客户端超过2个周期没有发送heartbeat消息，会导致connection被服务端close或reset掉。结合cinder-volume运行原理[见附2]及协程机制，推测此时可能存在非协程友好类且耗时较长的业务逻辑正在处理，导致heartbeat协程无法获取到执行权而超时，客户端无法发送heartbeat消息给服务端（如前序描述，heartbeat_check逻辑中包含了客户端向服务端发送heartbeat消息，也包含判断服务端向客户端发送的heartbeat消息），从而导致服务端主动reset了连接。因此在协程获得执行权后报了reset by peer日志。

reset by peer

reset之后，后续的too many heartbeat missed日志条数，恢复到了27条，说明在heartbeat超时而导致heatbeat reset后，27个connection又重新恢复到了无法接收或处理服务端heartbeat消息的状态。因此推测“Too many heartbeat missed”与connection reset有一定关系。

四、 解决方法

（一）初步结论

问题1：与问题3有关，当向一个状态不正常的connection里面写入数据时，会报socket closed。
问题2：与python协程调度机制有关，处理非协程友好、且耗时较长的逻辑，导致其他包括heartbeat在内的协程无法被调度。
问题3：oslo.messaging ensure_connection存在bug，导致无法ensure成功。

（二）测试验证

问题 1：问题3解决后，不会向断连的connection中发送数据，因此不会报问题1。
问题 2：通过编写demo程序来尝试触发该错误。实现思路为在cinder-volume周期性任务重，添加一个超过200秒（大于3个heartbeat超时周期）的计算型任务，此时cinder-volume其他业务逻辑处理被阻塞。同时，达到heartbeat超时时间后，rabbitmq-server主动关闭连接。当周期性任务运行结束后，重新使用前期所建立的connection时，报问题1或2。
问题3：通过在测试环境加压，会出现大量heartbeat missed报错，合并修复ensure connection的bug后问题解决。

（三）解决思路

问题1、3：通过代码修复
问题2：生产环境中不可避免会出现耗时较长的非协程友好任务，基于oslo.messaging自身较为完备的自愈机制，在重新获取执行权后可恢复连接（基于问题1、3的代码修复）。

五、 遗留问题

问题4:未保留现场日志及错误状态，推测与协程任务阻塞主线程有关，待再次遇到此问题时，保留一段时间现场及日志供分析。

附1 RabbitMQ Heartbeat机制

在理解RabbitMQ之前，先简单说下TCP的KeepAlive机制，与RabbitMQ的Heartbeat机制有异曲同工之妙。

(一) TCP KeepAlive

TCP Keepalive为确保连接对端存活状态的一种方法。当客户端等待（空闲）超过一定时间后，自动给服务端发送一个空报文，如果对方回复，则说明连接存活；如果对方没有报文，且多次尝试结果一样，那么可认为此连接已丢失，客户端没有必要继续保持连接，后续也不再使用此连接。

1. KeepAlive默认情况下是关闭的，可被上层应用关闭和打开（设置SO_KEEPALIVE）
2. Tcp_keepalive_time：KeepAlive的空闲时长，也可以理解为心跳周期
3. Tcp_keepalive_intvl: KeepAlive探测包的发送间隔
4. Tcp_keepalive_probes: 在tcp_keepalive_time之后，未收到对端确认，继续发送探测包的次数
   在使用linux内核时，可以通过以下参数，对tcp keepalive进行配置：

Linux 7.2默认配置分别为1，5, 5
Linux 7.3 默认配置分比为3, 8, 30
注：TCP KeepAlive和HTTP协议的Keep-Alive不一样，前者在于心跳、错误检测等；后者在于连接复用

(二) RabbitMQ Heartbeat

1. RabbitMQ基于AMQP协议实现，AMQP在0.9.1版本提供了heartbeat机制。该机制主要是确保应用层能够及时发现中断的连接或者完全没有响应的对等点，还可以防止某些网络设备在一定时间内没有活动时终止空闲的TCP连接。
2. 心跳超时值定义了RabbitMQ的两端认为对等TCP连接在多长时间无传输之后需要发送心跳包，目前最新版本的默认值是60s，之前是580s，再前面的版本是600s。
3. 系统的心跳超时值由客户端和服务端共同商定：
   (1) 如果都不设置，那就定为默认值
   (2) 当两个值都不为0时，将使用请求值的较低值
   (3) 如果一方使用零值(试图禁用心跳)，而另一方不使用，则使用非零值。
   (4) 如果时间间隔配置为0，则表示不启用heartbeat检测
   (5) 将心跳超时值设置得太小可能会导致由于临时网络拥塞、短暂的服务器流控制等原因导致的误判，认为对端不可用。
4. 任何流量交互（例如协议操作、发布的消息、确认)都可以算作有效的心跳。根据客户端的不同，可以选择发送心跳包，而不管连接上是否有其他流量，也可以只在必要时发送心跳包。
5. 在进行了两次心跳检测都没有回应后，对端就被认为是不可联系的，此时，TCP连接将被关闭。
6. 要想让heartbeat机制失效，有两个方式：
   (1) 将时间间隔配置为0，表示不启动heartbeat检测
   (2) 将超时值设置得足够大
   (3) 不推荐在实际环境中使用这两种配置方式，除非环境中使用了TCP KeepAlive
   一些网络工具(如HAproxy, AWS ELB)和设备(硬件负载均衡器)可能在一段时间内没有活动时终止环境中空闲的TCP连接。而当在连接上启用心跳检测时，它会导致周期性的轻网络流量。因此，心跳检测有一个副作用，就是保护客户机连接，防止代理和负载均衡器提前关闭这些连接，这些连接可能在一段时间内处于空闲状态。
   关于为什么不采用TCP KeepAlive而是重新开发heartbeat机制---TCP KeepAlive在不同内核或操作系统版本中的配置方式不一致，对应用层不友好，因此存在了heartbeat机制。

附2 cinder volume进程运行原理

cinder volume在启动时，首先会有一个父进程，然后针对每种后端存储启动一个子进程，每个子进程包含一个MainThread。MainThread中又包含了大量的_GreenThread（协程）。采用协程可大大提升程序处理效率，对disk io、网络密集型任务的提升尤其明显（处理python友好的io等请求时会让出cpu执行权，其他获取到cpu执行权的协程继续执行）；但对CPU密集型任务，与顺序处理无区别。
周期性任务：cinder volume中启动的周期性任务periodic task,如果有多个，会按照顺序执行。当某一个周期性任务，长时间运行，不释放CPU执行权时，其他周期性任务的运行要进行等待，直到前序周期性任务释放CPU执行权。
RPC Client：cinder volume在启动时，rpcserver会一并启动。RPC server初始化设定使用协程的消息处理方式。
在cinder volume作为消费者时，会监听自己的queue，当有RPC请求到来时，使用协程来处理RPC请求。
cinder-volume通过rpc.call或rpc.cast来与其他组件进行交互，而每当调用rpc.call或cast时，其背后的原理为通过oslo.messaging的连接池机制拿到一个可用连接，并进行后续的消息发送。如果连接池中的连接不够用时，则会新声明一个连接供其调用，直到连接数到达节点配置的上限（一般为30个）。达到上限后，后续的连接会排队等待。