Closed Bug 1541281 Opened 6 years ago Closed 4 years ago

Intermittent mozproxy Failed to kill the mitmproxy playback process

Categories

(Testing :: Mozbase, defect, P5)

Version 3
x86_64
macOS
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, regression)

#[markdown(off)]
Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=237703354&repo=autoland

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

21:47:59 INFO - TEST-START | awsy/test_memory_usage.py TestMemoryUsage.test_open_tabs
21:47:59 INFO - areweslimyet run by 0 pages, 1 iterations, 15 perTabPause, 30 settleWaitTime
21:47:59 INFO - setting up
21:47:59 INFO - mozproxy mozproxy_dir used for mitmproxy downloads and exe files: /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy
21:47:59 INFO - Using script ""/Users/cltbld/tasks/task_1554241541/build/tests/awsy/awsy/alternate-server-replay.py /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/yandex.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/apple.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/yahoo-mail.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/imgur.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/imdb.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/ebay.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/twitter.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/youtube.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/google-sheets.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/google-docs.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/google-search.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/google-mail.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/pinterest.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/tumblr.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/microsoft.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/reddit.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/paypal.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/google-slides.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/yahoo-news.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/instagram.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/amazon.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/facebook.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/bing.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/wikipedia.mp /Users/cltbld/tasks/task_1554241541/build/tests/html/testing/mozproxy/wikia.mp""
21:47:59 INFO - mozproxy downloading mitmproxy binary
21:47:59 INFO - mozproxy INFO - File mitmproxy-2.0.2-osx.tar.gz retrieved from local cache /builds/tooltool_cache
21:47:59 INFO - mozproxy INFO - untarring "mitmproxy-2.0.2-osx.tar.gz"
21:48:00 INFO - mozproxy downloading mitmproxy pageset
21:48:00 INFO - mozproxy INFO - File mitmproxy-tp6-instagram-binast.zip retrieved from local cache /builds/tooltool_cache
21:48:00 INFO - mozproxy INFO - File mitmproxy-tp6-ebay.zip retrieved from local cache /builds/tooltool_cache
21:48:00 INFO - mozproxy INFO - File mitmproxy-tp6-google-mail.zip retrieved from local cache /builds/tooltool_cache
21:48:00 INFO - mozproxy INFO - File mitmproxy-tp6-paypal.zip retrieved from local cache /builds/tooltool_cache
21:48:00 INFO - mozproxy INFO - File mitmproxy-tp6-pinterest.zip retrieved from local cache /builds/tooltool_cache
21:48:00 INFO - mozproxy INFO - File mitmproxy-recordings-raptor-tp6.zip retrieved from local cache /builds/tooltool_cache
21:48:00 INFO - mozproxy INFO - File mitmproxy-recordings-raptor-gdocs.zip retrieved from local cache /builds/tooltool_cache
21:48:01 INFO - mozproxy INFO - File raptor-tp6-3.zip retrieved from local cache /builds/tooltool_cache
21:56:05 INFO - switching to tab
21:56:05 INFO - switched to tab
21:56:05 INFO - loading https://www.youtube.com
21:56:07 INFO - loaded!
21:56:23 INFO - switching to tab
21:56:23 INFO - switched to tab
21:56:23 INFO - loading https://yandex.ru/search/?text=barack%20obama&lr=10115
21:56:25 INFO - loaded!
21:56:40 INFO - starting checkpoint TabsOpen...
21:56:47 INFO - checkpoint created, stored in /Users/cltbld/tasks/task_1554241541/build/tests/results/memory-report-TabsOpen-0.json.gz
21:57:17 INFO - starting checkpoint TabsOpenSettled...
21:57:23 INFO - checkpoint created, stored in /Users/cltbld/tasks/task_1554241541/build/tests/results/memory-report-TabsOpenSettled-0.json.gz
21:57:23 INFO - starting gc...
21:57:24 INFO - gc done!
21:57:24 INFO - starting checkpoint TabsOpenForceGC...
21:57:33 INFO - checkpoint created, stored in /Users/cltbld/tasks/task_1554241541/build/tests/results/memory-report-TabsOpenForceGC-0.json.gz
21:57:33 INFO - closing window: 8589934593
21:57:34 INFO - closing window: 10737418241
21:57:34 INFO - closing window: 12884901889
21:57:35 INFO - closing window: 15032385537
21:57:35 INFO - closing window: 17179869185
21:57:35 INFO - closing window: 19327352833
21:57:36 INFO - closing window: 21474836481
21:57:36 INFO - closing window: 2147483665
21:57:37 INFO - closing window: 8589934613
21:57:37 INFO - closing window: 10737418257
21:57:37 INFO - closing window: 12884901903
21:57:37 INFO - closing window: 15032385541
21:57:37 INFO - closing window: 17179869331
21:57:38 INFO - closing window: 19327352884
21:57:38 INFO - closing window: 21474836487
21:57:38 INFO - closing window: 2147483671
21:57:38 INFO - closing window: 8589934629
21:57:38 INFO - closing window: 10737418293
21:57:38 INFO - closing window: 12884901907
21:57:38 INFO - closing window: 15032385582
21:57:38 INFO - closing window: 17179869337
21:57:39 INFO - closing window: 19327353054
21:57:39 INFO - closing window: 21474836492
21:57:39 INFO - closing window: 2147483675
21:57:40 INFO - closing window: 8589934648
21:57:40 INFO - navigating to about:blank
21:57:40 INFO - navigated to about:blank
21:57:40 INFO - starting checkpoint TabsClosedExtraProcesses...
21:57:40 INFO - checkpoint created, stored in /Users/cltbld/tasks/task_1554241541/build/tests/results/memory-report-TabsClosedExtraProcesses-0.json.gz
21:57:40 INFO - closing preloaded browser
21:57:40 INFO - starting checkpoint TabsClosed...
21:57:40 INFO - checkpoint created, stored in /Users/cltbld/tasks/task_1554241541/build/tests/results/memory-report-TabsClosed-0.json.gz
21:58:10 INFO - starting checkpoint TabsClosedSettled...
21:58:11 INFO - checkpoint created, stored in /Users/cltbld/tasks/task_1554241541/build/tests/results/memory-report-TabsClosedSettled-0.json.gz
21:58:11 INFO - starting gc...
21:58:11 INFO - gc done!
21:58:11 INFO - starting checkpoint TabsClosedForceGC...
21:58:11 INFO - checkpoint created, stored in /Users/cltbld/tasks/task_1554241541/build/tests/results/memory-report-TabsClosedForceGC-0.json.gz
21:58:11 INFO - setting results
21:58:11 INFO - tearing down!
21:58:11 INFO - tearing down webservers!
21:58:11 INFO - mozproxy Stopping mitmproxy playback, killing process 676
21:58:12 ERROR - mozproxy Failed to kill the mitmproxy playback process
21:58:12 INFO - mozproxy Turning off the browser proxy
21:58:12 INFO - mozproxy writing: /Users/cltbld/tasks/task_1554241541/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
21:58:12 INFO - processing data in /Users/cltbld/tasks/task_1554241541/build/tests/results!
21:58:17 INFO - PERFHERDER_DATA: {"framework": {"name": "awsy"}, "suites": [{"extraOptions": ["tp6", "stylo"], "name": "Resident Memory", "lowerIsBetter": true, "value": 681646760.8820468, "units": "bytes", "subtests": [{"lowerIsBetter": true, "units": "bytes", "name": "Fresh start", "value": 320876544}, {"lowerIsBetter": true, "units": "bytes", "name": "Fresh start [+30s]", "value": 346030080}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open", "value": 2461741056}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s]", "value": 1769558016}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s, forced GC]", "value": 1706659840}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed extra processes", "value": 490823680}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed", "value": 474378240}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s]", "value": 421425152}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s, forced GC]", "value": 392245248}]}, {"extraOptions": ["tp6", "stylo"], "name": "Explicit Memory", "lowerIsBetter": true, "value": 508416847.5762792, "units": "bytes", "subtests": [{"lowerIsBetter": true, "units": "bytes", "name": "Fresh start", "value": 179705121}, {"lowerIsBetter": true, "units": "bytes", "name": "Fresh start [+30s]", "value": 174159185}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open", "value": 2111087000}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s]", "value": 2085220712}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s, forced GC]", "value": 1960341960}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed extra processes", "value": 413921712}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed", "value": 414810544}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s]", "value": 241963464}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s, forced GC]", "value": 202285512}]}, {"extraOptions": ["tp6", "stylo"], "name": "Heap Unclassified", "lowerIsBetter": true, "value": 88524953.94123758, "units": "bytes", "subtests": [{"lowerIsBetter": true, "units": "bytes", "name": "Fresh start", "value": 30227698}, {"lowerIsBetter": true, "units": "bytes", "name": "Fresh start [+30s]", "value": 30417628}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open", "value": 341101849}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s]", "value": 335343385}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s, forced GC]", "value": 303732496}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed extra processes", "value": 69901913}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed", "value": 70119113}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s]", "value": 49158521}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s, forced GC]", "value": 43378208}]}, {"extraOptions": ["tp6", "stylo"], "name": "JS", "lowerIsBetter": true, "value": 220708133.15162805, "units": "bytes", "subtests": [{"lowerIsBetter": true, "units": "bytes", "name": "Fresh start", "value": 94626792}, {"lowerIsBetter": true, "units": "bytes", "name": "Fresh start [+30s]", "value": 73258128}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open", "value": 1024538664}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s]", "value": 1000220904}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s, forced GC]", "value": 916429608}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed extra processes", "value": 193596728}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed", "value": 194070968}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s]", "value": 77550704}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s, forced GC]", "value": 65512984}]}, {"extraOptions": ["tp6", "stylo"], "name": "Images", "lowerIsBetter": true, "value": 6961615.567390078, "units": "bytes", "subtests": [{"lowerIsBetter": true, "units": "bytes", "name": "Fresh start", "value": 745936}, {"lowerIsBetter": true, "units": "bytes", "name": "Fresh start [+30s]", "value": 1027248}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open", "value": 50130864}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s]", "value": 50111904}, {"lowerIsBetter": true, "units": "bytes", "name": "After tabs open [+30s, forced GC]", "value": 50111328}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed extra processes", "value": 7057184}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed", "value": 7057184}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s]", "value": 5732464}, {"lowerIsBetter": true, "units": "bytes", "name": "Tabs closed [+30s, forced GC]", "value": 1394528}]}]}
21:58:17 INFO - Perfherder data written to /Users/cltbld/tasks/task_1554241541/build/tests/results/perfherder_data.json
21:58:17 INFO - done tearing down!
21:58:17 INFO - TEST-PASS | awsy/test_memory_usage.py TestMemoryUsage.test_open_tabs | took 617680ms
21:58:17 INFO -
21:58:17 INFO - SUMMARY
21:58:17 INFO - -------
21:58:17 INFO - passed: 1
21:58:17 INFO - failed: 0
21:58:17 INFO - todo: 0
21:58:17 INFO - SUITE-END | took 617s
21:58:17 INFO - Return code: 0
21:58:17 INFO - AWSY exited with return code 0: FAILURE
21:58:17 ERROR - # TBPL FAILURE #
21:58:17 WARNING - setting return code to 2
21:58:17 INFO - Running post-action listener: _package_coverage_data
21:58:17 INFO - Running post-action listener: _resource_record_post_action
21:58:17 INFO - Running post-action listener: process_java_coverage_data
21:58:17 INFO - [mozharness: 2019-04-02 21:58:17.824841Z] Finished run-tests step (success)

