Closed Bug 1409688 Opened 2 years ago Closed 2 years ago

Permaorange CCov ts_paint_heavy,tp6_google_heavy | 'last-modified'

Categories

(Testing :: Talos, defect, P5)

Version 3
defect

Tracking

(firefox58 fixed)

RESOLVED FIXED
mozilla58
Tracking Status
firefox58 --- fixed

People

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

Details

(Keywords: intermittent-failure, Whiteboard: [PI:October][stockwell fixed:other])

Attachments

(1 file)

Filed by: archaeopteryx [at] coole-files.de

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

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

[task 2017-10-18T11:04:30.893Z] 11:04:30     INFO -  SUITE-START | Running 1 tests
[task 2017-10-18T11:04:30.893Z] 11:04:30     INFO -  TEST-START | ts_paint_heavy
[task 2017-10-18T11:04:30.893Z] 11:04:30     INFO -  Initialising browser for ts_paint_heavy test...
[task 2017-10-18T11:04:32.223Z] 11:04:32     INFO -  TEST-UNEXPECTED-ERROR | ts_paint_heavy | 'last-modified'
[task 2017-10-18T11:04:32.223Z] 11:04:32    ERROR -  Traceback (most recent call last):
[task 2017-10-18T11:04:32.224Z] 11:04:32     INFO -    File "/builds/worker/workspace/build/tests/talos/talos/run_tests.py", line 278, in run_tests
[task 2017-10-18T11:04:32.224Z] 11:04:32     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2017-10-18T11:04:32.225Z] 11:04:32     INFO -    File "/builds/worker/workspace/build/tests/talos/talos/ttest.py", line 60, in runTest
[task 2017-10-18T11:04:32.225Z] 11:04:32     INFO -      with FFSetup(browser_config, test_config) as setup:
[task 2017-10-18T11:04:32.225Z] 11:04:32     INFO -    File "/builds/worker/workspace/build/tests/talos/talos/ffsetup.py", line 180, in __enter__
[task 2017-10-18T11:04:32.226Z] 11:04:32     INFO -      self._init_profile()
[task 2017-10-18T11:04:32.226Z] 11:04:32     INFO -    File "/builds/worker/workspace/build/tests/talos/talos/ffsetup.py", line 98, in _init_profile
[task 2017-10-18T11:04:32.227Z] 11:04:32     INFO -      path = heavy.download_profile(self.test_config['profile'])
[task 2017-10-18T11:04:32.227Z] 11:04:32     INFO -    File "/builds/worker/workspace/build/tests/talos/talos/heavy.py", line 100, in download_profile
[task 2017-10-18T11:04:32.227Z] 11:04:32     INFO -      url, last_modified = follow_redirects(url)
[task 2017-10-18T11:04:32.228Z] 11:04:32     INFO -    File "/builds/worker/workspace/build/tests/talos/talos/heavy.py", line 60, in follow_redirects
[task 2017-10-18T11:04:32.228Z] 11:04:32     INFO -      last_modified = page.headers['Last-Modified']
[task 2017-10-18T11:04:32.229Z] 11:04:32     INFO -    File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/requests/structures.py", line 54, in __getitem__
[task 2017-10-18T11:04:32.229Z] 11:04:32     INFO -      return self._store[key.lower()][1]
[task 2017-10-18T11:04:32.229Z] 11:04:32     INFO -  KeyError: 'last-modified'
[task 2017-10-18T11:04:32.230Z] 11:04:32     INFO -  TEST-INFO took 1333ms
Summary: Intermittent ts_paint_heavy | 'last-modified' → Permaorange CCov ts_paint_heavy | 'last-modified'
our new heavy profile test is causing some intermittents- 
http://searchfox.org/mozilla-central/source/testing/talos/talos/heavy.py#60

this is when we are downloading a profile, I suspect we are getting timeouts on the profile.  :rwood, maybe we increasing the logging and exception handling here, likewise the number of retries.  If we find this is a problem we can come up with an acceptable fallback- I am sure there are a few reasonable options.
Hmmm, I'll have a look
Assignee: nobody → rwood
Status: NEW → ASSIGNED
Interesting, so on linux x64 (where h1-e10s works):

