×

一个tornado超时异常的分析过程

96
东植George
2017.07.31 15:54* 字数 1962

1.前言

我一直以为,一个IT技术人员,重要的不是知道多少语言,新语法或者新框架,而是遇到问题分析问题的能力。而分析问题的能力,一方面需要多锻炼,另一方面也要多看一些好的分析过程。以前工作过程查过不少比较深的bug,比如踩内存,coredump这类的问题,但是都觉得反正自己知道就行了懒得去写文章,现在觉得有点可惜,因为久了就容易忘,而且一些好的想法不能分享给更多的人也很可惜,况且有更多的人看到可能还会给你指出纰漏。

刚好在这里,再提一个我认为学习技术的方法问题。比如学一个新的框架,文档先浏览一下,然后就是照着教程的例子运行,接着弄懂例子的运行原理(看源码)。抓住在使用框架过程中遇到的问题,并以那个问题为切入点深入分析,这样一方面能解决问题;另一方面能借机对框架有更深入的了解,因为框架内容那么多,也不可能面面俱到,但是至少遇到问题的地方你深挖是有价值的。

2.问题描述

使用tornado并发测试一个http服务,而刚好服务有异常,未能响应。

因此,运行后一段时间,接收到了超时异常:

Traceback (most recent call last):  File "test_asynchttpclient.py", line 72, inIOLoop.current().run_sync(run)  File "/usr/local/lib/python2.7/dist-packages/tornado/ioloop.py", line 458, in run_sync    return future_cell[0].result()  File "/usr/local/lib/python2.7/dist-packages/tornado/concurrent.py", line 238, in result    raise_exc_info(self._exc_info)  File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 1063, in run    yielded = self.gen.throw(*exc_info)  File "test_asynchttpclient.py", line 67, in run    yield [aync_post(payload) for payload in payload_ls]  File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 1055, in run    value = future.result()  File "/usr/local/lib/python2.7/dist-packages/tornado/concurrent.py", line 238, in result    raise_exc_info(self._exc_info)  File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 828, in callback    result_list.append(f.result())  File "/usr/local/lib/python2.7/dist-packages/tornado/concurrent.py", line 238, in result    raise_exc_info(self._exc_info)  File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 1063, in run    yielded = self.gen.throw(*exc_info)  File "test_asynchttpclient.py", line 58, in aync_post    body=payload  File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 1055, in run    value = future.result()  File "/usr/local/lib/python2.7/dist-packages/tornado/concurrent.py", line 238, in result    raise_exc_info(self._exc_info)  File "", line 3, in raise_exc_info

tornado.httpclient.HTTPError: HTTP 599: Timeout during request

这个问题让我疑惑的地方是,我没有设置超时,为什么会抛出超时异常?是否有默认的超时设置,设置在哪里?

3.问题分析

因为我是并发测试了100条请求,所以异常信息就很乱,所以首先,我要做的就是简化得到的信息,我把请求改为1条,这时异常信息就很清晰了。

接着,在tornado的源码中,搜索异常的提示“HTTP 599: Timeout during request”,但是搜索不到。

还是从异常提示信息入手,在异常的函数堆栈中,提示错在:run_sync这个函数,因此进入源码查看函数定义:

def  run_sync(self, func, timeout=None):

             """ 

              The keyword-only argument ``timeout`` may be used to set a maximum                            duration for the function.  If the timeout expires,a `TimeoutError` is raised.

             """

我猜测可能跟这个timeout参数有关,可能会有默认的值,一开始我们还是尽量不要深入源码,所以我就尝试传一个timeout值为10进去(因为之前发现是大概15秒以上才抛异常)。运行后,结果是这样:

Traceback (most recent call last):  File "test_asynchttpclient.py", line 72, inIOLoop.current().run_sync(run,10)

File "/usr/local/lib/python2.7/dist-packages/tornado/ioloop.py", line 457, in run_sync

raise TimeoutError('Operation timed out after %s seconds' % timeout)