This is either a problem in mozproxy's mitm.py or in how mozprocess handles kill on osx.

https://searchfox.org/mozilla-central/source/testing/mozbase/mozproxy/mozproxy/backends/mitm.py#217

        exit_code = self.mitmproxy_proc.kill()
        if exit_code != 0:
            # I *think* we can still continue, as process will be automatically
            # killed anyway when mozharness is done (?) if not, we won't be able
            # to startup mitmxproy next time if it is already running
            if exit_code is None:
                LOG.error("Failed to kill the mitmproxy playback process")
            else:

so exit_code as set by ProcessHandler's kill is None. I'm going to punt this mozbase for further triage.

whimboo: Do you know who would be best to look into this and whether it should be handled in mozprocess or mozproxy?

Component: AWSY → Mozbase
Flags: needinfo?(hskupin)

Interesting that this only affects MacOS. Also the output is strange given that we fail within a second here:

23:24:28 INFO - mozproxy Stopping mitmproxy playback, killing process 1855
23:24:29 ERROR - mozproxy Failed to kill the mitmproxy playback process

If we wait it should take longer, and indeed not returning None here. Mind pushing a try build with MOZPROCESS_DEBUG enabled? Or can you reproduce it locally? It doesn't seem to happen that often, so maybe harder to investigate.

Flags: needinfo?(hskupin)
OS: Unspecified → macOS
Hardware: Unspecified → x86_64
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.