【发布时间】：2017-05-20 20:27:27
【问题描述】：
我们有一个建立在以下基础上的服务器：
- CherryPy 3.2.2 for Windows
- Python 2.7.1
- 真子 0.3.6
- SQLAlchemy 0.7.2
- pyodbc 2.1.8
- 其他各种次要组件
它在以下平台上运行：
- Windows Server 2008
- Microsoft SQL Server 2008 网络
- 托管虚拟机
- xampp Apache 网关
在过去的几个月里，我们遇到过几次 cherypy 服务器无响应的情况。第一个症状是ajax请求超时，在浏览器中重新加载页面超时，然后最终Apache将返回502，因为cherrypy将不再接受任何连接。重新启动 python 服务可以解决问题。有时它会在 10 分钟内从超时变为 502，有时它会持续超时半个多小时，我们才意识到必须重新启动。
服务器可以运行数周而没有问题，但有时问题可能会在几个小时内出现 5 次。
我们对所有请求实施了一些额外的日志记录，以识别模式。首先，它似乎不是由任何一种特定类型的请求、一天中的时间、负载、用户等触发的。但是，我们偶尔会遇到 SQL 死锁错误，有时我们会遇到樱桃请求超时错误。 SQL 死锁似乎与请求清理无关，并且它们与服务器冻结的时间无关。请求超时确实发生在类似的时间，但我只见过几次，它们不会每次都发生。
在每个模块的每个入口点中，我们添加了以下日志记录：
util.write_to_debuglog("ajax", "START", _path)
# Call AJAX target providing the session object
_args.update(session=session)
result=target(**_args)
util.write_to_debuglog("ajax", "FINISH", _path)
return result
在调试日志中，我们还打印出会话 ID 和用户名，这样我就可以准确地看到请求的来源。
昨天出现故障时，调试日志显示如下（向后工作）：
- 我在 11:59:08 重启了服务器
- 之前的日志条目是 11:23:11，START ajax get_orders User1（没有对应的 FINISH）
- 11:23:04 到 11:22:33 之间有 9 对成功的 START 和 FINISH 不同用户和不同功能的请求
- 在 11:22:31 是一个 START ajax get_orders User2（没有完成）
- 11:22:27 到 11:22:23 4 对 START 和 FINISH，不同的用户和功能
- 11:22:22 START ajax do_substitutions User3（没有完成）
- 11:22:19 到 11:15:52 299 对 START 和 FINISH，不同的用户（包括 User1、User2 和 User3）和不同的功能（包括挂起的那些）
- 11:15:52 START ajax get_filling_pack User4（没有完成）
- 11:15:51 到 11:15:45 13 对 START 和 FINISH
- 11:15:45 START ajax echo User5（没有完成）
- 11:15:43 到 11:14:56 63 对 START 和 FINISH
- 11:14:56 START ajax echo User6（没有完成）
- 11:14:56 到 11:13:40 104 对 START 和 FINISH
- 11:13:40 开始 ajax update_supplies User7（没有完成）
- 11:13:38 到 11:13:17 36 对 START 和 FINISH
- 11:13:17 开始发布 set_status User8（未完成）
- 然后正常活动回到服务器计划重启时的午夜
在 11:23:11 和 11:59:08 之间，如果您尝试访问服务器，浏览器最终会超时，而在其他时候，它最终会到达一个点，您会立即从 Apache 获得 502 错误网关。这告诉我，在此期间，cherrypy 仍在接受套接字连接，但日志显示请求并未到来。即使是cherrypy访问日志也没有显示任何内容。
127.0.0.1 - - [05/Jan/2017:11:23:04] "GET /***/get_joblist HTTP/1.1" 200 18 "" "***/2.0"
127.0.0.1 - - [05/Jan/2017:11:59:09] "GET /***/upload_printer HTTP/1.1" 200 38 "" "***/2.0"
在这一天，错误日志文件中有两次请求超时，但这并不常见。
[05/Jan/2017:11:22:04] Traceback (most recent call last):
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 169, in trap
return func(*args, **kwargs)
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 96, in __call__
return self.nextapp(environ, start_response)
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 379, in tail
return self.response_class(environ, start_response, self.cpapp)
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 222, in __init__
self.run()
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 320, in run
request.run(meth, path, qs, rproto, headers, rfile)
File "c:\python27\lib\site-packages\cherrypy\_cprequest.py", line 603, in run
raise cherrypy.TimeoutError()
TimeoutError
[05/Jan/2017:11:22:05] Traceback (most recent call last):
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 169, in trap
return func(*args, **kwargs)
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 96, in __call__
return self.nextapp(environ, start_response)
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 379, in tail
return self.response_class(environ, start_response, self.cpapp)
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 222, in __init__
self.run()
File "c:\python27\lib\site-packages\cherrypy\_cpwsgi.py", line 320, in run
request.run(meth, path, qs, rproto, headers, rfile)
File "c:\python27\lib\site-packages\cherrypy\_cprequest.py", line 603, in run
raise cherrypy.TimeoutError()
TimeoutError
我们不会更改响应超时，所以这应该是默认的 5 分钟。基于此假设，错误与任何已挂起的请求无关。 11:22:04 的超时意味着 11:18:04 的请求，但当时的所有请求都是成功的。而确实挂起的 8 个请求的时间远远超过 5 分钟，并且从未超时。
为什么一种类型的请求会为一个用户挂起，但对其他用户继续成功？
如果他们之前已经工作了几天或几周，为什么还要挂起？
为什么请求超时没有清除所有这些？
为什么服务器会到达根本不接受任何请求的地步？ 8个并发请求肯定不是服务器最大值吗？
为什么服务器仍然接受套接字连接但不处理请求？
对于如何诊断或解决这些问题的任何建议将不胜感激。
谢谢， 帕特里克。
【问题讨论】：
-
你介意分享你的cherrypy配置吗？附言这个问题的某些部分可能会衍生为the new issue here
标签： python-2.7 timeout deadlock cherrypy freeze