Closed Bug 1587387 Opened 2 years ago Closed 2 years ago

Intermittent raptor-mitmproxy Error: Aborting: Mitmproxy process did not startup | Mitmproxy exited with error code 572

Categories

(Testing :: Raptor, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [comment 58])

Attachments

(1 file, 1 obsolete file)

Filed by: shindli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=270411522&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/Ugj4yCsCThOIz4cAjoKUsA/runs/0/artifacts/public/logs/live_backing.log


[taskcluster 2019-10-09T06:45:41.120Z] Worker Type (releng-hardware/gecko-t-win10-64-ref-hw) settings:
[taskcluster 2019-10-09T06:45:41.120Z] {
[taskcluster 2019-10-09T06:45:41.120Z] "config": {
[taskcluster 2019-10-09T06:45:41.120Z] "deploymentId": "",
[taskcluster 2019-10-09T06:45:41.120Z] "runTasksAsCurrentUser": false
[taskcluster 2019-10-09T06:45:41.120Z] },
[taskcluster 2019-10-09T06:45:41.120Z] "generic-worker": {
[taskcluster 2019-10-09T06:45:41.120Z] "go-arch": "amd64",
[taskcluster 2019-10-09T06:45:41.120Z] "go-os": "windows",
[taskcluster 2019-10-09T06:45:41.120Z] "go-version": "go1.10.8",
[taskcluster 2019-10-09T06:45:41.120Z] "release": "https://github.com/taskcluster/generic-worker/releases/tag/v14.1.2",
[taskcluster 2019-10-09T06:45:41.120Z] "revision": "13118c4c1ba10f863f39d6c623b3dd59ca6e0f00",
[taskcluster 2019-10-09T06:45:41.120Z] "source": "https://github.com/taskcluster/generic-worker/commits/13118c4c1ba10f863f39d6c623b3dd59ca6e0f00",
[taskcluster 2019-10-09T06:45:41.120Z] "version": "14.1.2"
[taskcluster 2019-10-09T06:45:41.120Z] }
[taskcluster 2019-10-09T06:45:41.120Z] }
[taskcluster 2019-10-09T06:45:41.121Z] Task ID: Ugj4yCsCThOIz4cAjoKUsA
[taskcluster 2019-10-09T06:45:41.121Z] === Task Starting ===
[taskcluster 2019-10-09T06:45:42.480Z] Uploading redirect artifact public/logs/live.log to URL https://websocktunnel.tasks.build/bitbar.acer-009.60099/log/FB5xKykrTtacKvNF16bf0g with mime type "text/plain; charset=utf-8" and expiry 2019-10-09T07:40:42.070Z
[taskcluster 2019-10-09T06:45:42.830Z] [mounts] Downloading task I0qqOhiTRdCNxWewxKd26w artifact public/build/mozharness.zip to C:\downloads\QRtsqrEUQ2uUEmZwJak6Qw
[taskcluster 2019-10-09T06:45:43.193Z] [mounts] Downloaded 2332958 bytes with SHA256 e89e194bc3baefa58423fece33831a67040fc999e771bf91152d562683896111 from task I0qqOhiTRdCNxWewxKd26w artifact public/build/mozharness.zip to C:\downloads\QRtsqrEUQ2uUEmZwJak6Qw
[taskcluster:warn 2019-10-09T06:45:43.193Z] [mounts] Download C:\downloads\QRtsqrEUQ2uUEmZwJak6Qw of task I0qqOhiTRdCNxWewxKd26w artifact public/build/mozharness.zip has SHA256 e89e194bc3baefa58423fece33831a67040fc999e771bf91152d562683896111 but task payload does not declare a required value, so content authenticity cannot be verified
[taskcluster 2019-10-09T06:45:43.193Z] [mounts] Creating directory C:\Users\task_1570599527 with permissions 0700
[taskcluster 2019-10-09T06:45:43.193Z] [mounts] Extracting zip file C:\downloads\QRtsqrEUQ2uUEmZwJak6Qw to 'C:\Users\task_1570599527'
[taskcluster 2019-10-09T06:45:43.543Z] [mounts] Downloading url https://hg.mozilla.org/mozilla-central/raw-file/26ebfec0883457409f3d2ff8bc882b3b6f4936b2/taskcluster/scripts/run-task to C:\downloads\SuT9r9OqRUCDoAO0q_yruA
[taskcluster 2019-10-09T06:45:44.888Z] [mounts] Downloaded 31468 bytes with SHA256 c69f9ae1494ced424fb5fcc36989f28ef291779f76f61ac6e7a5a1be9a560684 from url https://hg.mozilla.org/mozilla-central/raw-file/26ebfec0883457409f3d2ff8bc882b3b6f4936b2/taskcluster/scripts/run-task to C:\downloads\SuT9r9OqRUCDoAO0q_yruA
[taskcluster:warn 2019-10-09T06:45:44.888Z] [mounts] Download C:\downloads\SuT9r9OqRUCDoAO0q_yruA of url https://hg.mozilla.org/mozilla-central/raw-file/26ebfec0883457409f3d2ff8bc882b3b6f4936b2/taskcluster/scripts/run-task has SHA256 c69f9ae1494ced424fb5fcc36989f28ef291779f76f61ac6e7a5a1be9a560684 but task payload does not declare a required value, so content authenticity cannot be verified
[taskcluster 2019-10-09T06:45:44.888Z] [mounts] Creating directory C:\Users\task_1570599527 with permissions 0700
[taskcluster 2019-10-09T06:45:44.888Z] [mounts] Copying C:\downloads\SuT9r9OqRUCDoAO0q_yruA to C:\Users\task_1570599527\run-task
[taskcluster 2019-10-09T06:45:45.205Z] Executing command 0: C:/mozilla-build/python3/python3.exe run-task -- c:\mozilla-build\python\python.exe -u mozharness\scripts\raptor_script.py --cfg mozharness\configs\raptor\windows_config.py --test=raptor-tp6-cold-4 --download-symbols ondemand
C:\Users\task_1570599527>C:/mozilla-build/python3/python3.exe run-task -- c:\mozilla-build\python\python.exe -u mozharness\scripts\raptor_script.py --cfg mozharness\configs\raptor\windows_config.py --test=raptor-tp6-cold-4 --download-symbols ondemand
[setup 2019-10-09T06:45:46.328Z] run-task started in C:\Users\task_1570599527
[task 2019-10-09T06:45:46.329Z] executing ['c:\mozilla-build\python\python.exe', '-u', 'mozharness\scripts\raptor_script.py', '--cfg', 'mozharness\configs\raptor\windows_config.py', '--test=raptor-tp6-cold-4', '--download-symbols', 'ondemand']
[task 2019-10-09T06:45:47.938Z] 06:45:47 INFO - ConsoleLogger online at 20191009 06:45:47Z in C:\Users\task_1570599527
[task 2019-10-09T06:45:47.938Z] 06:45:47 INFO - Run as mozharness\scripts\raptor_script.py --cfg mozharness\configs\raptor\windows_config.py --test=raptor-tp6-cold-4 --download-symbols ondemand
[task 2019-10-09T06:45:47.938Z] 06:45:47 INFO - Dumping config to C:\Users\task_1570599527\logs\localconfig.json.
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - {u'app': u'firefox',
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - 'append_to_log': False,
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - 'base_work_dir': 'C:\Users\task_1570599527',
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - u'browsertime': False,
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - 'code_coverage': False,
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - 'config_files': ('mozharness\configs\raptor\windows_config.py',),
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - u'cpu_test': False,
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - u'debug_mode': False,
[task 2019-10-09T06:45:47.953Z] 06:45:47 INFO - 'default_actions': ('clobber',
[task 2019-10-09T06:45:47.954Z] 06:45:47 INFO - 'download-and-extract',
[task 2019-10-09T06:45:47.954Z] 06:45:47 INFO - 'populate-webroot',
[task 2019-10-09T06:45:47.954Z] 06:45:47 INFO - 'install-chromium-distribution',
[task 2019-10-09T06:45:47.954Z] 06:45:47 INFO - 'create-virtualenv',
[task 2019-10-09T06:45:47.954Z] 06:45:47 INFO - 'install',

What has Raptor to do with geckodriver?

Component: geckodriver → Raptor
Flags: needinfo?(shindli)

I mixed it up, sorry and thanks for changing it.

Flags: needinfo?(shindli)
Flags: needinfo?(rwood)
Whiteboard: [stockwell needswork:owner]

Hey :bebe can you or someone on SV take a look please? Thanks!

Flags: needinfo?(rwood) → needinfo?(fstrugariu)
Assignee: nobody → fstrugariu
Status: NEW → ASSIGNED
Flags: needinfo?(fstrugariu)
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Flags: needinfo?(fstrugariu)
Resolution: --- → INACTIVE
Status: RESOLVED → REOPENED
Resolution: INACTIVE → ---
Attachment #9103542 - Attachment is obsolete: true
Priority: P5 → P1

There are 42 total failures in the last 7 days on windows10-64-ref-hw-2017 opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=282887141&repo=mozilla-central&lineNumber=706

[task 2019-12-30T02:13:57.004Z] 02:13:57 INFO - raptor-main Info: Browser name: Firefox
[task 2019-12-30T02:13:57.004Z] 02:13:57 INFO - raptor-main Info: Browser version: 73.0a1
[task 2019-12-30T02:13:57.314Z] 02:13:57 INFO - raptor-control-server Info: raptor control server running on port 49776...
[task 2019-12-30T02:13:57.314Z] 02:13:57 INFO - raptor-main Info: creating browser runner using mozrunner
[task 2019-12-30T02:13:57.314Z] 02:13:57 INFO - raptor-main Info: test raptor-tp6-slides-firefox-cold is running in cold mode; browser WILL be restarted between page cycles
[task 2019-12-30T02:13:57.315Z] 02:13:57 INFO - raptor-main Info: begin browser cycle 1 of 25 for test raptor-tp6-slides-firefox-cold
[task 2019-12-30T02:13:57.315Z] 02:13:57 INFO - raptor-main Info: starting test: raptor-tp6-slides-firefox-cold
[task 2019-12-30T02:13:57.315Z] 02:13:57 INFO - raptor-main Info: test uses playback tool: mitmproxy
[task 2019-12-30T02:13:57.552Z] 02:13:57 INFO - raptor-mitmproxy Info: mitmproxy was not provided with a 'playback_binary_manifest' Using default playback_binary_manifest
[task 2019-12-30T02:13:57.552Z] 02:13:57 INFO - raptor-mitmproxy Info: mozproxy_dir used for mitmproxy downloads and exe files: C:\Users\task_1577668183\testing\mozproxy
[task 2019-12-30T02:13:57.553Z] 02:13:57 INFO - raptor-mitmproxy Info: create mitmproxy 4.0.4 dir
[task 2019-12-30T02:13:57.553Z] 02:13:57 INFO - raptor-mitmproxy Info: downloading mitmproxy binary
[task 2019-12-30T02:14:25.135Z] 02:14:25 INFO - raptor-mitmproxy Info: INFO - File mitmproxy-4.0.4-windows.zip retrieved from local cache C:\builds\tooltool_cache
[task 2019-12-30T02:14:35.787Z] 02:14:35 INFO - raptor-mitmproxy Info: INFO - unzipping "mitmproxy-4.0.4-windows.zip"
[task 2019-12-30T02:14:39.680Z] 02:14:39 INFO - raptor-mitmproxy Info: downloading mitmproxy pageset
[task 2019-12-30T02:15:29.679Z] 02:15:29 INFO - raptor-mitmproxy Info: INFO - File mitm4-linux-firefox-google-slides.zip retrieved from local cache C:\builds\tooltool_cache
[task 2019-12-30T02:15:35.834Z] 02:15:35 INFO - raptor-mitmproxy Info: INFO - unzipping "mitm4-linux-firefox-google-slides.zip"
[task 2019-12-30T02:15:36.020Z] 02:15:36 INFO - raptor-mitmproxy Info: mitmdump path: C:\Users\task_1577668183\testing\mozproxy\mitmdump-4.0.4\mitmdump
[task 2019-12-30T02:15:36.020Z] 02:15:36 INFO - raptor-mitmproxy Info: browser path: C:\Users\task_1577668183\build\application\firefox\firefox.exe
[task 2019-12-30T02:15:36.021Z] 02:15:36 INFO - raptor-mitmproxy Info: Starting mitmproxy playback using env path: C:\Users\task_1577668183\build\application\firefox;C:\Users\task_1577668183\build\venv\Scripts;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\System32\WindowsPowerShell\v1.0;C:\WINDOWS\System32\OpenSSH;C:\Program Files\Puppet Labs\Puppet\bin;C:\Program Files (x86)\GNU\GnuPG\pub;C:\Program Files\Mercurial;C:\Program Files\Mercurial;C:\mozilla-build\bin;C:\mozilla-build\kdiff;C:\mozilla-build\moztools-x64\bin;C:\mozilla-build\mozmake;C:\mozilla-build\nsis-3.01;C:\mozilla-build\python;C:\mozilla-build\python\Scripts;C:\mozilla-build\python3;C:\mozilla-build\msys\bin;C:\mozilla-build\msys\local\bin;C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit;C:\Program Files\Git\cmd;C:\Users\task_1577668183\AppData\Local\Microsoft\WindowsApps
[task 2019-12-30T02:15:36.021Z] 02:15:36 INFO - raptor-mitmproxy Info: Starting mitmproxy playback using command: C:\Users\task_1577668183\testing\mozproxy\mitmdump-4.0.4\mitmdump --listen-host 127.0.0.1 --listen-port 49778 -v --set upstream_cert=false --set websocket=false --set server_replay_files=C:\\Users\\task_1577668183\\testing\\mozproxy\\google-slides.mp --scripts C:\\Users\\task_1577668183\\build\\venv\\lib\\site-packages\\mozproxy\\backends\\mitm\\scripts\\alternate-server-replay-4.0.4.py
[task 2019-12-30T02:16:07.020Z] 02:16:07 ERROR - raptor-mitmproxy Error: Aborting: Mitmproxy process did not startup
[task 2019-12-30T02:16:07.020Z] 02:16:07 INFO - raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 3924
[task 2019-12-30T02:16:07.895Z] 02:16:07 ERROR - raptor-mitmproxy Error: Mitmproxy exited with error code 572
[task 2019-12-30T02:16:07.895Z] 02:16:07 INFO - raptor-control-server Info: shutting down control server
[task 2019-12-30T02:16:08.017Z] 02:16:08 INFO - raptor-main Info: finished
[task 2019-12-30T02:16:08.158Z] 02:16:08 ERROR - Traceback (most recent call last):
[task 2019-12-30T02:16:08.158Z] 02:16:08 INFO - File "C:\Users\task_1577668183\build\tests\raptor\raptor\raptor.py", line 1926, in <module>
[task 2019-12-30T02:16:08.158Z] 02:16:08 INFO - main()
[task 2019-12-30T02:16:08.158Z] 02:16:08 INFO - File "C:\Users\task_1577668183\build\tests\raptor\raptor\raptor.py", line 1884, in main
[task 2019-12-30T02:16:08.159Z] 02:16:08 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-12-30T02:16:08.159Z] 02:16:08 INFO - File "C:\Users\task_1577668183\build\tests\raptor\raptor\raptor.py", line 304, in run_tests
[task 2019-12-30T02:16:08.159Z] 02:16:08 INFO - self.run_test_teardown(test)
[task 2019-12-30T02:16:08.159Z] 02:16:08 INFO - File "C:\Users\task_1577668183\build\tests\raptor\raptor\raptor.py", line 1371, in run_test_teardown
[task 2019-12-30T02:16:08.159Z] 02:16:08 INFO - if self.runner.is_running():
[task 2019-12-30T02:16:08.159Z] 02:16:08 INFO - File "C:\Users\task_1577668183\build\venv\lib\site-packages\mozrunner\base\runner.py", line 171, in is_running
[task 2019-12-30T02:16:08.160Z] 02:16:08 INFO - return self.returncode is None
[task 2019-12-30T02:16:08.160Z] 02:16:08 INFO - File "C:\Users\task_1577668183\build\venv\lib\site-packages\mozrunner\base\runner.py", line 87, in returncode
[task 2019-12-30T02:16:08.160Z] 02:16:08 INFO - raise RunnerNotStartedError("returncode accessed before runner started")
[task 2019-12-30T02:16:08.160Z] 02:16:08 INFO - mozrunner.errors.RunnerNotStartedError: returncode accessed before runner started
[task 2019-12-30T02:16:08.331Z] 02:16:08 ERROR - Return code: 1
[task 2019-12-30T02:16:08.331Z] 02:16:08 WARNING - setting return code to 1

Florin are you working on this? If not, do you know who can?

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

these failures happen only on windows10-64-ref-hw-2017.

investigating on local hw and managed to reproduce the fail only on the first run. After that all worked as expected.

started try build with a retry procedure:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a142c4f7fa8bb9c8aeb6ba950e316016a2137117

Duplicate of this bug: 1598836

Florin are there updates here? Is there a way to disable this?

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

:apavel I'm working on it but as the hw is really slow it takes time

New try build:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=514b04c432ee5fd6b0337c8fd0fee7045b0cd500

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Exit code 572 happens when we close the mitm proxy. I think we can ignore this error when exiting the proxy.

I am a bit skeptical about this change because terminating a process on windows via the api should return 0 as far as I know, so I don't have a good explanation about what does this (supposedly a ctrl+C) but process handling on win32 is a bit weird and the behavior is not going to change for Raptor since we are already ignoring non-zero exit codes.

This will also not fix the intermittents. It's just that treeherder is confused when it encounter the 572 traceback in the logs and thinks that the traceback it needs to display as being the problem of the intermittent.

The only difference with Bebe patch is that we won't output the "Mitmproxy exited with error code 572" error in the logs anymore and that will help us understanding the real issue, which should be picked by treeherder.

Pushed by fstrugariu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c31f6054754f
Ignore error 572 when stoping mitmproxy r=tarek
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla74
See Also: → 1547943

There are 52 total failures since the patch here landed, Florin please take a look.

Flags: needinfo?(fstrugariu)
Flags: needinfo?(fstrugariu)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Duplicate of this bug: 1547943

:fstrugariu , there are ~86 failures since the "fix" landed and 177 in the last 7 days.

See Also: → 1598262
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Florin, i saw that the try build mentioned above still has failures.
This has also reached the disable-recommended queue again. Is there a way to disable this until there is a fix?

Flags: needinfo?(fstrugariu)
Flags: needinfo?(fstrugariu)

[:apavel] I have this intermittent as P1. But as the testing hw is limited it takes long time to investigate and fix this issue.

Hopefully I will have a patch by the end of the week.

Flags: needinfo?(fstrugariu)

(In reply to Florin Strugariu [:Bebe] (needinfo me) from comment #55)

[:apavel] I have this intermittent as P1. But as the testing hw is limited it takes long time to investigate and fix this issue.

Hopefully I will have a patch by the end of the week.

Thank you for the update.

Whiteboard: [stockwell disable-recommended] → [comment 55]

Looks like we managed to bring this intermittent down... or to be more exact point out the real failures...

Priority: P1 → P5
Duplicate of this bug: 1598262
Whiteboard: [comment 55][stockwell disable-recommended] → [comment 58]
Duplicate of this bug: 1608241
Duplicate of this bug: 1603978

Florin, can this bug also be closed now?

Flags: needinfo?(fstrugariu)

Closing this as intermittent should be fixed.

Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Flags: needinfo?(fstrugariu)
Resolution: --- → FIXED
Resolution: FIXED → WORKSFORME
You need to log in before you can comment on or make changes to this bug.