背景前两天晚上线上系统突然挂了。马上打开在线错误日志，只能得到一堆无意义的程序调用栈（traceback）输出，于是团队成员陷入了漫长而盲目的排查过程。还好问题已经解决了，但是我一直纳闷为什么log中打印的callstack没有意义。根据经验，它应该在异常产生过程中打印调用堆栈。经过后续的源码分析和排查，发现其实是项目中的一段旧代码使用了monkeypatch导致的，这也是本文要讨论的。什么是monkeypatchingMonkeypatching是一种编程方法，用于修改（增、改、删等）系统软件在运行时的行为。动态语言中有广泛的猴子补丁应用程序。例如，Ruby的开放类特性支持扩展类的定义，甚至支持在运行时实现替换方法。Python的方法或函数可以在运行时被替换。应用非常方便，其他语言如JavaScript也可以猴子补丁。猴子补丁是一把双刃剑。monkeypatch凭借其灵活性，可以实现补丁代码和应用代码的完全分离，同时保持应用代码的调用方式不变。从应用代码的角度来看，它调用了某个模块原来定义的方法或函数；从被调用的方法或函数的角度来看，猴子补丁的存在对它来说是透明的。下面展示了一个Python语言的Demo：让我们从一个极简的例子开始，向这个美好的世界问好：defgreet():print("HelloWorld!")if__name__=="__main__":greet()如上脚本被执行，我们得到的结果是：$pythondemo.pyHelloWorld!这很简单。接下来，如果我们做一个猴子补丁：我们扩展了原来greet的行为，现在除了打印信息，我们还需要打印当前时间：fromdatetimeimportdatetimedefgreet():print("HelloWorld!")#monkeypatchoriginal_greet=greetdefgreet_with_time():original_greet()print(datetime.now())greet=greet_with_time#替换实现#monkeypatchif__name__=="__main__":greet()#这里的调用与原来的没有变化。运行它，结果是：$pythondemo.pyHelloWorld！2019-09-2123:40:42.575782我们得到了预期的结果！从代码分析，我们添加了一个新的函数greet_with_time，它会调用原来的greet函数，然后打印当前时间，最后通过将函数赋值给一个变量来替换greet函数。但是对于最后一个greet函数的调用，不需要做任何改动，从而达到调用greet函数同样的目的，但是行为却大不相同。上面的demo由于篇幅有限，只是简化了代码，实际项目中的monkeypatch代码总是在另一个模块或文件中。想象一下，在一个复杂的大型项目中，如果你的代码中充斥着猴子补丁，这对系统行为分析和故障排除来说将是一场灾难性的挑战。既然对monkeypatching有了一定的了解，下面就来看看我在实际项目中遇到的例子。一堆无意义的堆栈信息。我在本地复现了开头提到的异常。以下是与线上环境一致的堆栈信息：2019-09-1917:30:11.103|CRITICAL|138:140147476383488|log.py:282|log.log|Taskcommand.celery.crontab_task.some_task[538ddb72-89b0-45fe-811e-107202dc665b]内部错误：AttributeError(“'butlong''objectinshasnoat',)Traceback（最后一次调用）：文件“/usr/local/bin/celery”，第10行，在sys.exit(main())文件“/usr/local/lib/python2.7/dist-packages/celery/__main__.py",line30,inmainmain()......由于篇幅所限，这里省略了很多无意义的内容File"/usr/local/lib/python2.7/dist-packages/celery/worker/job.py”，第384行，在on_successreturnself.on_failure(ret_value)File“/usr/local/lib/python2.7/dist-packages/celery/worker/job.py“，第443行，在on_failureself._log_error(exc_info,send_failed_event=send_failed_event)文件“/usr/local/lib/python2.7/dist-packages/celery/worker/job.py”中，第511行，在_log_error'internal'：内部}}）文件“/usr/local/lib/python2.7/dist-packages/celery/utils/log.py",line282,inlogreturnLogger.log(self,*args,**kwargs)None从这个堆栈信息来看，它打印的其实是调用了Logger.log函数Stack，有里面没有代码看到.insert相关的字，跟AttributeError("'long'objecthasnoattribute'insert'",)没有关系，这样的栈信息有和没有基本一样，差不多，然后我通过编辑器通过源代码进行了更多探索。首先我还是用上面的栈来分析哪里出了问题，所以先看celery/worker/job.py:504-511处的代码：context={'hostname':self.hostname,'id':self.id,'name':self.name,'exc':exception,'traceback':traceback,'args':sargs,'kwargs':skwargs,'description':描述,}logger.log(严重性,format.strip(),context,exc_info=exc_info,extra={'data':{'id':self.id,'name':self.name,'args':sargs,'kwargs':skwargs,'主机名':self.hostname,'internal':internal}})这里调用了logger.log方法（logger的来源可以在Celery代码中分析，但不是本文的重点，就不赘述了）expanded)并通过context对象传入了两个重要的信息：exception和traceback。在进一步阅读logger.log源码??时，确认了这个日志打印的核心依赖于调用traceback.print_exception函数：defformatException(self,ei):"""格式化并返回指定的异常信息为一个字符串。此默认实现仅使用traceback.print_exception()"""sio=io.StringIO()tb=ei[2]traceback.print_exception(ei[0],ei[1],tb,None,sio),回到celery/worker/job.py:504-511的代码，在logger.log前面插入了两种打印错误堆栈信息的代码：#context=...################################################################importtracebackas_traceback#Method1:likewhatlogger.logdoes_traceback.print_exception(*exc_info)#Method2:use`format_exception`而不是print(''.join(_traceback.format_exception(*exc_info)))##################################################################logger.log(....重启celery后，执行异步后task，第一个错误栈和我之前贴的栈信息是完全一致的，这个很好理解，毕竟这里print_exception函数的调用是logger.log中的核心实现而format_exception的调用给了我真正有意的错误堆信息：Traceback(mostrecentcalllast):File"/usr/local/lib/python2.7/dist-packages/celery/app/trace.py",line283，在trace_taskuuid，retval，SUCCESS，request=task_request，文件“/usr/local/lib/python2.7/dist-packages/celery/backends/base.py”，第271行，在store_resultrequest=request，**kwargs)文件“/usr/local/lib/python2.7/dist-packages/celery/backends/base.py”，第505行，在_store_resultself.set(self.get_key_for_task(task_id),self.encode(meta))文件“/usr/local/lib/python2.7/dist-packages/celery/backends/redis.py”，第161行，在setreturnself.ensure(self._set,(key,value),**retry_policy)File"/usr/local/lib/python2.7/dist-packages/celery/backends/redis.py",line150,inensure**retry_policyFile"/usr/local/lib/python2.7/dist-packages/kombu/utils/__init__.py",line246,inretry_over_timereturnfun(*args,**kwargs)File"/usr/local/lib/python2.7/dist-packages/celery/backends/redis.py”，第170行，在_setpipe.execute()文件“/usr/local/lib/python2.7/dist-packages/redis/client.py”，第2879行，在executereturnexecute(conn,stack,raise_on_error)文件“/usr/local/lib/python2.7/dist-packages/redis/client.py”，第2785行，在_execute_transactionresponse.insert(i,e)AttributeError:'long'objecthasnoattribute'insert'家伙，现在清楚了，原来这段代码中异常的真正源头在这里！但是问题来了，为什么print_exception和format_exception给出的堆栈信息不一样呢？我搜了下满满的官方文档疑惑，但困惑更重：traceback.format_exception(etype,value,tb[,limit])格式化堆栈跟踪和异常信息。参数与print_exception()的相应参数含义相同。返回值是一个字符串列表，每个字符串以换行符结尾，有些包含内部换行符。当这些行被连接并打印时，正是打印与print_exception()相同的文本。重点在最后一句。Python官方文档说这两个函数输出的错误栈是一样的（完全一样的文字）！找出monkeypatch其实问题的真正排查过程花了我很多时间，我一直没有想过猴子补丁，但在去朋友吃饭的路上，我终于在地铁上有了主意。我用手机翻了一下公司GitLab上的项目代码，找到了罪魁祸首。def_patch_print_exception():importtracebackdefcustom_print_exception(etype,value,tb,limit=None,file=None):exc_info=sys.exc_info()stack=traceback.extract_stack()#...省略其他源代码traceback.print_exception=custom_print_exception从补丁代码来看，补丁直接覆盖了原来的代码，实现直接忽略了传入的几个异常信息参数！所以才有了这么大的乌龙，还有一个无关的异常堆栈信息！(╯‵′)╯︵┻━┻猴子补丁技术故障排除猴子补丁等编程技术各有利弊，使用时必须格外小心，但也不必远离。关键是要掌握必要的故障排除技巧。基于这节课，我发现了一些可能有用的方法：1.通过函数或自身属性查看方法或函数的信息。众所周知，Python中的所有对象都有一堆内置属性，函数也不例外。项目示例：#djangoshellIn[1]:traceback.print_exception.func_codeOut[1]:一看就知道这个函数的真正代码其实就是工程中的patch代码！2.使用inspect包检查Python本身提供了很多工具包，inspect自然是强大的工具之一，可以用来对几乎所有类型进行Runtime检查，还是我的实际例子：#djangoshellIn[1]：导入inspectIn[2]:inspect.getfile(traceback.print_exception)Out[2]:'/Users/boy/work_area/项目/项目源/lib/common/logger.py'In[3]:inspect.getsource(traceback.print_exception)Out[3]:'\tdefcustom_print_exception(etype,value,tb,limit=None,file=None):......\n'In[4]:printinspect.getsource(traceback.print_exception)Out[4]:defcustom_print_exception(etype,value,tb,limit=None,file=None):disable=redefined-builtiniffileisNone:file=sys.stderrexc_info=sys.exc_info()stack=traceback.extract_stack()...总之，如果代码的行为不符合预期但不能对应官方文档或官方源码，则可能是依赖的方法或函数被打了猴子补丁，而确认猴子补丁的最快方法是第一时间检查被调用函数或方法的实际定义，即套用上面的方法！顺便说一句，我在做Ruby开发的时候，也遇到过monkeypatching的陷阱。Ruby中有类似的方法：file,line=A.new.method(:foo).source_locationputs"Methodfooisdefinedin#{file},line#{line}"#=>"Methodfooisdefinedintemp.rb,line2”参考链接维基百科：MonkeypatchPython官方文档：traceback.format_exceptionPython官方文档：inspectHowcanIgetsourcecodeofamethoddynamically以及此方法位于哪个文件中
