Closed Bug 1534689 Opened 6 years ago Closed 6 years ago

Intermittent [taskcluster:error] Uploading error artifact public/test_info from file build/blobber_upload_dir with message "Could not read directory 'C:\\Users\\task_1552402371\\build\\blobber_upload_dir'", reason "file-missing-on-worker"

Categories

(Taskcluster :: Workers, defect, P5)

Product:
Taskcluster
Component:
Workers
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1558718

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

#[markdown(off)]
Filed by: aciure [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=233386676&repo=autoland

https://queue.taskcluster.net/v1/task/JvQMZZ-qTR-LR_GMPg323w/runs/0/artifacts/public/logs/live_backing.log

15:01:31 INFO - Running pre-action listener: _resource_record_pre_action
15:01:31 INFO - Running main action method: clobber
15:01:31 INFO - rmtree: C:\Users\task_1552402371\build
15:01:31 INFO - Using _rmtree_windows ...
15:01:31 INFO - retry: Calling _rmtree_windows with args: ('C:\\Users\\task_1552402371\\build',), kwargs: {}, attempt #1
15:01:31 INFO - Running post-action listener: _resource_record_post_action
15:01:31 INFO - [mozharness: 2019-03-12 15:01:31.409000Z] Finished clobber step (success)
15:01:31 INFO - [mozharness: 2019-03-12 15:01:31.409000Z] Running download-and-extract step.
15:01:31 INFO - Running pre-action listener: _resource_record_pre_action
15:01:31 INFO - Running main action method: download_and_extract
15:01:31 INFO - mkdir: C:\Users\task_1552402371\build\tests
15:01:31 INFO - Downloading https://queue.taskcluster.net/v1/task/NJFNgyyhQK28fCD-yE_rEA/artifacts/public/build/target.test_packages.json to C:\Users\task_1552402371\build\target.test_packages.json
15:01:31 INFO - retry: Calling _download_file with args: (), kwargs: {'url': 'https://queue.taskcluster.net/v1/task/NJFNgyyhQK28fCD-yE_rEA/artifacts/public/build/target.test_packages.json', 'file_name': 'C:\\Users\\task_1552402371\\build\\target.test_packages.json'}, attempt #1
15:01:32 INFO - Downloaded 1265 bytes.
15:01:32 INFO - Reading from file C:\Users\task_1552402371\build\target.test_packages.json
15:01:32 INFO - Downloading packages: [u'target.common.tests.tar.gz', u'target.talos.tests.tar.gz'] for test suite categories: ['common', 'talos']
15:01:32 INFO - Downloading and extracting to C:\Users\task_1552402371\build\tests these dirs * from https://queue.taskcluster.net/v1/task/NJFNgyyhQK28fCD-yE_rEA/artifacts/public/build/target.common.tests.tar.gz
15:01:32 INFO - retry: Calling fetch_url_into_memory with args: (), kwargs: {'url': u'https://queue.taskcluster.net/v1/task/NJFNgyyhQK28fCD-yE_rEA/artifacts/public/build/target.common.tests.tar.gz'}, attempt #1
15:01:32 INFO - Fetch https://queue.taskcluster.net/v1/task/NJFNgyyhQK28fCD-yE_rEA/artifacts/public/build/target.common.tests.tar.gz into memory
15:01:34 INFO - Content-Length response header: 22488002
15:01:34 INFO - Bytes received: 22488002
[taskcluster 2019-03-12T15:01:36.341Z] Exit Code: 1073807364
[taskcluster 2019-03-12T15:01:36.341Z] User Time: 0s
[taskcluster 2019-03-12T15:01:36.341Z] Kernel Time: 15.625ms
[taskcluster 2019-03-12T15:01:36.341Z] Wall Time: 5.2104905s
[taskcluster 2019-03-12T15:01:36.341Z] Result: FAILED
[taskcluster 2019-03-12T15:01:36.341Z] === Task Finished ===
[taskcluster 2019-03-12T15:01:36.341Z] Task Duration: 5.2104905s
[taskcluster 2019-03-12T15:01:37.500Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-03-11T13:25:09.858Z
[taskcluster:error] Uploading error artifact public/test_info from file build/blobber_upload_dir with message "Could not read directory 'C:\\Users\\task_1552402371\\build\\blobber_upload_dir'", reason "file-missing-on-worker" and expiry 2020-03-11T13:25:09.858Z
[taskcluster:error] TASK FAILURE during artifact upload: file-missing-on-worker: Could not read directory 'C:\Users\task_1552402371\build\blobber_upload_dir'
[taskcluster 2019-03-12T15:01:38.578Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/JvQMZZ-qTR-LR_GMPg323w/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2020-03-11T13:25:09.858Z
[taskcluster:error] exit status 1073807364
[taskcluster:error] file-missing-on-worker: Could not read directory 'C:\Users\task_1552402371\build\blobber_upload_dir'

Component: Talos → Operations and Service Requests
Product: Testing → Taskcluster
Version: Version 3 → unspecified

:pmoore, we ran across this in triage, is this known?

Flags: needinfo?(pmoore)

This looks like it could be a case of bug 1444168 comment 36.

The OCC logs will probably say what terminated the process (possibly HaltOnIdle thinks no task is running).

Flags: needinfo?(pmoore)

Note, the message here is not the root cause of the problem:

[taskcluster:error] Uploading error artifact public/test_info from file build/blobber_upload_dir with message "Could not read directory 'C:\\Users\\task_1552402371\\build\\blobber_upload_dir'", reason "file-missing-on-worker"

Admittedly this is rather misleading.

When a task fails, an attempt is still made to upload all declared artifacts in order to assist any troubleshooting that may be required. If a task declares artifacts that are generated during the task execution, but fails before those artifacts are created, for any reason, we will still see the message in the logs that the worker was not able to upload the artifact(s) due to their non-existence. It is often useful to be explicit that the worker attempted to upload an artifact but was not able to, but for the unaccustomed user this may be confusing.

Looking at the original failure, the root cause was:

[taskcluster:error] exit status 1073807364

This is due to something triggering a shutdown or killing processes on the machine, as per comment 10.

However, I did notice other failures that were associated to this bug which had different root causes, which should be separately addressed.

Regarding the cause of the process termination for that particular task, it is difficult to say, since the papertrail logs have since been purged.

Note, I've created a command line tool that you pass a taskId (and optionally a runId) to, and it returns the server logs for that task. This is very useful in the case of an unexpected process termination (e.g. with exit code 1073807364) since the server logs will often report what triggered the machine to shutdown.

The tool can be found here in case it is useful to others that wish to troubleshoot future occurrences of this issue. Note, it requires that you have access to the Mozilla Corporation account on papertrail, that you have go (golang) installed, and have installed and configured the papertrail-cli tool.

There are 23 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-05-02&endday=2019-05-09&tree=trunk&bug=1534689

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=245278528&repo=autoland&lineNumber=233

05:59:58 INFO - Running command: ['Z:\task_1557291686\build\venv\Scripts\pip', 'install', '--timeout', '120', '--no-index', '--find-links', 'https://pypi.pub.build.mozilla.org/pub', 'psutil>=3.1.1'] in Z:\task_1557291686\build
05:59:58 INFO - Copy/paste: Z:\task_1557291686\build\venv\Scripts\pip install --timeout 120 --no-index --find-links https://pypi.pub.build.mozilla.org/pub psutil>=3.1.1
05:59:58 INFO - Using env: {'ALLUSERSPROFILE': 'C:\ProgramData',
05:59:58 INFO - 'APPDATA': 'Z:\task_1557291686\AppData\Roaming',
05:59:58 INFO - 'COMMONPROGRAMFILES': 'C:\Program Files\Common Files',
05:59:58 INFO - 'COMMONPROGRAMFILES(X86)': 'C:\Program Files (x86)\Common Files',
05:59:58 INFO - 'COMMONPROGRAMW6432': 'C:\Program Files\Common Files',
05:59:58 INFO - 'COMPUTERNAME': 'I-021D96647982C',
05:59:58 INFO - 'COMSPEC': 'C:\Windows\system32\cmd.exe',
05:59:58 INFO - 'DRIVERDATA': 'C:\Windows\System32\Drivers\DriverData',
05:59:58 INFO - 'EXTRA_MOZHARNESS_CONFIG': '{"test_packages_url": "https://queue.taskcluster.net/v1/task/ORHUv5nOTcG8yfLZd9xngw/artifacts/public/build/target.test_packages.json", "installer_url": "https://queue.taskcluster.net/v1/task/ORHUv5nOTcG8yfLZd9xngw/artifacts/public/build/target.zip"}',
05:59:58 INFO - 'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/integration/autoland',
05:59:58 INFO - 'GECKO_HEAD_REV': 'c464e9d2f4b810cb4da5651c5c5e14c5c9ab1080',
05:59:58 INFO - 'HOMEDRIVE': 'C:',
05:59:58 INFO - 'HOMEPATH': '\Users\task_1557291686',
05:59:58 INFO - 'LOCALAPPDATA': 'C:\Users\task_1557291686\AppData\Local',
05:59:58 INFO - 'LOGONSERVER': '\\I-021D96647982C',
05:59:58 INFO - 'MOZILLABUILD': 'C:\mozilla-build',
05:59:58 INFO - 'MOZ_AUTOMATION': '1',
05:59:58 INFO - 'NUMBER_OF_PROCESSORS': '8',
05:59:58 INFO - 'ONEDRIVE': 'C:\Users\task_1557291686\OneDrive',
05:59:58 INFO - 'OS': 'Windows_NT',
05:59:58 INFO - 'PATH': 'C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Windows\System32\OpenSSH\;C:\Windows\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\;;C:\Program Files\Mercurial;C:\mozilla-build\bin;C:\mozilla-build\kdiff3;C:\mozilla-build\moztools-x64\bin;C:\mozilla-build\mozmake;C:\mozilla-build\msys\bin;C:\mozilla-build\msys\local\bin;C:\mozilla-build\nsis-3.01;C:\mozilla-build\python;C:\mozilla-build\python\Scripts;C:\mozilla-build\python3;C:\Users\task_1557291686\AppData\Local\Microsoft\WindowsApps',
05:59:58 INFO - 'PATHEXT': '.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC',
05:59:58 INFO - 'PIP_DOWNLOAD_CACHE': 'y:\pip-cache',
05:59:58 INFO - 'PROCESSOR_ARCHITECTURE': 'AMD64',
05:59:58 INFO - 'PROCESSOR_IDENTIFIER': 'Intel64 Family 6 Model 85 Stepping 4, GenuineIntel',
05:59:58 INFO - 'PROCESSOR_LEVEL': '6',
05:59:58 INFO - 'PROCESSOR_REVISION': '5504',
05:59:58 INFO - 'PROGRAMDATA': 'C:\ProgramData',
05:59:58 INFO - 'PROGRAMFILES': 'C:\Program Files',
05:59:58 INFO - 'PROGRAMFILES(X86)': 'C:\Program Files (x86)',
05:59:58 INFO - 'PROGRAMW6432': 'C:\Program Files',
05:59:58 INFO - 'PROMPT': '$P$G',
05:59:58 INFO - 'PSMODULEPATH': '%ProgramFiles%\WindowsPowerShell\Modules;C:\Windows\system32\WindowsPowerShell\v1.0\Modules',
05:59:58 INFO - 'PUBLIC': 'C:\Users\Public',
05:59:58 INFO - 'SCCACHE_DISABLE': '1',
05:59:58 INFO - 'SYSTEMDRIVE': 'C:',
05:59:58 INFO - 'SYSTEMROOT': 'C:\Windows',
05:59:58 INFO - 'TASKCLUSTER_INSTANCE_TYPE': 'c5.2xlarge',
05:59:58 INFO - 'TASKCLUSTER_ROOT_URL': 'https://taskcluster.net',
05:59:58 INFO - 'TASK_ID': 'bk5TTs5rTY2FBFshsA4jig',
05:59:58 INFO - 'TEMP': 'C:\Users\task_1557291686\AppData\Local\Temp',
05:59:58 INFO - 'TMP': 'C:\Users\task_1557291686\AppData\Local\Temp',
05:59:58 INFO - 'TOOLTOOL_CACHE': 'y:\tooltool-cache',
05:59:58 INFO - 'USERDOMAIN': 'I-021D96647982C',
05:59:58 INFO - 'USERDOMAIN_ROAMINGPROFILE': 'I-021D96647982C',
05:59:58 INFO - 'USERNAME': 'task_1557291686',
05:59:58 INFO - 'USERPROFILE': 'C:\Users\task_1557291686',
05:59:58 INFO - 'WINDIR': 'C:\Windows'}
05:59:58 INFO - Ignoring indexes: https://pypi.python.org/simple
05:59:58 INFO - Collecting psutil>=3.1.1
05:59:58 INFO - Downloading https://pypi.pub.build.mozilla.org/pub/psutil-5.4.3-cp27-none-win_amd64.whl (223kB)
05:59:58 INFO - Installing collected packages: psutil
05:59:59 INFO - Successfully installed psutil-5.4.3
05:59:59 INFO - Return code: 0
05:59:59 INFO - Installing mozsystemmonitor==0.4 into virtualenv Z:\task_1557291686\build\venv
05:59:59 INFO - retry: Calling run_command with args: [['Z:\task_1557291686\build\venv\Scripts\pip', 'install', '--timeout', '120', '--no-index', '--find-links', 'https://pypi.pub.build.mozilla.org/pub', 'mozsystemmonitor==0.4']], kwargs: {'error_level': 'warning', 'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x0000000003099730>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x00000000031E2990>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x00000000034F5F50>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x0000000003206928>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x0000000003019590>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x00000000030A9780>, 'level': 'critical'}], 'cwd': 'Z:\task_1557291686\build', 'env': {'TMP': 'C:\Users\task_1557291686\AppData\Local\Temp', 'USERNAME': 'task_1557291686', 'COMPUTERNAME': 'I-021D96647982C', 'TASKCLUSTER_INSTANCE_TYPE': 'c5.2xlarge', 'MOZ_AUTOMATION': '1', 'PSMODULEPATH': '%ProgramFiles%\WindowsPowerShell\Modules;C:\Windows\system32\WindowsPowerShell\v1.0\Modules', 'COMMONPROGRAMFILES': 'C:\Program Files\Common Files', 'TASKCLUSTER_ROOT_URL': 'https://taskcluster.net', 'PROCESSOR_IDENTIFIER': 'Intel64 Family 6 Model 85 Stepping 4, GenuineIntel', 'TOOLTOOL_CACHE': 'y:\tooltool-cache', 'PROCESSOR_REVISION': '5504', 'PATH': 'C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Windows\System32\OpenSSH\;C:\Windows\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\;;C:\Program Files\Mercurial;C:\mozilla-build\bin;C:\mozilla-build\kdiff3;C:\mozilla-build\moztools-x64\bin;C:\mozilla-build\mozmake;C:\mozilla-build\msys\bin;C:\mozilla-build\msys\local\bin;C:\mozilla-build\nsis-3.01;C:\mozilla-build\python;C:\mozilla-build\python\Scripts;C:\mozilla-build\python3;C:\Users\task_1557291686\AppData\Local\Microsoft\WindowsApps', 'SYSTEMROOT': 'C:\Windows', 'PROGRAMFILES(X86)': 'C:\Program Files (x86)', 'DRIVERDATA': 'C:\Windows\System32\Drivers\DriverData', 'TEMP': 'C:\Users\task_1557291686\AppData\Local\Temp', 'COMMONPROGRAMFILES(X86)': 'C:\Program Files (x86)\Common Files', 'USERDOMAIN': 'I-021D96647982C', 'PROCESSOR_ARCHITECTURE': 'AMD64', 'ALLUSERSPROFILE': 'C:\ProgramData', 'EXTRA_MOZHARNESS_CONFIG': '{"test_packages_url": "https://queue.taskcluster.net/v1/task/ORHUv5nOTcG8yfLZd9xngw/artifacts/public/build/target.test_packages.json", "installer_url": "https://queue.taskcluster.net/v1/task/ORHUv5nOTcG8yfLZd9xngw/artifacts/public/build/target.zip"}', 'LOCALAPPDATA': 'C:\Users\task_1557291686\AppData\Local', 'HOMEPATH': '\Users\task_1557291686', 'USERDOMAIN_ROAMINGPROFILE': 'I-021D96647982C', 'PROGRAMW6432': 'C:\Program Files', 'MOZILLABUILD': 'C:\mozilla-build', 'SCCACHE_DISABLE': '1', 'LOGONSERVER': '\\I-021D96647982C', 'PROMPT': '$P$G', 'COMSPEC': 'C:\Windows\system32\cmd.exe', 'PROGRAMDATA': 'C:\ProgramData', 'GECKO_HEAD_REV': 'c464e9d2f4b810cb4da5651c5c5e14c5c9ab1080', 'ONEDRIVE': 'C:\Users\task_1557291686\OneDrive', 'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/integration/autoland', 'PATHEXT': '.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC', 'WINDIR': 'C:\Windows', 'TASK_ID': 'bk5TTs5rTY2FBFshsA4jig', 'HOMEDRIVE': 'C:', 'PROGRAMFILES': 'C:\Program Files', 'SYSTEMDRIVE': 'C:', 'NUMBER_OF_PROCESSORS': '8', 'APPDATA': 'Z:\task_1557291686\AppData\Roaming', 'PIP_DOWNLOAD_CACHE': 'y:\pip-cache', 'PROCESSOR_LEVEL': '6', 'COMMONPROGRAMW6432': 'C:\Program Files\Common Files', 'OS': 'Windows_NT', 'PUBLIC': 'C:\Users\Public', 'USERPROFILE': 'C:\Users\task_1557291686'}}, attempt #1
05:59:59 INFO - Running command: ['Z:\task_1557291686\build\venv\Scripts\pip', 'install', '--timeout', '120', '--no-index', '--find-links', 'https://pypi.pub.build.mozilla.org/pub', 'mozsystemmonitor==0.4'] in Z:\task_1557291686\build
05:59:59 INFO - Copy/paste: Z:\task_1557291686\build\venv\Scripts\pip install --timeout 120 --no-index --find-links https://pypi.pub.build.mozilla.org/pub mozsystemmonitor==0.4
05:59:59 INFO - Using env: (same as previous command)
05:59:59 INFO - Ignoring indexes: https://pypi.python.org/simple
05:59:59 INFO - Collecting mozsystemmonitor==0.4
06:00:00 INFO - Downloading https://pypi.pub.build.mozilla.org/pub/mozsystemmonitor-0.4.tar.gz
06:00:00 INFO - Requirement already satisfied (use --upgrade to upgrade): psutil>=3.1.1 in z:\task_1557291686\build\venv\lib\site-packages (from mozsystemmonitor==0.4)
06:00:00 INFO - Building wheels for collected packages: mozsystemmonitor
06:00:00 INFO - Running setup.py bdist_wheel for mozsystemmonitor: started
[taskcluster 2019-05-08T06:00:00.976Z] Exit Code: 1073807364
[taskcluster 2019-05-08T06:00:00.976Z] User Time: 0s
[taskcluster 2019-05-08T06:00:00.976Z] Kernel Time: 0s
[taskcluster 2019-05-08T06:00:00.976Z] Wall Time: 2m47.885316s
[taskcluster 2019-05-08T06:00:00.976Z] Result: FAILED
[taskcluster 2019-05-08T06:00:00.976Z] === Task Finished ===
[taskcluster 2019-05-08T06:00:00.976Z] Task Duration: 2m47.885316s
[taskcluster 2019-05-08T06:00:01.663Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-05-07T03:44:19.302Z
[taskcluster:error] Uploading error artifact public/test_info from file build/blobber_upload_dir with message "Could not read directory 'Z:\task_1557291686\build\blobber_upload_dir'", reason "file-missing-on-worker" and expiry 2020-05-07T03:44:19.302Z
[taskcluster:error] TASK FAILURE during artifact upload: file-missing-on-worker: Could not read directory 'Z:\task_1557291686\build\blobber_upload_dir'
[taskcluster 2019-05-08T06:00:02.661Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/bk5TTs5rTY2FBFshsA4jig/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2020-05-07T03:44:19.302Z
[taskcluster:error] exit status 1073807364
[taskcluster:error] file-missing-on-worker: Could not read directory 'Z:\task_1557291686\build\blobber_upload_dir'

Whiteboard: [stockwell needswork:owner]
Component: Operations and Service Requests → Workers

There are 31 failures associated to this bug in the last 7 days. These are occurring on windows10-64-ref-hw-2017 opt builds.

:dustin any updates with this?

Flags: needinfo?(dustin)
Whiteboard: [stockwell unknown] → [stockwell needswork]

See the dependent bug. This is a false star..

Flags: needinfo?(dustin)
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.