{"action":"created","issue":{"url":"https://api.github.com/repos/binux/pyspider/issues/536","repository_url":"https://api.github.com/repos/binux/pyspider","labels_url":"https://api.github.com/repos/binux/pyspider/issues/536/labels{/name}","comments_url":"https://api.github.com/repos/binux/pyspider/issues/536/comments","events_url":"https://api.github.com/repos/binux/pyspider/issues/536/events","html_url":"https://github.com/binux/pyspider/issues/536","id":175970164,"number":536,"title":"on_finished started before other task finished","user":{"login":"wonderay","id":4599206,"avatar_url":"https://avatars.githubusercontent.com/u/4599206?v=3","gravatar_id":"","url":"https://api.github.com/users/wonderay","html_url":"https://github.com/wonderay","followers_url":"https://api.github.com/users/wonderay/followers","following_url":"https://api.github.com/users/wonderay/following{/other_user}","gists_url":"https://api.github.com/users/wonderay/gists{/gist_id}","starred_url":"https://api.github.com/users/wonderay/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wonderay/subscriptions","organizations_url":"https://api.github.com/users/wonderay/orgs","repos_url":"https://api.github.com/users/wonderay/repos","events_url":"https://api.github.com/users/wonderay/events{/privacy}","received_events_url":"https://api.github.com/users/wonderay/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2016-09-09T09:46:50Z","updated_at":"2016-09-14T10:21:47Z","closed_at":null,"body":"the following script can reproduce the issue sometimes\r\n```\r\n\r\nimport re\r\nimport logging\r\nimport time\r\n\r\nfrom pyspider.libs.base_handler import *\r\n\r\n\r\n\r\nclass Handler(BaseHandler):\r\n    crawl_config = {\r\n    }\r\n\r\n    def on_start(self):\r\n        # mock some long time processing\r\n        time.sleep(20)\r\n        \r\n        self.crawl('http://sony.it168.com/', callback=self.index_page)\r\n        \r\n    def index_page(self, response):\r\n        \r\n        for each in response.doc('a[href^=\"http\"]').items():\r\n            url = each.attr.href\r\n            \r\n            # limit follows\r\n            if re.match(\"http://sony.it168.com/forum-32\\d+-1.html\", url):\r\n                self.crawl(each.attr.href, callback=self.detail_page)\r\n\r\n    def detail_page(self, response):\r\n        return {\r\n            \"url\": response.url,\r\n            \"title\": response.doc('title').text(),\r\n        }\r\n    \r\n    @not_send_status\r\n    def on_finished(self, response, task):\r\n        pass\r\n```\r\nLogs\r\n\r\n```\r\n[I 160909 17:25:24 scheduler:508] in 5m: new:0,success:3,retry:0,failed:0 test_delay:0,3,0,0\r\n[I 160909 17:25:26 scheduler:709] new task test_delay:on_start data:,on_start\r\n[I 160909 17:25:27 scheduler:866] select test_delay:on_start data:,on_start\r\n[I 160909 17:25:27 tornado_fetcher:179] [200] test_delay:on_start data:,on_start 0s\r\n[I 160909 17:25:47 processor:199] process test_delay:on_start data:,on_start -> [200] len:8 -> result:None fol:1 msg:0 err:None\r\n[I 160909 17:25:47 scheduler:866] select test_delay:on_finished data:,on_finished\r\n[I 160909 17:25:47 scheduler:807] task done test_delay:on_start data:,on_start\r\n[I 160909 17:25:47 scheduler:709] new task test_delay:f4ed7b0b63096fe5b2863765862f3dc6 http://sony.it168.com/\r\n[I 160909 17:25:47 tornado_fetcher:179] [200] test_delay:on_finished data:,on_finished 0s\r\n[I 160909 17:25:47 processor:199] process test_delay:on_finished data:,on_finished -> [200] len:11 -> result:None fol:0 msg:0 err:None\r\n[I 160909 17:25:47 scheduler:866] select test_delay:f4ed7b0b63096fe5b2863765862f3dc6 http://sony.it168.com/\r\n[I 160909 17:25:48 tornado_fetcher:409] [200] test_delay:f4ed7b0b63096fe5b2863765862f3dc6 http://sony.it168.com/ 0.50s\r\n[I 160909 17:26:08 processor:199] process test_delay:f4ed7b0b63096fe5b2863765862f3dc6 http://sony.it168.com/ -> [200] len:33020 -> result:None fol:3 msg:0 err:None\r\n[I 160909 17:26:08 scheduler:807] task done test_delay:f4ed7b0b63096fe5b2863765862f3dc6 http://sony.it168.com/\r\n[I 160909 17:26:08 scheduler:709] new task test_delay:77f803d163cb5679680cbd2299be6e9d http://sony.it168.com/forum-323-1.html\r\n[I 160909 17:26:08 scheduler:709] new task test_delay:92980a5ef3757874ba03d49692731d0b http://sony.it168.com/forum-321-1.html\r\n[I 160909 17:26:08 scheduler:709] new task test_delay:0f456edb8fe2692e735daeb8e5a639aa http://sony.it168.com/forum-322-1.html\r\n[I 160909 17:26:08 scheduler:866] select test_delay:92980a5ef3757874ba03d49692731d0b http://sony.it168.com/forum-321-1.html\r\n[I 160909 17:26:08 scheduler:866] select test_delay:77f803d163cb5679680cbd2299be6e9d http://sony.it168.com/forum-323-1.html\r\n[I 160909 17:26:08 scheduler:866] select test_delay:0f456edb8fe2692e735daeb8e5a639aa http://sony.it168.com/forum-322-1.html\r\n[I 160909 17:26:08 tornado_fetcher:409] [200] test_delay:77f803d163cb5679680cbd2299be6e9d http://sony.it168.com/forum-323-1.html 0.29s\r\n[I 160909 17:26:08 tornado_fetcher:409] [200] test_delay:92980a5ef3757874ba03d49692731d0b http://sony.it168.com/forum-321-1.html 0.31s\r\n[I 160909 17:26:08 processor:199] process test_delay:77f803d163cb5679680cbd2299be6e9d http://sony.it168.com/forum-323-1.html -> [200] len:74447 -> result:{'title':  fol:0 msg:0 err:None\r\n[I 160909 17:26:08 result_worker:33] result test_delay:77f803d163cb5679680cbd2299be6e9d http://sony.it168.com/forum-323-1.html -> {'url': 'http://sony.it168.com\r\n[I 160909 17:26:08 tornado_fetcher:409] [200] test_delay:0f456edb8fe2692e735daeb8e5a639aa http://sony.it168.com/forum-322-1.html 0.35s\r\n[I 160909 17:26:08 scheduler:807] task done test_delay:77f803d163cb5679680cbd2299be6e9d http://sony.it168.com/forum-323-1.html\r\n[I 160909 17:26:08 processor:199] process test_delay:92980a5ef3757874ba03d49692731d0b http://sony.it168.com/forum-321-1.html -> [200] len:93092 -> result:{'title':  fol:0 msg:0 err:None\r\n[I 160909 17:26:08 result_worker:33] result test_delay:92980a5ef3757874ba03d49692731d0b http://sony.it168.com/forum-321-1.html -> {'url': 'http://sony.it168.com\r\n[I 160909 17:26:08 processor:199] process test_delay:0f456edb8fe2692e735daeb8e5a639aa http://sony.it168.com/forum-322-1.html -> [200] len:91740 -> result:{'title':  fol:0 msg:0 err:None\r\n[I 160909 17:26:08 result_worker:33] result test_delay:0f456edb8fe2692e735daeb8e5a639aa http://sony.it168.com/forum-322-1.html -> {'url': 'http://sony.it168.com\r\n[I 160909 17:26:08 scheduler:807] task done test_delay:92980a5ef3757874ba03d49692731d0b http://sony.it168.com/forum-321-1.html\r\n[I 160909 17:26:08 scheduler:807] task done test_delay:0f456edb8fe2692e735daeb8e5a639aa http://sony.it168.com/forum-322-1.html\r\n[I 160909 17:26:09 scheduler:866] select test_delay:on_finished data:,on_finished\r\n[I 160909 17:26:09 tornado_fetcher:179] [200] test_delay:on_finished data:,on_finished 0s\r\n```\r\nAccording to the log, we find that `on_finished` started before `on_start` has done. `on_finished` scheduled  again when all tasks done, the first time `on_finished` started unexpected\r\n\r\npython version: 3.5.2\r\npyspider version: 0.3.8\r\n\r\nCan you please help me to resolve the problem,  thank you very much\r\n"},"comment":{"url":"https://api.github.com/repos/binux/pyspider/issues/comments/246969223","html_url":"https://github.com/binux/pyspider/issues/536#issuecomment-246969223","issue_url":"https://api.github.com/repos/binux/pyspider/issues/536","id":246969223,"user":{"login":"wonderay","id":4599206,"avatar_url":"https://avatars.githubusercontent.com/u/4599206?v=3","gravatar_id":"","url":"https://api.github.com/users/wonderay","html_url":"https://github.com/wonderay","followers_url":"https://api.github.com/users/wonderay/followers","following_url":"https://api.github.com/users/wonderay/following{/other_user}","gists_url":"https://api.github.com/users/wonderay/gists{/gist_id}","starred_url":"https://api.github.com/users/wonderay/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wonderay/subscriptions","organizations_url":"https://api.github.com/users/wonderay/orgs","repos_url":"https://api.github.com/users/wonderay/repos","events_url":"https://api.github.com/users/wonderay/events{/privacy}","received_events_url":"https://api.github.com/users/wonderay/received_events","type":"User","site_admin":false},"created_at":"2016-09-14T10:21:47Z","updated_at":"2016-09-14T10:21:47Z","body":"@beader Thank you , but I think it is a issue at least a bad design. thanks again"}}
{"actor":{"display_login":"wonderay"}}