tornado.ioloop.TimeoutError: Operation timed out after 10 seconds

这时,我们发现,异常不一样!于是我试着尝试了20秒和30秒,发现20秒和30秒都是提示之前的异常。所以我想看看超时的秒数是多少,加入了打印时间。

begin     2017-07-31 10:34:25.092218

end        2017-07-31 10:34:45.111876

begin      2017-07-31 10:36:19.603607

end         2017-07-31 10:36:39.627447

相同的时间!好像每次超时都是20秒,查问题最重要的就是关注这些规律性的东西。因此我又实验了几次,最终的结论就是:超时就是20秒!

然后我就用20和2000(代码一般都是毫秒)去搜索源码,也没有什么发现。

没头绪的时候,就又回去看异常提示信息,异常信息和函数堆栈是查问题最重要的信息

tornado.httpclient.HTTPError: HTTP 599: Timeout during request

我们看到“httpclient.HTTPError”,httpclient应该是tornado的一个文件,于是我们搜索这个文件,找到了并且找到了HTTPError这个类:

classHTTPError(Exception):

"""Exception thrown for an unsuccessful HTTP request.

Attributes:

* ``code`` - HTTP error integer error code, e.g. 404.  Error code 599 is

used when no HTTP response was received, e.g. for a timeout.

* ``response`` - `HTTPResponse` object, if any.

Note that if ``follow_redirects`` is False, redirects become HTTPErrors,

and you can look at ``error.response.headers['Location']`` to see the

destination of the redirect.

"""

哈哈,里面提到了599错误,这不就是异常信息里面提到的599错误吗!因此,我们以关键字“HTTPError”搜索,查找传递599作为参数的调用的地方,最后发现只有两个地方是有可能:

使用pycharm的“find in path”

分别是SimpleAsyncHTTPClient::_on_timeout 和 _HTTPConnection::_on_timeout。

SimpleAsyncHTTPClient::_on_timeout
_HTTPConnection::_on_timeout

而分析SimpleAsyncHTTPClient::_on_timeout后发现,根据python的语法规定,类方法如果是以下划线开头,表示为protect方法,因此该方法基本上就是内部使用了,然后看了下其他地方的调用,发现有一个地方(SimpleAsyncHTTPClient::fetch_impl)用到了:

functools.partial(self._on_timeout, key,"in request queue"))

因此不可能输出异常信息打印的那句话,所以结果就只能是_HTTPConnection::_on_timeout。我们还需要来验证一下:

_HTTPConnection::_on_connect

上图的代码逻辑就是:如果_HTTPConnection::request有request_timeout值,就给设置一个超时异常,所以接下来我们要看是这个request_timeout是什么。

查看AsyncHTTPClient::fetch的源码以及根据之前文章对AsyncHTTPClient的分析,我们知道在AsyncHTTPClient::fetch的时候,会构造request对象:

request=HTTPRequest(url=request,**kwargs)

self.defaults=dict(HTTPRequest._DEFAULTS)

request=_RequestProxy(request,self.defaults)

而这个request对象就刚好赋值给_HTTPConnection::request,因此我们去看HTTPRequest类:

而_RequestProxy对象,则是把HTTPRequest类的_DEFAULTS赋值给成员:

哈哈,终于找到了,结合上面得出的20秒超时,我们可以确定,这个超时就是在这个位置设置的。

4.结论

AsyncHTTPClient::fetch会通过HTTPRequest类构造请求对象,并且使用HTTPRequest的一些默认的限制值,里面包括了:

connect_timeout=20.0,

request_timeout=20.0,

follow_redirects=True,

max_redirects=5,

。。。。。。

因此,即使我们调用run_sync没有设置timeout,都是AsyncHTTPClient::fetch构造的一些工具对象还是有默认的超时参数。

tip: 不知道有没有发现,超时20秒这个规律,对后面的分析起到了很重要的作用,这可能就是体现在了为什么查问题有先慢的区别上了。

日记本
Web note ad 1