09:07:14     INFO -  * RW * inside while page status_code is 303 and < max tries
09:07:14     INFO -  * RW * location:
09:07:14     INFO -  https://public-artifacts.taskcluster.net/YFeA7LwrQB-WCgQ3X994yw/0/public/today-simple.tgz
09:07:14     INFO -  * RW * about to call requests again with location
09:07:14     INFO -  * RW * about to grab last_modified from page.headers['Last-Modified']
09:07:14     INFO -  * RW * last_modified:
09:07:14     INFO -  2017-10-18 01:10:00
09:07:14     INFO -  * RW * back from follow_redirects
09:07:14     INFO -  url: https://public-artifacts.taskcluster.net/YFeA7LwrQB-WCgQ3X994yw/0/public/today-simple.tgz
09:07:14     INFO -  last_modified:
09:07:14     INFO -  2017-10-18 01:10:00

However on linux x64 ccov, we are redirected to a different URL to get the simple profile, which looks like it doesn't have the 'Last-Modified' page.header:

[task 2017-10-19T16:54:57.772Z] 16:54:57     INFO -  * RW * inside while page status_code is 303 and < max tries
[task 2017-10-19T16:54:57.773Z] 16:54:57     INFO -  * RW * location:
[task 2017-10-19T16:54:57.773Z] 16:54:57     INFO -  https://queue.taskcluster.net/v1/task/YFeA7LwrQB-WCgQ3X994yw/artifacts/public%2Ftoday-simple.tgz
[task 2017-10-19T16:54:57.774Z] 16:54:57     INFO -  * RW * about to call requests again with location
[task 2017-10-19T16:54:58.359Z] 16:54:58     INFO -  * RW * inside while page status_code is 303 and < max tries
[task 2017-10-19T16:54:58.360Z] 16:54:58     INFO -  * RW * location:
[task 2017-10-19T16:54:58.360Z] 16:54:58     INFO -  https://cloud-mirror.taskcluster.net/v1/redirect/s3/us-west-1/https%3A%2F%2Fs3-us-west-2.amazonaws.com%2Ftaskcluster-public-artifacts%2FYFeA7LwrQB-WCgQ3X994yw%2F0%2Fpublic%2Ftoday-simple.tgz
[task 2017-10-19T16:54:58.360Z] 16:54:58     INFO -  * RW * about to call requests again with location
[task 2017-10-19T16:54:58.731Z] 16:54:58     INFO -  * RW * about to grab last_modified from page.headers['Last-Modified']
[task 2017-10-19T16:54:58.732Z] 16:54:58     INFO -  TEST-UNEXPECTED-ERROR | ts_paint_heavy | 'last-modified'
:tarek, being the author of heavy.py, any insight here? Thanks!
Flags: needinfo?(tarek)
one thought- linux64/opt runs on HW in a datacenter, and linux64/ccov runs on a VM in AWS- maybe we are hitting different s3 artifacts.
Summary: Permaorange CCov ts_paint_heavy | 'last-modified' → Permaorange CCov ts_paint_heavy,tp6_google_heavy | 'last-modified'
Whiteboard: [PI:October]
Solution: if page.headers['Last-Modified'] is not available then just default it to none. This is not the last-modified of the local profile; this is the last modified of the profile in automation from tc. The code already defaults to the current date-time when calculating local profile age if this last-modified value is none, so it's fine, it's just it was failing out before being able to be set to None.

[1] http://searchfox.org/mozilla-central/source/testing/talos/talos/heavy.py#76
Flags: needinfo?(tarek)
Comment on attachment 8921500 [details]
Bug 1409688 - default page header last modified to none if not available;

https://reviewboard.mozilla.org/r/192530/#review197686

good fix
Attachment #8921500 - Flags: review?(jmaher) → review+
Pushed by rwood@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7793675566cb
default page header last modified to none if not available; r=jmaher
https://hg.mozilla.org/mozilla-central/rev/7793675566cb
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla58
Whiteboard: [PI:October] → [PI:October][stockwell fixed:other]
You need to log in before you can comment on or make changes to this bug.