在客户的环境中，我们的代码表现为twisted封装的http接口处理web请求忽快忽慢。
客户反馈一个页面上有获取绘图数据的请求，一页在一个屏幕上大概显示九个图，每次打开页面总有几个图一直在加载，刷新页面后之前没加载出来的出来了但是其他原本正常的又变成加载中了，而且要很慢才会返回结果，其他接口也类似这种情况，但是没有大的并发量也没有太大的数据量的环境莫名其妙的运行了几天就变成这样了。
项目是起了twistd三个进程分别跑在127.0.0.1:8001, 127.0.0.1:8002, 127.0.0.1:8003，然后用nginx代理的，查看nginx的log，可以看到很多接口大部分的响应时间超过60秒甚至有的超过了100秒，看上去像是定时的会有一段时间接口会变慢。
第一反应就是我们的后台有很多定时任务服务，并且这些服务也会调用到相关的接口实现函数，怀疑是不是定时任务触发时导致系统性能下降，但是日志里面有的超过100秒的接口是和定时任务完全无关的，但也无法确定是否是连锁反应造成的，客户环境上也没法去一一暂停那些定时任务做排查。
但是看代码逻辑也实在想不出会是哪里有问题，之前都是正常的而且都没人去动过，暂时没有任何排查思路。
这时候再一次看nginx的log，但是这次把请求的upstream也打印出来了，意外的发现还真是有规律！
所有慢的请求处理都打到了127.0.0.1:8003上，于是怀疑是这个进程开启了某些其他两个进程没有开启的定时任务配置导致的，查看配置令人失望的发现三个进程的配置都是一样的。upstream去掉8003后，服务即恢复正常。
用strace看这个进程的数据，发现一直在重复刷一些日志，不断的重复sendto一些类似日志的内容，然后遇到有个文件不存在的报错后又继续sendto， 内容都一样，看上去像是进入了一个死循环。
那问题应该就是这个死循环导致进程在处理请求的时候几乎瘫痪。只要解决掉这个死循环就不会有这个问题了。
查看这个被封装的twisted框架代码，看到在服务启动的时候会启动一个loggingobserver，用于同时记录python和twisted的日志到同一个文件，里面用的handler是带rotating，和strace里面的rename返回-1的错误应该是有关联的。
那就自己重写一个handler检查删除文件或者重命名时先判断文件是否存在，只有存在时才进行删除就不会因为报错而死循环了。
加大strace显示的字符串长度可以看到，报错是在twisted的logging里面的_observer.py里面在处理brokenObservers时导致了递归死循环，每一个事件循环应该都出发了这个递归死循环从而使CPU负载激增。
于是在github上看了下cpython logging的代码，发现并没有什么逻辑上的问题，rm或者mv的时候都是做了相应的是否存在目标文件的检查的，不会有报错的可能，但是这些检查逻辑上有一条fix issue注释是检查文件不存在的修复。也没太在意这个，看到没有破绽的逻辑再一次沉默了。
然后又去看了下正式环境里的python的logging代码，发现……代码竟然和我在github上看的不一样，一看python版本是2.7.5，github上的代码是2.7.14！
在2.7.5里面，所有的rotate的handler都没有检查要被重命名的源文件是否存在就直接对源文件进行删除。所以python2.7最新代码fix的18940这个issue就是我们遇到的bug:https://bugs.python.org/issue18940。
所以，升级python到2.7到最新版本就能解决这个bug。
至于具体为什么会导致递归死循环没有找到原因，因为这个框架是以前的同事封装的，只有在这个框架里面遇到这种情况才会递归死循环。
在twisted官网文档上的例子中使用logging observer没有发现会出现递归死循环的情况，应该是和框架里面的代码写法和twisted的机制有关。
