{"action":"created","issue":{"url":"https://api.github.com/repos/log2timeline/plaso/issues/589","repository_url":"https://api.github.com/repos/log2timeline/plaso","labels_url":"https://api.github.com/repos/log2timeline/plaso/issues/589/labels{/name}","comments_url":"https://api.github.com/repos/log2timeline/plaso/issues/589/comments","events_url":"https://api.github.com/repos/log2timeline/plaso/issues/589/events","html_url":"https://github.com/log2timeline/plaso/issues/589","id":133752193,"number":589,"title":"Workers idle for too long","user":{"login":"jpoling-dswrx","id":8975886,"avatar_url":"https://avatars.githubusercontent.com/u/8975886?v=3","gravatar_id":"","url":"https://api.github.com/users/jpoling-dswrx","html_url":"https://github.com/jpoling-dswrx","followers_url":"https://api.github.com/users/jpoling-dswrx/followers","following_url":"https://api.github.com/users/jpoling-dswrx/following{/other_user}","gists_url":"https://api.github.com/users/jpoling-dswrx/gists{/gist_id}","starred_url":"https://api.github.com/users/jpoling-dswrx/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jpoling-dswrx/subscriptions","organizations_url":"https://api.github.com/users/jpoling-dswrx/orgs","repos_url":"https://api.github.com/users/jpoling-dswrx/repos","events_url":"https://api.github.com/users/jpoling-dswrx/events{/privacy}","received_events_url":"https://api.github.com/users/jpoling-dswrx/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/log2timeline/plaso/labels/core","name":"core","color":"fbca04"},{"url":"https://api.github.com/repos/log2timeline/plaso/labels/question","name":"question","color":"cc317c"}],"state":"open","locked":false,"assignee":{"login":"Onager","id":1298404,"avatar_url":"https://avatars.githubusercontent.com/u/1298404?v=3","gravatar_id":"","url":"https://api.github.com/users/Onager","html_url":"https://github.com/Onager","followers_url":"https://api.github.com/users/Onager/followers","following_url":"https://api.github.com/users/Onager/following{/other_user}","gists_url":"https://api.github.com/users/Onager/gists{/gist_id}","starred_url":"https://api.github.com/users/Onager/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Onager/subscriptions","organizations_url":"https://api.github.com/users/Onager/orgs","repos_url":"https://api.github.com/users/Onager/repos","events_url":"https://api.github.com/users/Onager/events{/privacy}","received_events_url":"https://api.github.com/users/Onager/received_events","type":"User","site_admin":false},"milestone":null,"comments":17,"created_at":"2016-02-15T16:09:26Z","updated_at":"2016-02-19T22:36:57Z","closed_at":null,"body":"Testing the new build on both a Win7 and Win10 system, the processing seems to always complete with errors, with a sample below (running it with 7 workers):\r\n\r\n> 2016-02-13 00:52:43,490 [ERROR] (MainProcess) PID:59740 <multi_process> Workers idle for too long\r\n2016-02-13 00:52:43,491 [WARNING] (MainProcess) PID:59740 <multi_process> Processing aborted with engine error: Workers idle for too long.\r\n2016-02-13 00:52:43,494 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: StorageWriter (PID: 59753).\r\n2016-02-13 00:52:43,494 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: Collector (PID: 59755).\r\n2016-02-13 00:52:43,495 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: Worker_00 (PID: 59758).\r\n2016-02-13 00:52:43,495 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: Worker_01 (PID: 59760).\r\n2016-02-13 00:52:43,495 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: Worker_02 (PID: 59762).\r\n2016-02-13 00:52:43,496 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: Worker_03 (PID: 59766).\r\n2016-02-13 00:52:43,496 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: Worker_04 (PID: 59768).\r\n2016-02-13 00:52:43,496 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: Worker_05 (PID: 59770).\r\n2016-02-13 00:52:43,497 [WARNING] (MainProcess) PID:59740 <multi_process> Terminating process: Worker_06 (PID: 59775).\r\n2016-02-13 00:53:03,673 [WARNING] (MainProcess) PID:59740 <multi_process> Killing process: StorageWriter (PID: 59753).\r\n2016-02-13 00:53:03,674 [WARNING] (MainProcess) PID:59740 <multi_process> Killing process: Worker_02 (PID: 59762).\r\n2016-02-13 00:53:03,676 [WARNING] (MainProcess) PID:59740 <multi_process> Killing process: Worker_03 (PID: 59766).\r\n2016-02-13 00:53:03,677 [WARNING] (MainProcess) PID:59740 <multi_process> Killing process: Worker_06 (PID: 59775).\r\nProcessing completed with errors.\r\n\r\nDmesg shows no errors. "},"comment":{"url":"https://api.github.com/repos/log2timeline/plaso/issues/comments/186436586","html_url":"https://github.com/log2timeline/plaso/issues/589#issuecomment-186436586","issue_url":"https://api.github.com/repos/log2timeline/plaso/issues/589","id":186436586,"user":{"login":"Onager","id":1298404,"avatar_url":"https://avatars.githubusercontent.com/u/1298404?v=3","gravatar_id":"","url":"https://api.github.com/users/Onager","html_url":"https://github.com/Onager","followers_url":"https://api.github.com/users/Onager/followers","following_url":"https://api.github.com/users/Onager/following{/other_user}","gists_url":"https://api.github.com/users/Onager/gists{/gist_id}","starred_url":"https://api.github.com/users/Onager/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Onager/subscriptions","organizations_url":"https://api.github.com/users/Onager/orgs","repos_url":"https://api.github.com/users/Onager/repos","events_url":"https://api.github.com/users/Onager/events{/privacy}","received_events_url":"https://api.github.com/users/Onager/received_events","type":"User","site_admin":false},"created_at":"2016-02-19T22:36:57Z","updated_at":"2016-02-19T22:36:57Z","body":"What does the preprocessing output at the beginning of the log say? Does it do the detection, then fail to store it, perhaps?\r\n\r\nThis looks to me like a problem in one of the underlying storage layers, as there doesn't seem to be a python exception, and the worker stops responding immediately after grabbing a new pathspec off the queue. The desktop.ini is not causing this:\r\n\r\n```\r\n2016-02-17 23:52:11,167 DEBUG PID:4190 [ProcessFileEntry] done processing file entry: VSS4:TSK:/PATH/desktop.ini\r\n2016-02-17 23:52:11,167 DEBUG PID:4190 Pop on Worker_02 pathspec queue, port 56424\r\n```\r\nI suspect that fresh pathspec is stalling the worker.\r\n\r\nOne other debugging step (that will take a while), try running with `--single_process -d`. The workers are disappearing without a trace at the moment, and hopefully this will let us reliably trigger the error. When it goes to crash, you should get a python debug warning - `bt` will give a helpful backtrace.\r\n\r\n"}}