原文地址：http://aspirer2004.blog.163.com/blog/static/1067647201411119615820/
1. 问题症状
QA测试重复挂卸载网卡场景过程中，多次挂卸载后，发现网卡挂载成功，nova-compute日志无异常，但却无法卸载，nova-compute日志中有异常输出：
|
|
2014-12-04 14:27:45.037 5243 ERROR nova.openstack.common.rpc.amqp [req-cae51866-d040-406c-91db-503954f4289e 19cf25635e8f4f64b7884eacf0b2d707 e2e52a8b4a1442e994675c0be721d42 b] Exception during message handling 2014-12-04 14:27:45.037 5243 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last): 2014-12-04 14:27:45.037 5243 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/openstack/common/rpc/amqp.py", line 461, in _process_data 2014-12-04 14:27:45.037 5243 TRACE nova.openstack.common.rpc.amqp **args) 2014-12-04 14:27:45.037 5243 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch 2014-12-04 14:27:45.037 5243 TRACE nova.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs) 2014-12-04 14:27:45.037 5243 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 4938, in detach_interface 2014-12-04 14:27:45.037 5243 TRACE nova.openstack.common.rpc.amqp "attached") % port_id) 2014-12-04 14:27:45.037 5243 TRACE nova.openstack.common.rpc.amqp PortNotFound: Port 4559c7d7-5242-4d4d-9807-c558f1b76f77 is not attached |
并且nova list看不到挂载的网卡，但是nova interface-list $UUID可以看到挂载的网卡：
初步判断问题不是必现的，因为挂载网卡属于常规操作，经常用到，如果是必现问题，应该很容易被发现。
2. 问题难点
经过简单的定位之后，发现要分析问题的原因，有以下几点困难：
- 代码不熟悉，之前没看过这部分代码，这也是使用开源软件最常遇到的困难
- 问题比较难重现出来，如果找不到重现场景，就很难分析出具体原因，更不要说解决问题了，即使搞出来一个解决方法，也没办法验证是否真正解决了问题
- 网卡挂卸载属于与neutron组件交互的功能，对neutron组件实现细节不熟悉，不清楚是否属于neutron本身的问题还是属于nova的问题
3. 分析问题
虽说分析起来有一些困难，但是问题总归还是要解决掉，否则一旦用户使用过程中发现这个问题，短时间内面临时间压力的情况下，会更难静下心来找到问题原因并解决掉。
针对上述几个困难，简单的在稿纸上罗列了对应的解决方法：
- 阅读代码分析代码流程，先把代码吃透，分析出的代码流程可以根据日志中的内容来进行正确性验证
- 在阅读代码的基础上，思考问题可能出现的场景，整理出所有可能的场景，记录下来，以便进行问题重现
- 先把nova部分代码搞清楚，确认是不是nova这边的问题，如果确认不是，再分析neutron组件
3.1 阅读代码
代码没看过不是问题，一个几十上百万行代码的开源软件，一般都不太可能把所有代码都分析一遍，最多也就是把关键流程搞清楚，后续遇到具体问题再具体分析（当然也不排除有些牛人+闲人，一天到晚的没事做在分析代码流程），这样既能快速了解代码的大致框架，也节省出来时间去做二次开发。
既然要分析代码，总要先找到入口，确定从哪里下手，这最终还是得根据问题症状来确定，症状有两点，一是挂载网卡后nova list看不到，nova interface-list可以看到，二是卸载的时候报错，port未挂载。
首先分析第一个症状的代码流程，发现nova list看到的网卡信息是调用的nova api，从nova数据库中取到的，具体是在instance_info_cache表中，而nova interface-list则是直接调用的neutron api，从neutron数据库中获取的。分析到这里得出两种可能，一是nova这边挂载网卡失败，没有把网卡信息保存到数据库中，但是没有通知neutron清理残留现场（或者通知了neutron但是清理失败了），二是挂载成功了，nova没有把网卡信息写入数据库（可能是没写，也可能是数据库、网络等抽风导致写入失败），不管怎样，还有第二个症状没有分析，先把这两种场景记录下来再说。
继续分析第二个症状的代码流程，卸载网卡失败，查看错误TRACE日志发现是因为nova数据库中instance_info_cache表中没有这个网卡信息导致的，分析到这里，发现和症状1应该是同样的原因，所以可以暂时不考虑症状2，全力分析症状1的出现场景和原因。
3.2 分析场景
既然决定分析症状1，那就把刚刚整理的可能的场景拿出来认真想一想。
第一种场景是nova挂载失败，如果真的是这种情况，那么日志里面一般都会有错误信息输出，因为一般人写代码通常都会把一些错误、警告等信息打印到日志里面，当然也不排除有些人不喜欢打日志，不过nova是python语言开发的，即使你不打印日志，如果遇到没有捕获的异常，也会有错误TRACE输出的，除非遇到变态码农，把所有的异常都捕获掉并且不打印任何日志，我相信OpenStack这么大的社区，这么多的大牛，是不能忍受这样的码农和代码存在的，所以去搜索日志中的ERROR、WARN、TRACE，发现除了卸载时的错误，还有一些其他告警之外，没有任何异常日志输出，当然这并不能说nova挂载网卡一定是成功的，还需要继续跟进日志，一步一步的跟着代码和日志进行逐行日志分析，确认是否有代码中已经处理但是又没有特殊级别日志输出的异常逻辑流程，经过分析，发现挂载过程没有异常，也没有走到异常流程，这里还做了一件事，就是把本次挂载流程的所有日志挑选出来，和某次确认是正常挂载的挑选出来的日志进行对比（注意挑选方式要保持一致，比如grep request id，port-id等），对比工具有很多，notepad++、beyondcompare、vimdiff等文本对比工具都可以，主要是为了对比是否有多余或者缺少的日志输出，多余和缺少的部分很有可能就是走到了异常逻辑流程。总之，挂载流程基本确认是正常的，这个结论也符合偶现问题这个前提，否则就极有可能是必现问题了。
接着考虑第二种场景，挂载成功了，但是nova没有把网卡信息写入数据库，要确认是否是这个场景，通过分析代码，看到更新数据库之前会打印日志，把更新的网卡信息打印到日志里面，既然有日志就好办多了，首先就是搜索日志中对应记录：
|
|
wwww@10-xxx-0-xxx:~$ grep "10.xxx.xxx.71" nova-compute.log.1 | grep Updating 2014-12-04 14:17:07.359 5243 DEBUG nova.network.api [req-f5b7febd-ffe9-4859-850c-69cff88a5659 19cf25635e8f4f64b7884eacf0b2d707 e2e52a8b4a1442e994675c0be721d42b] Updating cache with info: [VIF({'ovs_interfaceid': u'b375c304-f610-4f09-bb1c-f59e24cd2730', 'network': Network({'bridge': u'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.xxx.xxx.11'})], 'version': 4, 'meta': {u'dhcp_server': u'10.xxx.xxx.5'}, 'dns': [], 'routes': [], 'cidr': u'10.xxx.xxx.0/23', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.xxx.xxx.1'})})], 'meta': {u'injected': False, u'tenant_id': u'e2e52a8b4a1442e994675c0be721d42b'}, 'id': u'ac968912-d491-4380-914d-213483d8104e', 'label': u'private_e2e52a8b4a1442e994675c0be721d42b'}), 'devname': u'tapb375c304-f6', 'qbh_params': None, 'meta': {}, 'address': u'fa:16:3e:15:8f:4d', 'type': u'ovs', 'id': u'b375c304-f610-4f09-bb1c-f59e24cd2730', 'qbg_params': None}), VIF({'ovs_interfaceid': u'4559c7d7-5242-4d4d-9807-c558f1b76f77', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.xxx.xxx.71'})], 'version': 4, 'meta': {'dhcp_server': u'10.xxx.xxx.68'}, 'dns': [], 'routes': [], 'cidr': u'10.xxx.xxx.64/26', 'gateway': IP({'meta': {}, 'version': None, 'type': 'gateway', 'address': None})})], 'meta': {'injected': False, 'tenant_id': u'e2e52a8b4a1442e994675c0be721d42b'}, 'id': u'b11d8ca7-27cb-48bc-b65a-a7a66c6b7e9b', 'label': u'idc_e2e52a8b4a1442e994675c0be721d42b'}), 'devname': u'tap4559c7d7-52', 'qbh_params': None, 'meta': {}, 'address': u'fa:16:3e:84:76:ab', 'type': u'ovs', 'id': u'4559c7d7-5242-4d4d-9807-c558f1b76f77', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/dist-packages/nova/network/api.py:72 |
搜索到日志，并且是在挂载流程过程中打印的，说明挂载过程是正常尝试更新了数据库的（至于是不是后面的更新数据库操作失败了，暂时不清楚，不过没有看到错误日志，基本可以断定是成功的）。
既然有更新进去，那就看下数据库里面有没有，经过检查，发现数据库里面确实没有新挂载的网卡，那就有两种可能，一是没更新成功，这个可能性很小，二是更新成功了，但是后来被其他操作清理掉了。
重点看下第二个可能性概率比较高的问题，既然每次更新都有日志，那肯定还是搜索日志，搜索发现：
|
|
wwww@10-xxx-0-xxx:~$ grep "update_instance_cache_with_nw_info" nova-compute.log.1 2014-12-05 00:53:27.099 5243 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': u'9e9dff77-46bb-41c4-aed2-35370314544a', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.xxx.xxx.12'})], 'version': 4, 'meta': {'dhcp_server': u'10.xxx.xxx.5'}, 'dns': [], ...... |
有很多很多的这个日志，并且时间间隔都很规律，1分钟左右，再检查update_instance_cache_with_nw_info的代码流程，发现nova-compute有个定时任务在刷新info_cache：
|
|
@periodic_task.periodic_task def _heal_instance_info_cache(self, context): |
继续搜索日志，看下什么时候把挂载的网卡清理掉的（根据QA提供截图中的两个网卡id来过滤）：
|
|
grep 9e9df nova-compute.log.1 | grep "Updating " grep 9e9df nova-compute.log.1 | grep "Updating " | grep -v 4559c |
发现日志太多太多了，定时任务每分钟都会更新这个info cache，需要再考虑另外的方法来过滤。既然上面已经在日志中找到了挂载过程中的更新记录，那么要把信息更新回去，必然在这个时间点之后做更新操作才行，并且剩下的网卡应该是现在可以看到的那个，于是在日志里面根据网卡id从上面那个更新成功时间点2014-12-04 14:17:07.359向后排查，发现短时间内并未找到更新信息。
仔细查看了上面更新成功的日志和QA截图后，发现QA其实还挂卸载过另外一张网卡，导致两张网卡的ip和id都不一样，截图是老的，目前是新的（ip最后2位分别是12、11），既然知道了问题所在，那就更换网卡id继续搜索，果然就在后面没几行，就看到了一条日志：
|
|
2014-12-04 14:17:07.612 5243 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': u'b375c304-f610-4f09-bb1c-f59e24cd2730', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.xxx.xxx.11'})], 'version': 4, 'meta': {'dhcp_server': u'10.xxx.xxx.5'}, 'dns': [], 'routes': [], 'cidr': u'10.xxx.xxx.0/23', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.xxx.xxx.1'})})], 'meta': {'injected': False, 'tenant_id': u'e2e52a8b4a1442e994675c0be721d42b'}, 'id': u'ac968912-d491-4380-914d-213483d8104e', 'label': u'private_e2e52a8b4a1442e994675c0be721d42b'}), 'devname': u'tapb375c304-f6', 'qbh_params': None, 'meta': {}, 'address': u'fa:16:3e:15:8f:4d', 'type': u'ovs', 'id': u'b375c304-f610-4f09-bb1c-f59e24cd2730', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/dist-packages/nova/network/api.py:72 |
注意看两条日志的时间点：2014-12-04 14:17:07.359（挂载网卡操作），2014-12-04 14:17:07.612（定时任务操作），相隔不到300ms，既然如此相近，那么就极有可能是并发问题，联系到问题不是必现，而且是两个不同操作在分别执行，并发问题的可能性就更大了。
3.3 确定场景
怀疑是并发问题的话，就需要找到并发点，从哪里下手呢？当然是以更新到数据库中info cache信息的数据来源为切入点，因为是定时任务更新在后，并且是定时任务把数据库中信息更新丢了一部分，那么就以定时任务的数据来源为主要分析点，肯定是数据来源有问题，才导致更新后丢失了部分网卡信息。
分析代码发现，定时任务会先从数据库查询出来当前的info cache信息，并且一步一步的传到最终的更新数据库操作方法里面，这个过程如此漫长肯定不是原子的，那么就必须要加锁才能解决并发问题，经过仔细寻找确认，整个流程都没有加锁，再回头分析一下挂载网卡流程，发现整个流程也没有加锁，这就更进一步说明了并发问题的可能性。
并发问题的场景一般都是多个操作穿插交互执行，本来应该是串行执行的操作被打乱之后就会导致各种意想不到的问题，那么就模拟思考当时的场景，还是以定时任务的数据来源为切入点，来源有三种情况，一是在挂载操作之前从nova数据库中查询到info cache信息，二是在挂载操作过程中，三是在挂载完成之后，经过分析挂载流程代码，发现info cache是在挂载完成的最后一步才更新到数据库的，那么前两种情况其实就属于同一种情况了，都是在数据库中的info cache没有更新之前，就被定时任务拿到了，这个可能性很大，因为挂载流程比较漫长，很有可能被每分钟就执行一次的定时任务给乱入掉，如果定时任务拿到的是旧的info cache数据（也即脏数据），并且恰好在挂载操作执行成功之后紧接着就再次刷新数据库中的info cache，那么就会出现QA所说的症状。
画个流程示意图来确定一下二者的流程是否有重复，并且确认下有哪些时间点可以被乱入：
发现有很长一段操作都可能被乱入…
4. 重现问题
既然分析出了可能性很高的场景，就得去动手验证是否真的是这样的原因。如果一个问题不能被重现，那么你就不能断定你的分析过程是否正确，也就没办法确定解决方法是否正确，一切也都停留在假设上面，所以说重现问题比解决问题重要，能大概率重现的问题都是能被解决掉的，怕的就是无规律低概率重现的问题。
重现并发问题，一个基本的原则就是加延时，在两个操作的任意代码位置增加sleep代码，并且是任意时间长度，如果可以导致乱序执行，那就说明代码存在并发可能性。既然是定时任务冲掉了挂载网卡后的info cache信息，那么就在定时任务里面增加延时，让他先到后执行（强制他被挂载操作乱入掉），这样应该就能出现后续的刷掉正确info cache的问题。
直接改代码加延时：
|
|
diff --git a/nova/compute/manager.py b/nova/compute/manager.py index f240709..9184e08 100644 --- a/nova/compute/manager.py +++ b/nova/compute/manager.py @@ -5358,6 +5358,10 @@ class ComputeManager(manager.Manager): break if instance: + if instance['uuid'] == '61c1159c-3999-4bd5-9029-1757a55bce3d': + LOG.debug("xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx-------------------------xxxxxxxxxxxxx") + time.sleep(30) + LOG.debug("yyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy-------------------------xxxxxxxxxxxxx") # We have an instance now to refresh try: # Call to network API to get instance info.. this will |
上面的判断里面的uuid，是之后会被执行挂载网卡操作的虚拟机的uuid。重启nova-compute服务之后，等待定时任务执行到虚拟机61c1159c-3999-4bd5-9029-1757a55bce3d，日志会打印出”xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx————————-xxxxxxxxxxxxx”，看到之后这条日志后，执行挂载网卡操作，挂载成功后，执行nova list和nova interface-list，可以看到一切正常，再等半分钟左右，看到日志里面打印出”yyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy————————-xxxxxxxxxxxxx”，再次执行nova list和nova interface-list，发现与QA同样的症状，执行卸载网卡操作，报同样的port未挂载错误，查看nova数据库instance_info_cache表，网卡少了一块，问题重现！
5. 解决问题
NO！还没有，为啥呢？因为仔细分析过这个修复patch，发现他们还是没有解决定时任务数据源不准确问题，也即没有对数据来源加锁，更新info cache所用的数据仍然可能是脏数据，要确认是否修复正确，只需要把重现代码加入到上游代码里面进行测试验证就行了（这里也可以看出，找出问题的必现场景是多么重要），试过之后发现，问题依然存在，社区修复方法有问题。
我们自己的代码比较老了，但只要稍作改动就可以实现类似的锁和网卡info cache信息获取的原子性，这里不再列出具体改动。
6. 思路总结
总结一下思路：
- 确认问题症状
- 分析代码流程
- 根据日志输出检查分析过程的正确性
- 思考问题出现场景，并根据日志进行验证
- 再次回到代码，模拟代码执行过程，验证问题场景
- 整理可能的场景（可以使用画图、草稿纸上列出等方式），根据场景可能性的高低进行顺序，先尝试重现高概率的场景
- 根据代码流程和要重现的场景，思考重现辅助代码，对于并发问题来说，加延时是最简单有效的手段
- 重现出来之后，去社区搜索是否已经有类似bug，是否已经解决
- 如果已经解决，还需要分析并验证社区方法是否真正的修复了问题，毕竟社区虽然有很多牛人，也不一定会每个bug都找到重现方法，并一一验证patch正确性
- 如果验证ok，那问题解决，万事大吉
- 如果验证问题依旧存在，那就得想办法自己动手解决了
- 既然找到了问题的根因，那解决方法就有很多种，即便你不知道如何解决，也可以把必现条件反馈给社区，请社区牛人帮忙进行解决
之前也处理过nova中另外一个并发问题，处理流程也是十分类似的，所以觉得这个流程是比较通用的，整理出来分享给大家，希望能对大家解决bug有所帮助。
