1391811 - Intermittent WindowsError: [Error 5] Access is denied: u'c:/builds/tooltool_cache\\b726645f9d26c5a3048720b3839166021c1cf91a02d2ff2f10c49adced7455c7352e18b5052084d80bf9d1c40ec1bf72d0397921b8cd23262f89fdbd10def58f'

Status: RESOLVED INVALID

(Release Engineering :: Applications: MozharnessCore, defect)

Description

[Treeherder Bug Filer]

Filed by: wkocher [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=124211598&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/WOpI1Jl3QDug79gQcviJEw/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

4 failures in 949 pushes (0.004 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 2
* autoland: 2

Platform breakdown:
* windows2012-64: 2
* windows2012-64-noopt: 1
* windows2012-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1391811&startday=2017-08-14&endday=2017-08-20&tree=all

Comment 2

[Mike Hommey [:glandium]]

This is yet another case of non-failing errors being shown by treeherder failure classification, while the actual error is not shown in there. I just got a failure on try with a link to this bug, while the actual error has nothing to do with the actual error from the log linked in comment 0.

Comment 3

[Intermittent Failures Robot]

22 failures in 908 pushes (0.024 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 14
* mozilla-inbound: 3
* mozilla-beta: 2
* try: 1
* mozilla-release: 1
* mozilla-central: 1

Platform breakdown:
* windows2012-64: 15
* windows2012-64-noopt: 4
* windows2012-32: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1391811&startday=2017-08-21&endday=2017-08-27&tree=all

Comment 4

[Intermittent Failures Robot]

11 failures in 939 pushes (0.012 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 6
* try: 2
* mozilla-inbound: 2
* mozilla-central: 1

Platform breakdown:
* windows2012-64: 9
* windows7-32: 1
* windows2012-64-noopt: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1391811&startday=2017-08-28&endday=2017-09-03&tree=all

Comment 5

[Intermittent Failures Robot]

4 failures in 1032 pushes (0.004 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 3
* mozilla-beta: 1

Platform breakdown:
* windows2012-64: 4

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1391811&startday=2017-09-11&endday=2017-09-17&tree=all

Comment 6

[Intermittent Failures Robot]

3 failures in 943 pushes (0.003 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 3

Platform breakdown:
* windows2012-64: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1391811&startday=2017-09-18&endday=2017-09-24&tree=all

Comment 7

[Intermittent Failures Robot]

5 failures in 885 pushes (0.006 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 4
* mozilla-inbound: 1

Platform breakdown:
* windows2012-64: 3
* windows7-32: 1
* windows2012-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1391811&startday=2017-09-25&endday=2017-10-01&tree=all

Comment 8

[Intermittent Failures Robot]

4 failures in 824 pushes (0.005 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 3
* autoland: 1

Platform breakdown:
* windows7-32: 2
* windows2012-32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1391811&startday=2017-10-02&endday=2017-10-08&tree=all

Comment 9

[Andrei Obreja [:aobreja NOT AVAILABLE][:buildduty]]

This is a very isolated case, we have 0.005-0,006 failures/push or even less.
Also by checking the logs it seems that many jobs that failed where re-run and went fine after that.
So we can ignore these failures and mark this bug as Invalid.

Comment 10

[Phil Ringnalda (:philor)]

No, there is no threshold under which we call an intermittent failure invalid.

If you can be absolutely sure that the failure could never happen 100% of the time no matter what, then whatever script is running here could be altered to swallow the failure and set the job to RETRY, but I doubt that's the case here, so you just have to pick some other Bugzilla component and throw the bug there.

Comment 11

[Mike Hommey [:glandium]]

See comment 2. This bug is most probably classifying a bunch of stuff that all have nothing to do with each other, because the first error that shows up in the log is actually swallowed by the build system and doesn't make anything fail. But it actually happens on most likely every single build, so as soon as you get a failure, you get that error shown up.

Comment 12

[Mike Hommey [:glandium]]

I went through 15 of the 57 logs associated with bug on brasstacks. There are very few of them pointing to the same error. IOW, this bug is useless as a tracking bug for any of them, so closing as invalid. I filed bug 1408224 to just never make the error in this bug summary appear again, short of fixing the permission problem that makes it appear.

Many of the real errors, pasted below, are not pointed out by the log viewer, which is also pointing to flaws in the log viewer, if anyone wants to file them:

[taskcluster 2017-08-18T19:47:59.294Z] Error uploading artifact: (Permanent) HTTP response code 400

20:31:11     INFO -  cp: will not create hard link `../../installer-stage/core/./uninstall' to directory `../../installer-stage/core/./gmp-clearkey/0.1'

22:58:58     INFO - ____________________________ test_cli_run_with_fix ____________________________
22:58:58     INFO - run = <function inner at 0x037290F0>
22:58:58     INFO - capfd = <_pytest.capture.CaptureFixture instance at 0x03724620>
22:58:58     INFO -     def test_cli_run_with_fix(run, capfd):
22:58:58     INFO - >       ret = run(['-f', 'json', '--fix', '--linter', 'external'])
22:58:58     INFO - ..\python\mozlint\test\test_cli.py:36:
22:58:58     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
22:58:58     INFO - ..\python\mozlint\test\test_cli.py:31: in inner
22:58:58     INFO -     return cli.run(**lintargs)
22:58:58     INFO - ..\python\mozlint\mozlint\cli.py:157: in run
22:58:58     INFO -     results = lint.roll(paths, outgoing=outgoing, workdir=workdir)
22:58:58     INFO - ..\python\mozlint\mozlint\roller.py:159: in roll
22:58:58     INFO -     m.shutdown()
22:58:58     INFO - c:\mozilla-build\python\Lib\multiprocessing\util.py:207: in __call__
22:58:58     INFO -     res = self._callback(*self._args, **self._kwargs)
22:58:58     INFO - c:\mozilla-build\python\Lib\multiprocessing\managers.py:625: in _finalize_manager
22:58:58     INFO -     process.terminate()
22:58:58     INFO - c:\mozilla-build\python\Lib\multiprocessing\process.py:137: in terminate
22:58:58     INFO -     self._popen.terminate()
22:58:58     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
22:58:58     INFO - self = <multiprocessing.forking.Popen object at 0x037426B0>
22:58:58     INFO -     def terminate(self):
22:58:58     INFO -         if self.returncode is None:
22:58:58     INFO -             try:
22:58:58     INFO - >               _subprocess.TerminateProcess(int(self._handle), TERMINATE)
22:58:58     INFO - E               WindowsError: [Error 5] Access is denied
22:58:58     INFO - c:\mozilla-build\python\Lib\multiprocessing\forking.py:312: WindowsError
22:58:58     INFO - ===================== 1 failed, 1 passed in 34.86 seconds =====================

02:41:35     INFO -  cp: will not create hard link `../../installer-stage/core/./dictionaries' to directory `../../installer-stage/core/./defaults'

19:30:04     INFO -  The error occurred in code that was called by the mach command. This is either
19:30:04     INFO -  a bug in the called code itself or in the way that mach is calling it.
19:30:04     INFO -  You should consider filing a bug for this issue.
19:30:04     INFO -  If filing a bug, please include the full output of mach, including this error
19:30:04     INFO -  message.
19:30:04     INFO -  The details of the failure are as follows:
19:30:04     INFO -  KeyError: u'package-generated-sources'
19:30:04     INFO -    File "z:\build\build\src\python/mozbuild/mozbuild/mach_commands.py", line 641, in build
19:30:04     INFO -      telemetry_data = monitor.get_resource_usage()
19:30:04     INFO -    File "z:\build\build\src\python/mozbuild\mozbuild\controller\building.py", line 402, in get_resource_usage
19:30:04     INFO -      o['tiers'] = self.tiers.tiered_resource_usage()
19:30:04     INFO -    File "z:\build\build\src\python/mozbuild\mozbuild\controller\building.py", line 119, in tiered_resource_usage
19:30:04     INFO -      self.add_resources_to_dict(t_entry, phase=tier)
19:30:04     INFO -    File "z:\build\build\src\python/mozbuild\mozbuild\controller\building.py", line 128, in add_resources_to_dict
19:30:04     INFO -      end=end, phase=phase, per_cpu=False)
19:30:04     INFO -    File "z:\build\build\src\testing/mozbase/mozsystemmonitor\mozsystemmonitor\resourcemonitor.py", line 466, in aggregate_cpu_percent
19:30:04     INFO -      data = self.phase_usage(phase)
19:30:04     INFO -    File "z:\build\build\src\testing/mozbase/mozsystemmonitor\mozsystemmonitor\resourcemonitor.py", line 425, in phase_usage
19:30:04     INFO -      time_start, time_end = self.phases[phase]
19:30:04    ERROR - Return code: 1

[taskcluster 2017-08-21T20:05:34.199Z] Aborting task - max run time exceeded!
[taskcluster 2017-08-21T20:05:34.322Z]    Exit Code: 0
[taskcluster 2017-08-21T20:05:34.322Z] Success Code: 0x4
[taskcluster 2017-08-21T20:05:34.323Z]    User Time: 15.625ms
[taskcluster 2017-08-21T20:05:34.323Z]  Kernel Time: 0s
[taskcluster 2017-08-21T20:05:34.323Z]    Wall Time: 46m26.9710002s
[taskcluster 2017-08-21T20:05:34.323Z]  Peak Memory: 1699840
[taskcluster 2017-08-21T20:05:34.323Z]       Result: IDLENESS_LIMIT_EXCEEDED

19:08:41     INFO - Traceback (most recent call last):
19:08:41     INFO -   File "c:\mozilla-build\python\Lib\multiprocessing\util.py", line 274, in _run_finalizers
19:08:41     INFO -     finalizer()
19:08:41     INFO -   File "c:\mozilla-build\python\Lib\multiprocessing\util.py", line 207, in __call__
19:08:41     INFO -     res = self._callback(*self._args, **self._kwargs)
19:08:41     INFO -   File "c:\mozilla-build\python\Lib\multiprocessing\pool.py", line 513, in _terminate_pool
19:08:41     INFO -     p.terminate()
19:08:41     INFO -   File "c:\mozilla-build\python\Lib\multiprocessing\process.py", line 137, in terminate
19:08:41     INFO -     self._popen.terminate()
19:08:41     INFO -   File "c:\mozilla-build\python\Lib\multiprocessing\forking.py", line 312, in terminate
19:08:41     INFO -     _subprocess.TerminateProcess(int(self._handle), TERMINATE)
19:08:41     INFO - WindowsError: [Error 5] Access is denied

[taskcluster 2017-08-21T19:36:39.502Z] Task not successful due to following exception(s):
[taskcluster 2017-08-21T19:36:39.502Z] Exception 1)
[taskcluster 2017-08-21T19:36:39.502Z] (Permanent) HTTP response code 400

22:02:48  WARNING - TEST-UNEXPECTED-FAIL | z:\build\build\src\testing\xpcshell\selftest.py | XPCShellTestsTests.testChildPass, line 609: Tests should have passed, log:

23:53:40     INFO -  mozmake.EXE[9]: Leaving directory 'z:/build/build/src/obj-firefox/intl/locales'
[taskcluster 2017-08-21T23:53:40.752Z] Uploading file public/logs/live.log as artifact public/logs/live.log
[taskcluster 2017-08-21T23:53:41.262Z] Task not successful due to following exception(s):
[taskcluster 2017-08-21T23:53:41.262Z] Exception 1)
[taskcluster 2017-08-21T23:53:41.262Z] []
[taskcluster 2017-08-21T23:53:41.262Z] 
[taskcluster 2017-08-21T23:53:41.262Z] Exit code: 0

01:25:21     INFO - ================================== FAILURES ===================================
01:25:21     INFO - _______________________ test_linter_types[external.yml] _______________________
01:25:21     INFO - lint = <mozlint.roller.LintRoller object at 0x03584150>
01:25:21     INFO - linter = 'z:\\task_1503362816\\build\\src\\python\\mozlint\\test\\linters\\external.yml'
01:25:21     INFO - files = ['z:\\task_1503362816\\build\\src\\python\\mozlint\\test\\files\\foobar.js', 'z:\\task_1503362816\\build\\src\\python\\mozlint\\test\\files\\foobar.py', 'z:\\task_1503362816\\build\\src\\python\\mozlint\\test\\files\\no_foobar.js']
01:25:21     INFO - path = <function _path at 0x034AA9B0>
01:25:21     INFO -     def test_linter_types(lint, linter, files, path):
01:25:21     INFO -         lint.read(linter)
01:25:21     INFO - >       result = lint.roll(files)
01:25:21     INFO - ..\python\mozlint\test\test_types.py:31:
01:25:21     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
01:25:21     INFO - ..\python\mozlint\mozlint\roller.py:159: in roll
01:25:21     INFO -     m.shutdown()
01:25:21     INFO - c:\mozilla-build\python\Lib\multiprocessing\util.py:207: in __call__
01:25:21     INFO -     res = self._callback(*self._args, **self._kwargs)
01:25:21     INFO - c:\mozilla-build\python\Lib\multiprocessing\managers.py:625: in _finalize_manager
01:25:21     INFO -     process.terminate()
01:25:21     INFO - c:\mozilla-build\python\Lib\multiprocessing\process.py:137: in terminate
01:25:21     INFO -     self._popen.terminate()
01:25:21     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
01:25:21     INFO - self = <multiprocessing.forking.Popen object at 0x034DE7D0>
01:25:21     INFO -     def terminate(self):
01:25:21     INFO -         if self.returncode is None:
01:25:21     INFO -             try:
01:25:21     INFO - >               _subprocess.TerminateProcess(int(self._handle), TERMINATE)
01:25:21     INFO - E               WindowsError: [Error 5] Access is denied
01:25:21     INFO - c:\mozilla-build\python\Lib\multiprocessing\forking.py:312: WindowsError
01:25:21     INFO - ===================== 1 failed, 4 passed in 7.84 seconds ======================

15:53:41     INFO -  The error occurred in code that was called by the mach command. This is either
15:53:41     INFO -  a bug in the called code itself or in the way that mach is calling it.
15:53:41     INFO -  You should consider filing a bug for this issue.
15:53:41     INFO -  If filing a bug, please include the full output of mach, including this error
15:53:41     INFO -  message.
15:53:41     INFO -  The details of the failure are as follows:
15:53:41     INFO -  KeyError: u'package-generated-sources'
15:53:41     INFO -    File "z:\build\build\src\python/mozbuild/mozbuild/mach_commands.py", line 641, in build
15:53:41     INFO -      telemetry_data = monitor.get_resource_usage()
15:53:41     INFO -    File "z:\build\build\src\python/mozbuild\mozbuild\controller\building.py", line 402, in get_resource_usage
15:53:41     INFO -      o['tiers'] = self.tiers.tiered_resource_usage()
15:53:41     INFO -    File "z:\build\build\src\python/mozbuild\mozbuild\controller\building.py", line 119, in tiered_resource_usage
15:53:41     INFO -      self.add_resources_to_dict(t_entry, phase=tier)
15:53:41     INFO -    File "z:\build\build\src\python/mozbuild\mozbuild\controller\building.py", line 128, in add_resources_to_dict
15:53:41     INFO -      end=end, phase=phase, per_cpu=False)
15:53:41     INFO -    File "z:\build\build\src\testing/mozbase/mozsystemmonitor\mozsystemmonitor\resourcemonitor.py", line 466, in aggregate_cpu_percent
15:53:41     INFO -      data = self.phase_usage(phase)
15:53:41     INFO -    File "z:\build\build\src\testing/mozbase/mozsystemmonitor\mozsystemmonitor\resourcemonitor.py", line 425, in phase_usage
15:53:41     INFO -      time_start, time_end = self.phases[phase]
15:53:41    ERROR - Return code: 1

16:30:07     INFO - /bin/sh: C:/Users/task_1503413748/AppData/Local/Temp/make2168-2.sh: No such file or directory
16:30:07     INFO - /bin/sh: C:/Users/task_1503413748/AppData/Local/Temp/make2168-3.sh: No such file or directory
16:30:07     INFO - Makefile:64: recipe for target 'check-masm' failed
16:30:07     INFO - mozmake.EXE[2]: *** [check-masm] Error 127
16:30:07     INFO - Makefile:67: recipe for target 'check-js-msg' failed
16:30:07     INFO - mozmake.EXE[2]: *** [check-js-msg] Error 127

16:13:22     INFO - _______________________ test_linter_types[external.yml] _______________________
16:13:22     INFO - lint = <mozlint.roller.LintRoller object at 0x030651B0>
16:13:22     INFO - linter = 'z:\\build\\build\\src\\python\\mozlint\\test\\linters\\external.yml'
16:13:22     INFO - files = ['z:\\build\\build\\src\\python\\mozlint\\test\\files\\foobar.js', 'z:\\build\\build\\src\\python\\mozlint\\test\\files\\foobar.py', 'z:\\build\\build\\src\\python\\mozlint\\test\\files\\no_foobar.js']
16:13:22     INFO - path = <function _path at 0x02DE88B0>
16:13:22     INFO -     def test_linter_types(lint, linter, files, path):
16:13:22     INFO -         lint.read(linter)
16:13:22     INFO - >       result = lint.roll(files)
16:13:22     INFO - ..\python\mozlint\test\test_types.py:31:
16:13:22     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
16:13:22     INFO - ..\python\mozlint\mozlint\roller.py:159: in roll
16:13:22     INFO -     m.shutdown()
16:13:22     INFO - c:\mozilla-build\python\Lib\multiprocessing\util.py:207: in __call__
16:13:22     INFO -     res = self._callback(*self._args, **self._kwargs)
16:13:22     INFO - c:\mozilla-build\python\Lib\multiprocessing\managers.py:625: in _finalize_manager
16:13:22     INFO -     process.terminate()
16:13:22     INFO - c:\mozilla-build\python\Lib\multiprocessing\process.py:137: in terminate
16:13:22     INFO -     self._popen.terminate()
16:13:22     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
16:13:22     INFO - self = <multiprocessing.forking.Popen object at 0x02EE9310>
16:13:22     INFO -     def terminate(self):
16:13:22     INFO -         if self.returncode is None:
16:13:22     INFO -             try:
16:13:22     INFO - >               _subprocess.TerminateProcess(int(self._handle), TERMINATE)
16:13:22     INFO - E               WindowsError: [Error 5] Access is denied
16:13:22     INFO - c:\mozilla-build\python\Lib\multiprocessing\forking.py:312: WindowsError
16:13:22     INFO - ===================== 1 failed, 4 passed in 38.83 seconds =====================

[taskcluster 2017-08-23T15:30:22.547Z] Task not successful due to following exception(s):
[taskcluster 2017-08-23T15:30:22.547Z] Exception 1)
[taskcluster 2017-08-23T15:30:22.547Z] (Permanent) HTTP response code 400

Comment 13

[Intermittent Failures Robot]

2 failures in 947 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 2

Platform breakdown:
* windows7-32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1391811&startday=2017-10-09&endday=2017-10-15&tree=all