1598262 - Intermittent condprof.client.ProfileNotFoundError: 503 | After raptor-mitmproxy Error: Mitmproxy exited with error code 572

Status: RESOLVED DUPLICATE of bug 1587387

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2019-11-21T10:30:51.013Z] 10:30:51 INFO - raptor-control-server Info: received webext_status: Removed tab: 2
[task 2019-11-21T10:30:51.013Z] 10:30:51 INFO - PID 6908 | console.log: "[raptor-runnerjs] post success"
[task 2019-11-21T10:30:52.960Z] 10:30:52 INFO - raptor-main Info: begin browser cycle 7 of 25 for test raptor-tp6-amazon-firefox-cold
[task 2019-11-21T10:30:52.960Z] 10:30:52 INFO - raptor-main Info: starting test: raptor-tp6-amazon-firefox-cold
[task 2019-11-21T10:30:52.960Z] 10:30:52 INFO - raptor-main Info: starting raptor test: raptor-tp6-amazon-firefox-cold
[task 2019-11-21T10:30:52.960Z] 10:30:52 INFO - raptor-main Info: test settings: {'expected_browser_cycles': 25, 'alert_threshold': '2.0', 'playback_pageset_manifest': 'mitm4-linux-firefox-amazon.manifest', 'browser_cycles': '25', 'alert_on': ['fcp', 'loadtime'], 'here': 'C:\Users\task_1574331429\build\tests\raptor\raptor\tests\tp6\desktop', 'expected': 'pass', 'measure': ['fnbpaint', 'fcp', 'dcf', 'loadtime'], 'path': 'C:\Users\task_1574331429\build\tests\raptor\raptor\tests\tp6\desktop\raptor-tp6-amazon-firefox-cold', 'cold': True, 'manifest_relpath': 'tests\tp6\desktop\raptor-tp6-1-cold.ini', 'unit': 'ms', 'ancestor-manifest': 'C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.ini', 'name': 'raptor-tp6-amazon-firefox-cold', 'playback_recordings': 'amazon.mp', 'page_cycles': 1, 'apps': 'firefox', 'test_url': 'https://www.amazon.com/s?k=laptop&ref=nb_sb_noss_1', 'manifest': 'C:\Users\task_1574331429\build\tests\raptor\raptor\tests\tp6\desktop\raptor-tp6-1-cold.ini', 'page_timeout': '60000', 'playback': 'mitmproxy', 'browser_cycle': 7, 'lower_is_better': True, 'type': 'pageload', 'relpath': 'tests\tp6\desktop\raptor-tp6-amazon-firefox-cold'}
[task 2019-11-21T10:30:52.960Z] 10:30:52 INFO - raptor-main Info: raptor config: {'playback_binary_zip': None, 'gecko_profile_entries': None, 'playback_pageset_manifest': 'C:\Users\task_1574331429\build\tests\raptor\raptor\playback\mitm4-linux-firefox-amazon.manifest', 'e10s': True, 'app': 'firefox', 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eJKNuUB4RwWK_QObeDghHA/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'playback_tool': 'mitmproxy', 'host': '127.0.0.1', 'platform': 'win', 'subtest_alert_on': ['fcp', 'loadtime'], 'memory_test': False, 'enable_webrender': False, 'with_conditioned_profile': True, 'binary': 'C:\Users\task_1574331429\build\application\firefox\firefox.exe', 'local_profile_dir': 'c:\users\task_1574331429\appdata\local\temp\tmpeifvls', 'gecko_profile_interval': None, 'enable_control_server_wait': False, 'cpu_test': False, 'playback_version': '4.0.4', 'is_release_build': False, 'playback_files': ['C:\Users\task_1574331429\testing\mozproxy\amazon.mp'], 'playback_pageset_zip': None, 'playback_binary_manifest': 'mitmproxy-rel-bin-4.0.4-{platform}.manifest', 'obj_path': None, 'processor': 'x86_64', 'gecko_profile': False}
[task 2019-11-21T10:30:52.961Z] 10:30:52 INFO - raptor-gen-test-config Info: writing test settings into background js, so webext can get it
[task 2019-11-21T10:30:52.961Z] 10:30:52 INFO - raptor-gen-test-config Info: finished writing test config to C:\Users\task_1574331429\build\tests\raptor\webext\raptor\auto_gen_test_config.js
[task 2019-11-21T10:30:52.961Z] 10:30:52 INFO - raptor-main Info: installing webext C:\Users\task_1574331429\build\tests\raptor\raptor..\webext\raptor
[task 2019-11-21T10:30:52.961Z] 10:30:52 INFO - raptor-main Info: Making temp_download_dir from inside get_conditioned_profile c:\users\task_1574331429\appdata\local\temp\tmpqplwfr
[task 2019-11-21T10:31:23.663Z] 10:31:23 INFO - Getting https://index.taskcluster.net/v1/task/gecko.v2.try.latest.firefox.condprof-win64/artifacts/public/condprof/profile-win64-cold-default.tgz
[task 2019-11-21T10:31:23.663Z] 10:31:23 INFO - raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 1576
[task 2019-11-21T10:31:23.680Z] 10:31:23 ERROR - raptor-mitmproxy Error: Mitmproxy exited with error code 572
[task 2019-11-21T10:31:23.680Z] 10:31:23 INFO - raptor-mitmproxy Info: Turning off the browser proxy
[task 2019-11-21T10:31:23.680Z] 10:31:23 INFO - raptor-mitmproxy Info: writing: C:\Users\task_1574331429\build\application\firefox\distribution\policies.json
[task 2019-11-21T10:31:23.680Z] 10:31:23 INFO - raptor-main Info: removing webext C:\Users\task_1574331429\build\tests\raptor\raptor..\webext\raptor
[task 2019-11-21T10:31:23.680Z] 10:31:23 INFO - raptor-control-server Info: shutting down control server
[task 2019-11-21T10:31:24.037Z] 10:31:24 INFO - raptor-main Info: finished
[task 2019-11-21T10:31:24.042Z] 10:31:24 ERROR - Traceback (most recent call last):
[task 2019-11-21T10:31:24.042Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.py", line 1808, in <module>
[task 2019-11-21T10:31:24.042Z] 10:31:24 INFO - main()
[task 2019-11-21T10:31:24.043Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.py", line 1776, in main
[task 2019-11-21T10:31:24.043Z] 10:31:24 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-11-21T10:31:24.043Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.py", line 272, in run_tests
[task 2019-11-21T10:31:24.043Z] 10:31:24 INFO - self.run_test(test, timeout=int(test.get('page_timeout')))
[task 2019-11-21T10:31:24.043Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.py", line 1105, in run_test
[task 2019-11-21T10:31:24.043Z] 10:31:24 INFO - self.__run_test_cold(test, timeout)
[task 2019-11-21T10:31:24.043Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.py", line 1170, in __run_test_cold
[task 2019-11-21T10:31:24.044Z] 10:31:24 INFO - self.build_browser_profile()
[task 2019-11-21T10:31:24.044Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.py", line 946, in build_browser_profile
[task 2019-11-21T10:31:24.044Z] 10:31:24 INFO - super(Raptor, self).build_browser_profile()
[task 2019-11-21T10:31:24.044Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.py", line 210, in build_browser_profile
[task 2019-11-21T10:31:24.044Z] 10:31:24 INFO - self.get_conditioned_profile()
[task 2019-11-21T10:31:24.044Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\tests\raptor\raptor\raptor.py", line 189, in get_conditioned_profile
[task 2019-11-21T10:31:24.044Z] 10:31:24 INFO - cond_prof_target_dir = get_profile(temp_download_dir, platform, "cold")
[task 2019-11-21T10:31:24.044Z] 10:31:24 INFO - File "C:\Users\task_1574331429\build\venv\lib\site-packages\condprof\client.py", line 59, in get_profile
[task 2019-11-21T10:31:24.045Z] 10:31:24 INFO - raise ProfileNotFoundError(exists)
[task 2019-11-21T10:31:24.045Z] 10:31:24 INFO - condprof.client.ProfileNotFoundError: 503
[task 2019-11-21T10:31:24.071Z] 10:31:24 ERROR - Return code: 1
[task 2019-11-21T10:31:24.071Z] 10:31:24 WARNING - setting return code to 1
[task 2019-11-21T10:31:24.071Z] 10:31:24 INFO - Copying Raptor results to upload dir:
[task 2019-11-21T10:31:24.071Z] 10:31:24 INFO - C:\Users\task_1574331429\build\blobber_upload_dir\perfherder-data.json
[task 2019-11-21T10:31:24.071Z] 10:31:24 INFO - Copying raptor results from C:\Users\task_1574331429\build\raptor.json to C:\Users\task_1574331429\build\blobber_upload_dir\perfherder-data.json
[task 2019-11-21T10:31:24.072Z] 10:31:24 CRITICAL - Error copying results C:\Users\task_1574331429\build\raptor.json to upload dir C:\Users\task_1574331429\build\blobber_upload_dir\perfherder-data.json
[task 2019-11-21T10:31:24.072Z] 10:31:24 INFO - [Errno 2] No such file or directory: u'C:\Users\task_1574331429\build\raptor.json'

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3

Platform breakdown:

• windows7-32-shippable: 1
• windows10-64-shippable: 1
• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1598262&startday=2019-11-18&endday=2019-11-24&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 4331 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1598262&startday=2019-11-25&endday=2019-12-01&tree=all

Comment 3

[Stephen Donner [:stephend] Not actively reading bugmail]

Hi :malexandru: does (did) this have the same underlying cause as bug 1599889, which was "fixed" by bug 1596340, if you know (is it still happening?)

Comment 4

[Alexandru Michis [:malexandru]]

Hello,
I see this bug had a spike of failures on the 21st of November and then a couple of other failures in the 25th, possibly appearing by retriggers.
Since then there have been no occurrences.
The patch in Bug 1596340 landed two days ago on autoland, so I don't really think there is any correlation between this and Bug 1599889.

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform breakdown:

• linux64-shippable-qr: 1
• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1598262&startday=2019-12-02&endday=2019-12-08&tree=all

Comment 6

[Intermittent Failures Robot]

1 failures in 4867 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-ref-hw-2017: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1598262&startday=2019-12-09&endday=2019-12-15&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• windows10-64-ref-hw-2017: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1598262&startday=2019-12-16&endday=2019-12-22&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 3

Platform breakdown:

• windows10-64-ref-hw-2017: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1598262&startday=2019-12-30&endday=2020-01-05&tree=all

Comment 9

[Intermittent Failures Robot]

32 failures in 4472 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

This is the #44 most frequent failure this week.

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

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

Repository breakdown:

• mozilla-central: 32

Platform breakdown:

• windows10-64-ref-hw-2017: 31
• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1598262&startday=2020-01-06&endday=2020-01-12&tree=all

Comment 10

[Alexandru Michis [:malexandru]]

Stephen, any recent progress on this issue?

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 6

Platform breakdown:

• windows10-64-ref-hw-2017: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1598262&startday=2020-01-13&endday=2020-01-19&tree=all

Comment 12

[Florin Strugariu [:Bebe]]

investigating this...

I looks related to Bug 1587387 - Intermittent raptor-mitmproxy Error: Aborting: Mitmproxy process did not startup | Mitmproxy exited with error code 572