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

RESOLVED FIXED

Status

Testing
Talos
RESOLVED FIXED
3 years ago
2 years ago

People

(Reporter: RyanVM, Unassigned)

Tracking

({intermittent-failure})

Firefox Tracking Flags

(Not tracked)

Details

(Reporter)

Description

3 years ago
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
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
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: → bug 1188863
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
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
Last Resolved: 2 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.