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秒这个规律，对后面的分析起到了很重要的作用，这可能就是体现在了为什么查问题有先慢的区别上了。