1779265 - Perma mochitests/xpcshell condprof.client.ProfileNotFoundError: https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-win64-full/artifacts/public/condprof/profile-win64-full-default.tgz

Status: RESOLVED FIXED

(Testing :: Condprofile, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=384117469&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/U-7o1ZbzRNSSb_3NtSdM0g/runs/0/artifacts/public/logs/live_backing.log

---

[task 2022-07-12T16:12:57.329Z] 16:12:57     INFO -  condprof Failed to extract the tarball
[task 2022-07-12T16:12:57.332Z] 16:12:57     INFO -  condprof Removing cached file to attempt a new download
[task 2022-07-12T16:12:57.332Z] 16:12:57     INFO -  condprof Failed to get the profile.
[task 2022-07-12T16:12:57.332Z] 16:12:57     INFO -  condprof Failed, retrying
[task 2022-07-12T16:13:42.323Z] 16:13:42     INFO -  condprof Getting https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-win64-full/artifacts/public/condprof/profile-win64-full-default.tgz
[task 2022-07-12T16:13:42.325Z] 16:13:42     INFO -  condprof Getting headers at https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-win64-full/artifacts/public/condprof/profile-win64-full-default.tgz
[task 2022-07-12T16:13:42.431Z] 16:13:42     INFO -  condprof Redirected
[task 2022-07-12T16:13:42.444Z] 16:13:42     INFO -  condprof Getting headers at https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/JMrK1_6dTfquzTTtdzWCvg/artifacts/public%2Fcondprof%2Fprofile-win64-full-default.tgz?bewit=c3RhdGljL3Rhc2tjbHVzdGVyL2luZGV4XDE2NTc2NDMzMjFcNGdIRXM5WFJtZzc1RkdmT3B4dmVXeVJkS05pdjM1eTNuemt4Mi91ZU9TWT1c
[task 2022-07-12T16:13:42.534Z] 16:13:42     INFO -  condprof Response code is 404
[task 2022-07-12T16:13:42.541Z] 16:13:42     INFO -  condprof Checking for existence of: C:\Users\task_165764139118664/.condprof-cache\profile-win64-full-default.tgz
[task 2022-07-12T16:13:42.541Z] 16:13:42     INFO -  condprof Could not find an existing archive.
[task 2022-07-12T16:13:42.541Z] 16:13:42     INFO -  condprof Content in cache directory C:\Users\task_165764139118664/.condprof-cache: ['profile-win64-full-default.tgz.etag']
[task 2022-07-12T16:13:42.542Z] 16:13:42     INFO -  condprof Downloading https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-win64-full/artifacts/public/condprof/profile-win64-full-default.tgz
[task 2022-07-12T16:13:42.773Z] 16:13:42     INFO -  condprof Failed to extract the tarball
[task 2022-07-12T16:13:42.775Z] 16:13:42     INFO -  condprof Removing cached file to attempt a new download
[task 2022-07-12T16:13:42.775Z] 16:13:42     INFO -  condprof Failed to get the profile.
[task 2022-07-12T16:13:42.775Z] 16:13:42     INFO -  condprof Failed, retrying
[task 2022-07-12T16:14:50.259Z] 16:14:50     INFO -  condprof Retried 2 attempts and failed
[task 2022-07-12T16:14:50.260Z] 16:14:50     INFO -  Could not get the conditioned profile
[task 2022-07-12T16:14:50.261Z] 16:14:50     INFO -  Traceback (most recent call last):
[task 2022-07-12T16:14:50.261Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\venv\lib\site-packages\condprof\client.py", line 222, in get_profile
[task 2022-07-12T16:14:50.261Z] 16:14:50     INFO -      return _retries(_get_profile, onerror, retries)
[task 2022-07-12T16:14:50.262Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\venv\lib\site-packages\condprof\client.py", line 123, in _retries
[task 2022-07-12T16:14:50.262Z] 16:14:50     INFO -      raise RetriesError()
[task 2022-07-12T16:14:50.262Z] 16:14:50     INFO -  condprof.client.RetriesError
[task 2022-07-12T16:14:50.263Z] 16:14:50     INFO -  During handling of the above exception, another exception occurred:
[task 2022-07-12T16:14:50.263Z] 16:14:50     INFO -  Traceback (most recent call last):
[task 2022-07-12T16:14:50.263Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\tests\xpcshell\runxpcshelltests.py", line 1586, in downloadConditionedProfile
[task 2022-07-12T16:14:50.264Z] 16:14:50     INFO -      cond_prof_target_dir = get_profile(
[task 2022-07-12T16:14:50.264Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\venv\lib\site-packages\condprof\client.py", line 224, in get_profile
[task 2022-07-12T16:14:50.264Z] 16:14:50     INFO -      raise ProfileNotFoundError(url)
[task 2022-07-12T16:14:50.265Z] 16:14:50     INFO -  condprof.client.ProfileNotFoundError: https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-win64-full/artifacts/public/condprof/profile-win64-full-default.tgz
[task 2022-07-12T16:14:50.265Z] 16:14:50     INFO -  Traceback (most recent call last):
[task 2022-07-12T16:14:50.265Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\venv\lib\site-packages\condprof\client.py", line 222, in get_profile
[task 2022-07-12T16:14:50.265Z] 16:14:50     INFO -      return _retries(_get_profile, onerror, retries)
[task 2022-07-12T16:14:50.266Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\venv\lib\site-packages\condprof\client.py", line 123, in _retries
[task 2022-07-12T16:14:50.266Z] 16:14:50     INFO -      raise RetriesError()
[task 2022-07-12T16:14:50.266Z] 16:14:50     INFO -  condprof.client.RetriesError
[task 2022-07-12T16:14:50.266Z] 16:14:50     INFO -  During handling of the above exception, another exception occurred:
[task 2022-07-12T16:14:50.267Z] 16:14:50     INFO -  Traceback (most recent call last):
[task 2022-07-12T16:14:50.267Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\tests\xpcshell\runxpcshelltests.py", line 2223, in <module>
[task 2022-07-12T16:14:50.267Z] 16:14:50     INFO -      main()
[task 2022-07-12T16:14:50.267Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\tests\xpcshell\runxpcshelltests.py", line 2218, in main
[task 2022-07-12T16:14:50.268Z] 16:14:50     INFO -      if not xpcsh.runTests(options):
[task 2022-07-12T16:14:50.268Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\tests\xpcshell\runxpcshelltests.py", line 1755, in runTests
[task 2022-07-12T16:14:50.268Z] 16:14:50     INFO -      self.conditioned_profile_dir = self.downloadConditionedProfile(
[task 2022-07-12T16:14:50.268Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\tests\xpcshell\runxpcshelltests.py", line 1586, in downloadConditionedProfile
[task 2022-07-12T16:14:50.268Z] 16:14:50     INFO -      cond_prof_target_dir = get_profile(
[task 2022-07-12T16:14:50.269Z] 16:14:50     INFO -    File "Z:\task_165764139118664\build\venv\lib\site-packages\condprof\client.py", line 224, in get_profile
[task 2022-07-12T16:14:50.269Z] 16:14:50     INFO -      raise ProfileNotFoundError(url)
[task 2022-07-12T16:14:50.269Z] 16:14:50     INFO -  condprof.client.ProfileNotFoundError: https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-win64-full/artifacts/public/condprof/profile-win64-full-default.tgz
[task 2022-07-12T16:14:50.343Z] 16:14:50    ERROR - Return code: 1
[task 2022-07-12T16:14:50.343Z] 16:14:50    ERROR - No tests run or test summary not found
[task 2022-07-12T16:14:50.344Z] 16:14:50     INFO - TinderboxPrint: xpcshell-xpcshell<br/><em class="testfail">T-FAIL</em>
[task 2022-07-12T16:14:50.344Z] 16:14:50  WARNING - # TBPL FAILURE #
[task 2022-07-12T16:14:50.344Z] 16:14:50  WARNING - setting return code to 2
[task 2022-07-12T16:14:50.344Z] 16:14:50  WARNING - The xpcshell suite: xpcshell ran with return status: FAILURE
[task 2022-07-12T16:14:50.344Z] 16:14:50     INFO - Running post-action listener: _package_coverage_data
[task 2022-07-12T16:14:50.344Z] 16:14:50     INFO - Running post-action listener: _resource_record_post_action
[task 2022-07-12T16:14:50.344Z] 16:14:50     INFO - Running post-action listener: process_java_coverage_data
[task 2022-07-12T16:14:50.344Z] 16:14:50     INFO - [mozharness: 2022-07-12 16:14:50.344749Z] Finished run-tests step (success)
[task 2022-07-12T16:14:50.344Z] 16:14:50     INFO - Running post-run listener: _resource_record_post_run
[task 2022-07-12T16:14:50.437Z] 16:14:50     INFO - instance_metadata.json not found; unable to determine instance type
[task 2022-07-12T16:14:50.447Z] 16:14:50     INFO - Validating Perfherder data against Z:\task_165764139118664\mozharness\external_tools\performance-artifact-schema.json
[task 2022-07-12T16:14:50.449Z] 16:14:50     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "xpcshell.xpcshell.overall", "extraOptions": ["e10s", "buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 1.3766260162601627}, {"name": "io_write_bytes", "value": 266740224}, {"name": "io.read_bytes", "value": 217839616}, {"name": "io_write_time", "value": 16}, {"name": "io_read_time", "value": 1}]}, {"name": "xpcshell.xpcshell.start-pulseaudio", "subtests": [{"name": "time", "value": 0.012902975082397461}]}, {"name": "xpcshell.xpcshell.install", "subtests": [{"name": "time", "value": 2.862081289291382}, {"name": "cpu_percent", "value": 12.362499999999999}]}, {"name": "xpcshell.xpcshell.stage-files", "subtests": [{"name": "time", "value": 0.02399587631225586}]}, {"name": "xpcshell.xpcshell.run-tests", "subtests": [{"name": "time", "value": 121.39033603668213}, {"name": "cpu_percent", "value": 1.0954166666666667}]}]}
[task 2022-07-12T16:14:50.449Z] 16:14:50     INFO - Total resource usage - Wall time: 123s; CPU: 1%; Read bytes: 217839616; Write bytes: 266740224; Read time: 1; Write time: 16
[task 2022-07-12T16:14:50.449Z] 16:14:50     INFO - TinderboxPrint: CPU usage<br/>1.1%
[task 2022-07-12T16:14:50.449Z] 16:14:50     INFO - TinderboxPrint: I/O read bytes / time<br/>217,839,616 / 1
[task 2022-07-12T16:14:50.449Z] 16:14:50     INFO - TinderboxPrint: I/O write bytes / time<br/>266,740,224 / 16
[task 2022-07-12T16:14:50.449Z] 16:14:50     INFO - TinderboxPrint: CPU idle<br/>972.4 (98.6%)
[task 2022-07-12T16:14:50.450Z] 16:14:50     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-07-12T16:14:50.450Z] 16:14:50     INFO - install - Wall time: 3s; CPU: 12%; Read bytes: 57344; Write bytes: 6680576; Read time: 0; Write time: 3
[task 2022-07-12T16:14:50.450Z] 16:14:50     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-07-12T16:14:50.451Z] 16:14:50     INFO - run-tests - Wall time: 121s; CPU: 1%; Read bytes: 217202176; Write bytes: 249614848; Read time: 1; Write time: 10
[task 2022-07-12T16:14:50.464Z] 16:14:50  WARNING - returning nonzero exit status 2
[taskcluster 2022-07-12T16:14:50.528Z]    Exit Code: 2
[taskcluster 2022-07-12T16:14:50.528Z]    User Time: 15.625ms
[taskcluster 2022-07-12T16:14:50.528Z]  Kernel Time: 15.625ms
[taskcluster 2022-07-12T16:14:50.528Z]    Wall Time: 10m2.1554305s
[taskcluster 2022-07-12T16:14:50.528Z]       Result: FAILED
[taskcluster 2022-07-12T16:14:50.528Z] === Task Finished ===
[taskcluster 2022-07-12T16:14:50.528Z] Task Duration: 10m2.1854304s
[taskcluster 2022-07-12T16:14:50.652Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-12T15:04:29.393Z
[taskcluster 2022-07-12T16:14:51.184Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-12T15:04:29.393Z
[taskcluster 2022-07-12T16:14:51.421Z] Uploading artifact public/test_info/system-info.log from file build\blobber_upload_dir\system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2023-07-12T15:04:29.393Z
[taskcluster 2022-07-12T16:14:51.700Z] Uploading artifact public/test_info/xpcshell_errorsummary.log from file build\blobber_upload_dir\xpcshell_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2023-07-12T15:04:29.393Z
[taskcluster 2022-07-12T16:14:51.911Z] Uploading artifact public/test_info/xpcshell_raw.log from file build\blobber_upload_dir\xpcshell_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2023-07-12T15:04:29.393Z
[taskcluster 2022-07-12T16:14:52.146Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2023-07-12T15:04:29.393Z
[taskcluster:error] exit status 2

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Despite the error, the task sets a successful exit code.

Comment 2

[Joel Maher ( :jmaher ) (UTC -8)]

this is another case of firefox-full running on mozilla-central and failing, BUT looking like success. I have fixed 2 cases of this so far, will look into this one.

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: Bug 1779265 - catch further exceptions in condprof creation. r=sparky!

Comment 4

[Intermittent Failures Robot]

155 failures in 707 pushes (0.219 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 139
• mozilla-central: 16

Platform and build breakdown:

• windows10-64-2004-qr: 91
  • opt: 91
• windows10-64-2004-shippable-qr: 64
  • opt: 64

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1779265&startday=2022-07-12&endday=2022-07-12&tree=all

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/681c35a8d5ba
catch further exceptions in condprof creation. r=sparky

Comment 6

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/681c35a8d5ba

Comment 7

[Intermittent Failures Robot]

85 failures in 715 pushes (0.119 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 69
• mozilla-central: 16

Platform and build breakdown:

• windows10-64-2004-qr: 36
  • opt: 36
• windows10-64-2004-shippable-qr: 49
  • opt: 49

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1779265&startday=2022-07-13&endday=2022-07-13&tree=all

Comment 8

[Intermittent Failures Robot]

240 failures in 3341 pushes (0.072 failures/push) were associated with this bug in the last 7 days.

This is the #4 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 208
• mozilla-central: 32

Platform and build breakdown:

• windows10-64-2004-qr: 127
  • opt: 127
• windows10-64-2004-shippable-qr: 113
  • opt: 113

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1779265&startday=2022-07-11&endday=2022-07-17&tree=all