Closed Bug 1171418 Opened 11 years ago Closed 10 years ago

Intermittent Win8 talos "INFO - WindowsError: [Error 32] The process cannot access the file because it is being used by another process: 'browser_output.txt'"

Categories

(Testing :: Talos, defect)

x86_64
Windows 8
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: RyanVM, Unassigned)

References

Details

(Keywords: intermittent-failure)

03:53:40 INFO - Running test ts_paint: 03:53:40 INFO - Started Thu, 04 Jun 2015 03:53:40 03:53:40 INFO - DEBUG : operating with platform_type : w8_ 03:53:40 INFO - DEBUG : created profile 03:53:40 INFO - DEBUG : command line: C:\slave\test\build\application\firefox\firefox -profile c:\users\cltbld~1.t-w\appdata\local\temp\tmpof7kny\profile http://localhost/getInfo.html 03:53:52 INFO - ProcessManager UNABLE to use job objects to manage child processes 03:53:52 INFO - DEBUG : initialized firefox 03:53:52 INFO - DEBUG : command line: C:\slave\test\build\application\firefox\firefox -profile c:\users\cltbld~1.t-w\appdata\local\temp\tmpof7kny\profile http://localhost/startup_test/tspaint_test.html 03:53:54 INFO - ProcessManager UNABLE to use job objects to manage child processes 03:53:54 INFO - INFO : Browser exited with error code: 0 03:53:59 INFO - DEBUG : Terminating: 1716, 2688 03:53:59 INFO - DEBUG : command line: C:\slave\test\build\application\firefox\firefox -profile c:\users\cltbld~1.t-w\appdata\local\temp\tmpof7kny\profile http://localhost/startup_test/tspaint_test.html 03:54:02 INFO - ProcessManager UNABLE to use job objects to manage child processes 03:54:02 INFO - INFO : Browser exited with error code: 0 03:54:07 INFO - DEBUG : Terminating: 2528 03:54:07 INFO - DEBUG : command line: C:\slave\test\build\application\firefox\firefox -profile c:\users\cltbld~1.t-w\appdata\local\temp\tmpof7kny\profile http://localhost/startup_test/tspaint_test.html 03:54:09 INFO - ProcessManager UNABLE to use job objects to manage child processes 03:54:09 INFO - INFO : Browser exited with error code: 0 03:54:14 INFO - DEBUG : Terminating: 2232 03:54:14 INFO - DEBUG : command line: C:\slave\test\build\application\firefox\firefox -profile c:\users\cltbld~1.t-w\appdata\local\temp\tmpof7kny\profile http://localhost/startup_test/tspaint_test.html 03:54:22 INFO - ProcessManager UNABLE to use job objects to manage child processes 03:54:22 INFO - INFO : Browser shutdown timed out after 5 seconds, terminating process. 03:54:22 INFO - INFO : Browser exited with error code: None 03:54:27 INFO - Exception in thread Thread-12: 03:54:27 ERROR - Traceback (most recent call last): 03:54:27 INFO - File "c:\mozilla-build\python27\Lib\threading.py", line 551, in __bootstrap_inner 03:54:27 INFO - self.run() 03:54:27 INFO - File "c:\mozilla-build\python27\Lib\threading.py", line 504, in run 03:54:27 INFO - self.__target(*self.__args, **self.__kwargs) 03:54:27 INFO - File "C:\slave\test\build\venv\lib\site-packages\talos\TalosProcess.py", line 63, in waitForQuit 03:54:27 INFO - self.proc.kill() 03:54:27 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 129, in kill 03:54:27 INFO - raise OSError(err) 03:54:27 INFO - OSError: Could not terminate process 03:54:27 INFO - INFO : Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] [browser_output.txt] 03:54:27 INFO - DEBUG : Terminating: 2172 03:54:27 INFO - INFO : 03:54:27 INFO - DEBUG : Terminating: 03:54:27 INFO - ProcessManager NOT managing child processes 03:54:27 INFO - Shumway is registered 03:54:27 INFO - __metrics Screen width/height:1600/1200 03:54:27 INFO - colorDepth:24 03:54:27 INFO - Browser inner width/height: 1010/674 03:54:27 INFO - __metrics 03:54:27 INFO - JavaScript error: resource:///modules/WebappManager.jsm, line 48: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver] 03:54:27 INFO - ProcessManager NOT managing child processes 03:54:27 INFO - Shumway is registered 03:54:27 INFO - __start_report1250__end_report 03:54:27 INFO - __startTimestamp1433415234105__endTimestamp 03:54:27 INFO - ProcessManager NOT managing child processes 03:54:27 INFO - Shumway is registered 03:54:27 INFO - __start_report923__end_report 03:54:27 INFO - __startTimestamp1433415240896__endTimestamp 03:54:27 INFO - ProcessManager NOT managing child processes 03:54:27 INFO - Shumway is registered 03:54:27 INFO - __start_report915__end_report 03:54:27 INFO - __startTimestamp1433415248807__endTimestamp 03:54:27 INFO - ProcessManager NOT managing child processes 03:54:27 INFO - Shumway is registered 03:54:27 INFO - __start_report3585__end_report 03:54:27 INFO - __startTimestamp1433415258157__endTimestamp 03:54:27 ERROR - Traceback (most recent call last): 03:54:27 INFO - File "C:\slave\test\build\venv\Scripts\talos-script.py", line 9, in <module> 03:54:27 INFO - load_entry_point('talos==0.0', 'console_scripts', 'talos')() 03:54:27 INFO - File "C:\slave\test\build\venv\lib\site-packages\talos\run_tests.py", line 311, in main 03:54:27 INFO - sys.exit(run_tests(parser)) 03:54:27 INFO - File "C:\slave\test\build\venv\lib\site-packages\talos\run_tests.py", line 249, in run_tests 03:54:27 INFO - talos_results.add(mytest.runTest(browser_config, test)) 03:54:27 INFO - File "C:\slave\test\build\venv\lib\site-packages\talos\ttest.py", line 406, in runTest 03:54:27 INFO - os.remove(browser_config['browser_log']) 03:54:27 INFO - WindowsError: [Error 32] The process cannot access the file because it is being used by another process: 'browser_output.txt' 03:54:27 ERROR - Return code: 1
Oh, this should be easy to fix. Just use mozfile.remove instead of os.remove (mozfile.remove is designed for this kind of issue). BTW, we should grep/replace every os.remove or os.unlink that way.
Hm, a bit more complicated, because we are now using mozfile.remove, but still the issue happen. Copied from the output of the last comment: 07:41:17 ERROR - Traceback (most recent call last): 07:41:17 INFO - File "C:\slave\test-pgo\build\talos_repo\talos\run_tests.py", line 348, in <module> 07:41:17 INFO - main() 07:41:17 INFO - File "C:\slave\test-pgo\build\talos_repo\talos\run_tests.py", line 344, in main 07:41:17 INFO - sys.exit(run_tests(parser)) 07:41:17 INFO - File "C:\slave\test-pgo\build\talos_repo\talos\run_tests.py", line 275, in run_tests 07:41:17 INFO - talos_results.add(mytest.runTest(browser_config, test)) 07:41:17 INFO - File "C:\slave\test-pgo\build\talos_repo\talos\ttest.py", line 297, in runTest 07:41:17 INFO - return self._runTest(browser_config, test_config) 07:41:17 INFO - File "C:\slave\test-pgo\build\talos_repo\talos\ttest.py", line 462, in _runTest 07:41:17 INFO - mozfile.remove(browser_config[key]) 07:41:17 INFO - File "C:\slave\test-pgo\build\venv\lib\site-packages\mozfile\mozfile.py", line 190, in remove 07:41:17 INFO - _call_with_windows_retry(os.remove, path) 07:41:17 INFO - File "C:\slave\test-pgo\build\venv\lib\site-packages\mozfile\mozfile.py", line 154, in _call_with_windows_retry 07:41:17 INFO - func(path) 07:41:17 INFO - WindowsError: [Error 32] The process cannot access the file because it is being used by another process: 'browser_output.txt' Looking before that in the log, we have the real issue: 07:41:08 INFO - INFO : Browser exited with error code: None 07:41:13 INFO - Exception in thread Thread-7: 07:41:13 ERROR - Traceback (most recent call last): 07:41:13 INFO - File "c:\mozilla-build\python27\Lib\threading.py", line 551, in __bootstrap_inner 07:41:13 INFO - self.run() 07:41:13 INFO - File "c:\mozilla-build\python27\Lib\threading.py", line 504, in run 07:41:13 INFO - self.__target(*self.__args, **self.__kwargs) 07:41:13 INFO - File "C:\slave\test-pgo\build\talos_repo\talos\TalosProcess.py", line 76, in waitForQuit 07:41:13 INFO - self.proc.kill() 07:41:13 INFO - File "C:\slave\test-pgo\build\venv\lib\site-packages\mozprocess\processhandler.py", line 129, in kill 07:41:13 INFO - raise OSError(err) 07:41:13 INFO - OSError: Could not terminate process 07:41:13 INFO - INFO : Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] [browser_output.txt] 07:41:13 INFO - DEBUG : Terminating: 2516 07:41:16 INFO - INFO : 07:41:16 INFO - DEBUG : Terminating: 07:41:17 INFO - ProcessManager NOT managing child processes So we are trying to kill the process but we fail (this is in a thread, so the exception is only printed but dot stop the program!). So the browser still have a handle on the log file, and this is why we can't remove it.
See Also: → 1188863
lets see how this bug works out, we have removed browser_output.txt (earlier errors) and now we get mozharness errors early on before launching the browser (as best as we can tell)
It's been nearly a month now - I really think this is fixed (previously we had the error in an interval of 5 days max). Closing it as resolved.
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.