{"action":"created","issue":{"url":"https://api.github.com/repos/scrapy/scrapy/issues/3108","repository_url":"https://api.github.com/repos/scrapy/scrapy","labels_url":"https://api.github.com/repos/scrapy/scrapy/issues/3108/labels{/name}","comments_url":"https://api.github.com/repos/scrapy/scrapy/issues/3108/comments","events_url":"https://api.github.com/repos/scrapy/scrapy/issues/3108/events","html_url":"https://github.com/scrapy/scrapy/issues/3108","id":294317375,"number":3108,"title":"Scrapy crawl stalls and doesn't raise TimeoutError, prints logstats every minute","user":{"login":"sheri528","id":12407528,"avatar_url":"https://avatars0.githubusercontent.com/u/12407528?v=4","gravatar_id":"","url":"https://api.github.com/users/sheri528","html_url":"https://github.com/sheri528","followers_url":"https://api.github.com/users/sheri528/followers","following_url":"https://api.github.com/users/sheri528/following{/other_user}","gists_url":"https://api.github.com/users/sheri528/gists{/gist_id}","starred_url":"https://api.github.com/users/sheri528/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/sheri528/subscriptions","organizations_url":"https://api.github.com/users/sheri528/orgs","repos_url":"https://api.github.com/users/sheri528/repos","events_url":"https://api.github.com/users/sheri528/events{/privacy}","received_events_url":"https://api.github.com/users/sheri528/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":2,"created_at":"2018-02-05T09:03:48Z","updated_at":"2018-02-20T12:11:04Z","closed_at":null,"author_association":"NONE","body":"I got log like these every minute, and the process never quite itself unless I do \"kill -9\".\r\n```\r\n2018-02-05 16:38:21 [scrapy.extensions.logstats] INFO: Crawled 254 pages (at 0 pages/min), scraped 115 items (at 0 items/min)\r\n2018-02-05 16:39:21 [scrapy.extensions.logstats] INFO: Crawled 254 pages (at 0 pages/min), scraped 115 items (at 0 items/min)\r\n2018-02-05 16:40:21 [scrapy.extensions.logstats] INFO: Crawled 254 pages (at 0 pages/min), scraped 115 items (at 0 items/min)\r\n2018-02-05 16:41:21 [scrapy.extensions.logstats] INFO: Crawled 254 pages (at 0 pages/min), scraped 115 items (at 0 items/min)\r\n2018-02-05 16:42:21 [scrapy.extensions.logstats] INFO: Crawled 254 pages (at 0 pages/min), scraped 115 items (at 0 items/min)\r\n```\r\nThen I use gdb to track the process, I got these(part of them)\r\n```\r\n#0  0x00007f0eb65d6903 in __epoll_wait_nocancel () from /lib64/libc.so.6\r\n#1  0x00007f0ea9b04123 in pyepoll_poll (self=0x21c2180, args=<optimized out>, kwds=<optimized out>) at /usr/src/debug/Python-2.7.5/Modules/selectmodule.c:1005\r\n#2  0x00007f0eb72aabb0 in call_function (oparg=<optimized out>, pp_stack=0x7ffebc5e2c40) at /usr/src/debug/Python-2.7.5/Python/ceval.c:4408\r\n#3  PyEval_EvalFrameEx (\r\n    f=f@entry=Frame 0x3356680, for file /usr/lib64/python2.7/site-packages/twisted/internet/epollreactor.py, line 379, in doPoll (self=<EPollReactor(waker=<_UnixWaker(i=25, fi>, reactor=<...>, o=26) at remote 0x2714cd0>, _poller=<select.epoll at remote 0x21c2180>, threadpoolShutdownID=('shutdown', ('during', <instancemethod at remote 0x32674b0>, ()medCalls=[], _pendingTimedCalls=[<DelayedCall(resetter=<instancemethod at remote 0x32fcfa0>, seconds=<built-in function time>, args=(...), canceller=<instancemethod at remote  func=<LoopingCall(a=(...), interval=5, clock=<...>, f=<instancemethod at remote 0x32670a0>, running=True, kw={}, starttime=<float at remote 0x2ab0708>, call=<...>, _runAtStarller=None, callbacks=[]) at remote 0x32e4200>) at remote 0x32dde50>, time=<float at remote 0x39af480>, cancelled=0, called=0) at remote 0x368cdd0>, <DelayedCall(resetter=<instncated), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3040\r\n#4  0x00007f0eb72acefd in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=locals@entry=0x0, args=<optimized out>, argcount=2, kws=0x333f5b0, kwcount=0, \r\n    closure=closure@entry=0x0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3640\r\n#5  0x00007f0eb72aa3fc in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7ffebc5e2e50, func=<optimized out>) at /usr/src/debug/Python-2.7\r\n#6  call_function (oparg=<optimized out>, pp_stack=0x7ffebc5e2e50) at /usr/src/debug/Python-2.7.5/Python/ceval.c:4429\r\n#7  PyEval_EvalFrameEx (\r\n    f=f@entry=Frame 0x333f410, for file /usr/lib64/python2.7/site-packages/twisted/internet/base.py, line 1207, in mainLoop (self=<EPollReactor(waker=<_UnixWaker(i=25, fileno=actor=<...>, o=26) at remote 0x2714cd0>, _poller=<select.epoll at remote 0x21c2180>, threadpoolShutdownID=('shutdown', ('during', <instancemethod at remote 0x32674b0>, (), {})lls=[], _pendingTimedCalls=[<DelayedCall(resetter=<instancemethod at remote 0x32fcfa0>, seconds=<built-in function time>, args=(...), canceller=<instancemethod at remote 0x361=<LoopingCall(a=(...), interval=5, clock=<...>, f=<instancemethod at remote 0x32670a0>, running=True, kw={}, starttime=<float at remote 0x2ab0708>, call=<...>, _runAtStart=TruNone, callbacks=[]) at remote 0x32e4200>) at remote 0x32dde50>, time=<float at remote 0x39af480>, cancelled=0, called=0) at remote 0x368cdd0>, <DelayedCall(resetter=<instancemncated), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3040\r\n#8  0x00007f0eb72acefd in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=locals@entry=0x0, args=<optimized out>, argcount=1, kws=0x333ce60, kwcount=0, \r\n    closure=closure@entry=0x0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3640\r\n#9  0x00007f0eb72aa3fc in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7ffebc5e3060, func=<optimized out>) at /usr/src/debug/Python-2.7\r\n#10 call_function (oparg=<optimized out>, pp_stack=0x7ffebc5e3060) at /usr/src/debug/Python-2.7.5/Python/ceval.c:4429\r\n#11 PyEval_EvalFrameEx (\r\n    f=f@entry=Frame 0x333ccd0, for file /usr/lib64/python2.7/site-packages/twisted/internet/base.py, line 1195, in run (self=<EPollReactor(waker=<_UnixWaker(i=25, fileno=<func=<...>, o=26) at remote 0x2714cd0>, _poller=<select.epoll at remote 0x21c2180>, threadpoolShutdownID=('shutdown', ('during', <instancemethod at remote 0x32674b0>, (), {})), _j], _pendingTimedCalls=[<DelayedCall(resetter=<instancemethod at remote 0x32fcfa0>, seconds=<built-in function time>, args=(...), canceller=<instancemethod at remote 0x36134b0>pingCall(a=(...), interval=5, clock=<...>, f=<instancemethod at remote 0x32670a0>, running=True, kw={}, starttime=<float at remote 0x2ab0708>, call=<...>, _runAtStart=True, _d callbacks=[]) at remote 0x32e4200>) at remote 0x32dde50>, time=<float at remote 0x39af480>, cancelled=0, called=0) at remote 0x368cdd0>, <DelayedCall(resetter=<instancemethodncated), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3040\r\n#12 0x00007f0eb72acefd in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=locals@entry=0x0, args=<optimized out>, argcount=1, kws=0x2f2d9b0, kwcount=1, \r\n    closure=closure@entry=0x0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3640\r\n#13 0x00007f0eb72aa3fc in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7ffebc5e3270, func=<optimized out>) at /usr/src/debug/Python-2.7\r\n#14 call_function (oparg=<optimized out>, pp_stack=0x7ffebc5e3270) at /usr/src/debug/Python-2.7.5/Python/ceval.c:4429\r\n\r\n```\r\nTrack the last call by twisted in doPoll, I got timeout=5. \r\n```\r\n(gdb) py-locals\r\nself = <EPollReactor(waker=<_UnixWaker(i=25, fileno=<function at remote 0x1ab8d70>, reactor=<...>, o=26) at remote 0x2714cd0>, _poller=<select.epoll at remote 0x21c2180>, threadpoolShutdownID=('shutdown', ('during', <instancemethod at remote 0x32674b0>, (), {})), _justStopped=False, _newTimedCalls=[], _pendingTimedCalls=[<DelayedCall(resetter=<instancemethod at remote 0x32fcfa0>, seconds=<built-in function time>, args=(...), canceller=<instancemethod at remote 0x36134b0>, delayed_time=0, kw={}, func=<LoopingCall(a=(...), interval=5, clock=<...>, f=<instancemethod at remote 0x32670a0>, running=True, kw={}, starttime=<float at remote 0x2ab0708>, call=<...>, _runAtStart=True, _deferred=<Deferred(_canceller=None, callbacks=[]) at remote 0x32e4200>) at remote 0x32dde50>, time=<float at remote 0x39af480>, cancelled=0, called=0) at remote 0x368cdd0>, <DelayedCall(resetter=<instancemethod at remote 0x36512d0>, seconds=<built-in function time>, args=(...), canceller=<instancemethod at remote 0x3f8a730>, delayed_time=0, kw={}...(truncated)\r\ntimeout = <float at remote 0x34bc670>\r\n(gdb) print timeout\r\n$1 = 5\r\n```\r\nAnd also,\r\nscrapy==1.5.0\r\ntwisted==16.4.1\r\nOS==centOs, 3.10.0-693.11.1.el7.x86_64\r\nSo,why the process doesn't quite itself when timeout does have a value? How to fix it?\r\n"},"comment":{"url":"https://api.github.com/repos/scrapy/scrapy/issues/comments/366958451","html_url":"https://github.com/scrapy/scrapy/issues/3108#issuecomment-366958451","issue_url":"https://api.github.com/repos/scrapy/scrapy/issues/3108","id":366958451,"user":{"login":"cathalgarvey","id":1167837,"avatar_url":"https://avatars3.githubusercontent.com/u/1167837?v=4","gravatar_id":"","url":"https://api.github.com/users/cathalgarvey","html_url":"https://github.com/cathalgarvey","followers_url":"https://api.github.com/users/cathalgarvey/followers","following_url":"https://api.github.com/users/cathalgarvey/following{/other_user}","gists_url":"https://api.github.com/users/cathalgarvey/gists{/gist_id}","starred_url":"https://api.github.com/users/cathalgarvey/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cathalgarvey/subscriptions","organizations_url":"https://api.github.com/users/cathalgarvey/orgs","repos_url":"https://api.github.com/users/cathalgarvey/repos","events_url":"https://api.github.com/users/cathalgarvey/events{/privacy}","received_events_url":"https://api.github.com/users/cathalgarvey/received_events","type":"User","site_admin":false},"created_at":"2018-02-20T12:11:04Z","updated_at":"2018-02-20T12:11:04Z","author_association":"CONTRIBUTOR","body":"Hi @sheri528 - I just changed the title to assist others in finding the issue. Please let me know if the new title does not match what you meant. :)\r\n\r\nHave you found a solution to your problem, since your last post? Or, have you found more information on the problem, to help us understand it? Thanks!"}}
{"actor":{"display_login":"cathalgarvey"}}