Closed Bug 1605885 Opened 2 years ago Closed 2 years ago

Categories

(Testing :: Condprofile, defect, P5)

Version 3
defect

Tracking

(firefox73 fixed, firefox74 fixed)

RESOLVED FIXED
mozilla74
Tracking Status
firefox73 --- fixed
firefox74 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: tarek)

References

(Regression)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=282523399&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Am9yg7JXQamyuH76AeZAkw/runs/0/artifacts/public/logs/live_backing.log


[task 2019-12-24T17:54:33.838Z] Installing collected packages: urllib3, certifi, requests
[task 2019-12-24T17:54:33.838Z] Successfully installed certifi-2019.11.28 requests-2.22.0 urllib3-1.25.7
[task 2019-12-24T17:54:33.838Z] WARNING: You are using pip version 19.2.3, however version 19.3.1 is available.
[task 2019-12-24T17:54:33.838Z] You should consider upgrading via the 'pip install --upgrade pip' command.
[task 2019-12-24T17:54:33.838Z] Looking in links: https://pypi.pub.build.mozilla.org/pub
[task 2019-12-24T17:54:33.838Z] Collecting pyyaml==5.1.2
[task 2019-12-24T17:54:33.838Z] Downloading https://files.pythonhosted.org/packages/e3/e8/b3212641ee2718d556df0f23f78de8303f068fe29cdaa7a91018849582fe/PyYAML-5.1.2.tar.gz (265kB)
[task 2019-12-24T17:54:33.838Z] Building wheels for collected packages: pyyaml
[task 2019-12-24T17:54:33.838Z] Building wheel for pyyaml (setup.py): started
[task 2019-12-24T17:54:33.838Z] Building wheel for pyyaml (setup.py): finished with status 'done'
[task 2019-12-24T17:54:33.838Z] Created wheel for pyyaml: filename=PyYAML-5.1.2-cp36-cp36m-linux_x86_64.whl size=44104 sha256=c76b457a4a36eba120b94d0417cb28b0d15abeb9c5aa8ed6cd6ecaaab60eeabd
[task 2019-12-24T17:54:33.838Z] Stored in directory: /tmp/pip-ephem-wheel-cache-q4w02sv0/wheels/d9/45/dd/65f0b38450c47cf7e5312883deb97d065e030c5cca0a365030
[task 2019-12-24T17:54:33.838Z] Successfully built pyyaml
[task 2019-12-24T17:54:33.838Z] Installing collected packages: pyyaml
[task 2019-12-24T17:54:33.838Z] Successfully installed pyyaml-5.1.2
[task 2019-12-24T17:54:33.838Z] WARNING: You are using pip version 19.2.3, however version 19.3.1 is available.
[task 2019-12-24T17:54:33.838Z] You should consider upgrading via the 'pip install --upgrade pip' command.
[task 2019-12-24T17:54:33.838Z] [2019-12-24T17:50:20.560839] environ({'MOZ_FETCHES': '[{"artifact": "public/build/target.common.tests.tar.gz", "extract": true, "task": "RXPaTgflSh-QGk9OFZCgcQ"}, {"artifact": "public/build/target.condprof.tests.tar.gz", "extract": true, "task": "RXPaTgflSh-QGk9OFZCgcQ"}, {"artifact": "public/build/geckoview_example.apk", "extract": true, "task": "T0SnF8cBQ96KT48HJ8i5zw"}]', 'DOCKER_IMAGE_VERSION': '', 'MOZ_AUTOMATION': '1', 'HOSTNAME': 'bitbar-ubuntu-155', 'OLDPWD': '/builds/task_1577209756', 'TESTDROID_BUILD_ID': '1539733', 'HOST_IP': '10.7.205.155', 'DEBUG': '*', 'TC_WORKER_GROUP': 'bitbar', 'PYTHONIOENCODING': 'utf-8', 'USER': 'root', 'DEVICE_SERIAL': 'FA79W1A10172', 'PWD': '/builds/task_1577209756/fetches/condprofile', 'HOME': '/builds/worker', 'DEVICE_IP': '10.7.205.134', 'CONDPROF_ARCHIVES': '/builds/worker/archive', 'ANDROID_DEVICE': 'FA79W1A10172', 'NEED_XVFB': 'false', 'MOZ_SCM_LEVEL': '3', 'TESTDROID_PROJECT_ID': '417061', 'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com', 'TASK_ID': 'Am9yg7JXQamyuH76AeZAkw', 'MOZ_FETCHES_DIR': '/builds/task_1577209756/fetches', 'DEVICE_NAME': 'pixel2-40', 'SHLVL': '1', 'CONDPROF_ROOT': 'fetches/condprofile', 'PATH': '/builds/worker/.pyenv/shims:/builds/worker/.pyenv/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/builds/worker/bin:/usr/local/bin:/builds/worker/android-sdk-linux/platform-tools:/builds/worker/android-sdk-linux/platform-tools/bin:/builds/worker/android-sdk-linux/tools:/builds/worker/android-sdk-linux/tools/bin:/builds/worker/android-sdk-linux/build-tools/27.0.3:/builds/worker/android-sdk-linux/tools/bin:/builds/worker/android-sdk-linux/platform-tools:/builds/task_1577209756/fetches/bin', 'SCCACHE_DISABLE': '1', 'TC_WORKER_TYPE': 'gecko-t-bitbar-gw-perf-p2', 'TESTDROID_RUN_ID': '40611178', '_': 'bin/python3'})
[task 2019-12-24T17:59:17.605Z] [2019-12-24T17:50:20.560949] Archives directory is /builds/task_1577209756/archive
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:50:20.561009] Verifying Geckodriver binary presence
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:50:20.561203] Getting https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/changelog.json
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:50:21.033031] Downloading https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/changelog.json
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:50:21.298726] Got the changelog from TaskCluster
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:50:21.299676] Building heavy x default
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:50:21.299780] Loaded options for that scenario {'max_urls': 50}
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:50:21.300003] Getting https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/profile-p2_aarch64-geckoview_example-heavy-default.tgz
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:52:32.065654] Cannot find 'https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/profile-p2_aarch64-geckoview_example-heavy-default.tgz'
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:52:32.065726] Failed to get the profile.
[task 2019-12-24T17:59:17.606Z] Traceback (most recent call last):
[task 2019-12-24T17:59:17.606Z] File "condprof/../condprof/client.py", line 82, in get_profile
[task 2019-12-24T17:59:17.606Z] archive = download_file(url, target=downloaded_archive)
[task 2019-12-24T17:59:17.606Z] File "condprof/../condprof/util.py", line 172, in download_file
[task 2019-12-24T17:59:17.606Z] raise ArchiveNotFound(url)
[task 2019-12-24T17:59:17.606Z] condprof.util.ArchiveNotFound: https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/profile-p2_aarch64-geckoview_example-heavy-default.tgz
[task 2019-12-24T17:59:17.606Z]
[task 2019-12-24T17:59:17.606Z] During handling of the above exception, another exception occurred:
[task 2019-12-24T17:59:17.606Z]
[task 2019-12-24T17:59:17.606Z] Traceback (most recent call last):
[task 2019-12-24T17:59:17.606Z] File "condprof/../condprof/client.py", line 84, in get_profile
[task 2019-12-24T17:59:17.606Z] raise ProfileNotFoundError(url)
[task 2019-12-24T17:59:17.606Z] condprof.client.ProfileNotFoundError: https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/profile-p2_aarch64-geckoview_example-heavy-default.tgz
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:02.093388] Getting https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/profile-p2_aarch64-geckoview_example-heavy-default.tgz
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:02.433097] Downloading https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/profile-p2_aarch64-geckoview_example-heavy-default.tgz
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:03.130999] Extracting the tarball content in /tmp/tmp60qkswo2/profile
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:03.490494] Success, we have a profile to work with
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:03.490534] Updating profile located at '/tmp/tmp60qkswo2/profile'
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:03.490553] Reading existing metadata at /tmp/tmp60qkswo2/profile/condprofile.json
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:03.490633] Starting the Gecko app...
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:03.490658] Setting ADB log file to /builds/task_1577209756/archive/adb-heavy-default.log
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:07.313448] Setting org.mozilla.geckoview_example as the debug app on the phone
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:07.518343] Creating the profile on the device
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:09.352028] The profile on the phone will be at /sdcard/tests/condprof/profile
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:10.289238] Pushing /tmp/tmp60qkswo2/profile on the phone
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:18.259774] Creating socket forwarding on port 2828
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:18.365159] Sleeping for 30s
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:48.394211] Writing geckodriver logs in /builds/task_1577209756/archive/geckodriver-heavy-default.log
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:48.469925] Running Webdriver on port 53677
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:48.470093] Running Marionette on port 2828
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:48.470143] Connecting on Android device
[task 2019-12-24T17:59:17.606Z] [2019-12-24T17:53:48.623244] Running the heavy scenario
[task 2019-12-24T17:59:17.606Z] 1/50 https://www.google.com/search?q=sideboard
[task 2019-12-24T17:59:17.606Z] 2/50 https://search.yahoo.com/yhs/search?p=electricity
[task 2019-12-24T17:59:17.606Z] 3/50 https://www.bing.com/search?q=create+list+of+nounspouch
[task 2019-12-24T17:59:17.606Z] 4/50 https://www.ebay.com/sch/i.html?_from=R40&_trksid=p2380057.m570.l1313.TR0.TRC0.H0.Xbottle.TRS0&_nkw=jodhpurs
[task 2019-12-24T17:59:17.606Z] 5/50 https://www.bing.com/search?q=create+list+of+nounsfawn
[task 2019-12-24T17:59:17.606Z] 6/50 https://www.amazon.com/s/ref=nb_sb_noss_2?url=search-alias%3Daps&field-keywords=aunt
[task 2019-12-24T17:59:17.606Z] 7/50 https://www.bing.com/search?q=create+list+of+nounscheetah
[task 2019-12-24T17:59:17.606Z] 8/50 https://www.amazon.com/s/ref=nb_sb_noss_2?url=search-alias%3Daps&field-keywords=trainer
[task 2019-12-24T17:59:17.606Z] 9/50 https://www.youtube.com/results?search_query=cephalopod
[task 2019-12-24T17:59:17.606Z] 10/50 https://www.youtube.com/results?search_query=necktie
[task 2019-12-24T17:59:17.606Z] 11/50 https://search.yahoo.com/yhs/search?p=incident
[task 2019-12-24T17:59:17.606Z] 12/50 https://www.bing.com/search?q=create+list+of+nounsname
[task 2019-12-24T17:59:17.606Z] 13/50 https://www.ebay.com/sch/i.html?_from=R40&_trksid=p2380057.m570.l1313.TR0.TRC0.H0.Xbottle.TRS0&_nkw=motel
[task 2019-12-24T17:59:17.606Z] 14/50 https://www.ebay.com/sch/i.html?_from=R40&_trksid=p2380057.m570.l1313.TR0.TRC0.H0.Xbottle.TRS0&_nkw=lawyer
[task 2019-12-24T17:59:17.606Z] 15/50 https://www.bing.com/search?q=create+list+of+nounsquiver
[task 2019-12-24T17:59:17.606Z] 16/50 https://www.youtube.com/results?search_query=thinking
[task 2019-12-24T17:59:17.606Z] 17/50 https://www.bing.com/search?q=create+list+of+nounscomic
[task 2019-12-24T17:59:17.606Z] 18/50 https://www.youtube.com/results?search_query=gap
[task 2019-12-24T17:59:17.606Z] 19/50 https://www.amazon.com/s/ref=nb_sb_noss_2?url=search-alias%3Daps&field-keywords=concept
[task 2019-12-24T17:59:17.606Z] 20/50 https://www.youtube.com/results?search_query=artichoke
[task 2019-12-24T17:59:17.606Z] 21/50 https://search.yahoo.com/yhs/search?p=nasty
[task 2019-12-24T17:59:17.606Z] 22/50 https://www.youtube.com/results?search_query=jailhouse
[task 2019-12-24T17:59:17.606Z] 23/50 https://www.bing.com/search?q=create+list+of+nounspeach
[task 2019-12-24T17:59:17.606Z] 24/50 https://www.ebay.com/sch/i.html?_from=R40&_trksid=p2380057.m570.l1313.TR0.TRC0.H0.Xbottle.TRS0&_nkw=accountant
[task 2019-12-24T17:59:17.606Z] 25/50 https://www.youtube.com/results?search_query=celeriac
[task 2019-12-24T17:59:17.606Z] 26/50 https://www.ebay.com/sch/i.html?_from=R40&_trksid=p2380057.m570.l1313.TR0.TRC0.H0.Xbottle.TRS0&_nkw=squirrel
[task 2019-12-24T17:59:17.606Z] 27/50 https://search.yahoo.com/yhs/search?p=earrings
[task 2019-12-24T17:59:17.606Z] 28/50 https://www.bing.com/search?q=create+list+of+nounssister-in-law
[task 2019-12-24T17:59:17.606Z] 29/50 https://www.amazon.com/s/ref=nb_sb_noss_2?url=search-alias%3Daps&field-keywords=chainstay
[task 2019-12-24T17:59:17.606Z] 30/50 https://www.youtube.com/results?search_query=level
[task 2019-12-24T17:59:17.606Z] 31/50 https://www.google.com/search?q=great-grandmother--- Logging error ---
[task 2019-12-24T17:59:17.606Z] Traceback (most recent call last):
[task 2019-12-24T17:59:17.606Z] File "/usr/lib/python3.6/logging/init.py", line 996, in emit
[task 2019-12-24T17:59:17.606Z] stream.write(msg)
[task 2019-12-24T17:59:17.606Z] UnicodeEncodeError: 'ascii' codec can't encode character '\u27a1' in position 270696: ordinal not in range(128)
[task 2019-12-24T17:59:17.606Z] Call stack:
[task 2019-12-24T17:59:17.606Z] File "condprof/runner.py", line 186, in <module>
[task 2019-12-24T17:59:17.606Z] main()
[task 2019-12-24T17:59:17.606Z] File "condprof/runner.py", line 178, in main
...

