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)
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
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment 18•11 years ago
|
||
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.
Comment 19•11 years ago
|
||
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.
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment 27•11 years ago
|
||
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)
Comment 28•10 years ago
|
||
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.
Description
•