Could this be caused by the changes on bug 1597711 ?

stephend could you, please, take a look?

Flags: needinfo?(stephen.donner)

(Moving from Raptor component to Conditioned Profile).

I'm sorry; I don't know what causes this class of intermittents, which is that the files (correctly named) aren't always available. This mirrors the behavior of bug 1603978, as well. Sorry to cast the net wider, but since Tarek is still on PTO a little while longer: Tom, Dustin - any ideas on the backend failures I presume leads to this temporary condition?

Assignee: nobody → tarek
Component: Raptor → Condprofile
Flags: needinfo?(stephen.donner)
Flags: needinfo?(mozilla)
Flags: needinfo?(dustin)

Could you describe what's happening a bit more concisely? I'm not sure what the log means..

Flags: needinfo?(rwood)
Regressed by: 1604527
Summary: Intermittent Bustage condprof.client.ProfileNotFoundError: https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/profile-p2_aarch64-geckoview_ex → Perma condprof.client.ProfileNotFoundError: https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-p2_aarch64-geckoview_example/artifacts/public/condprof/profile-p2_aarch64-geckoview_ex

The failure from comment 0 is unrelated to trying to download the condprofile. The next line in the log shows it trying to download the same file again and succeeding.

The failure from comment 6 appears to be trying to download a profile from fennec_aurora, for which there does not exist a profile. This is probably partially a fallout from https://hg.mozilla.org/mozilla-central/rev/cb86af33e59f which enables condprofile support on all android products
(such fennec_aurora) when there is not condprofiles generated for them; possibly in concert with another change that introduced new tests that started trying to run tests against those products.

Those two failures should be tracked separately.

I've created bug https://bugzilla.mozilla.org/show_bug.cgi?id=1606199 for failures that are trying to download a profile from fennec_aurora.

See Also: → 1606199

(In reply to Cosmin Sabou [:CosminS] from comment #6)

This bug spiked in failures on this merge to central: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&resultStatus=testfailed%2Cbusted%2Cexception&revision=20b3a68275d5143ff754b4b7e92e624bed5a565e&searchStr=raptor&selectedJob=282816485

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=282816477&repo=mozilla-central&lineNumber=1035
Presumably from Bug 1604527 https://hg.mozilla.org/mozilla-central/rev/0f6acdafe0ebc1116f115cc8999c7a8a520d6122
Rob, please take a look over this. Thank you.

Bug 1604527 is unrelated and I don't believe it caused this regression. This regression is happening on Raptor fennec and has to do with conditioned profiles. Bug 1604527 only enabled some jobs on browsertime android (unrelated to fennec). Thanks!

Flags: needinfo?(rwood)
No longer regressed by: 1604527
Flags: needinfo?(dustin)

The real issue is when the script calls adb log, see Bug 1606793.
The errors on retrying to download the profile should be silent if we succeed at the end. I will work on a patch to fix this

This line should be calling LOG(), not ERROR(). unless it's the last attempt

https://searchfox.org/mozilla-central/source/testing/condprofile/condprof/client.py#108

Flags: needinfo?(mozilla)

If the condprof client retries getting a condprof, it will
display the traceback of the failure. If the task succeeds eventually,
this failure will pollute the logs and confuse Treeherder if there's
another problem later on in the job.

Pushed by tziade@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/aa76437db826
Silent errors if we eventually succeed getting the profile. r=rwood
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla74
You need to log in before you can comment on or make changes to this bug.