1675173 - Intermittent [tier 2] MnFr testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_none | IOError: Process killed because the connection to Marionette server is lost.

Status: RESOLVED FIXED

(Testing :: Marionette Client and Harness, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-11-04T02:33:38.443Z] 02:33:38     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_none
[task 2020-11-04T02:37:31.351Z] 02:37:31     INFO -  DEBUG: Completed blocker places.sqlite#2: PlacesUtils: promiseKeywordsCache (0) for phase places.sqlite#2: waiting for clients
[task 2020-11-04T02:39:38.564Z] 02:39:38     INFO -  1604457578557	Marionette	DEBUG	Closed connection 26
[task 2020-11-04T02:40:49.694Z] 02:40:49    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_none | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
[task 2020-11-04T02:40:49.694Z] 02:40:49     INFO -  Traceback (most recent call last):
[task 2020-11-04T02:40:49.695Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 214, in run
[task 2020-11-04T02:40:49.696Z] 02:40:49     INFO -      testMethod()
[task 2020-11-04T02:40:49.696Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py", line 925, in test_none
[task 2020-11-04T02:40:49.696Z] 02:40:49     INFO -      message="Target page has not been loaded",
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_driver\wait.py", line 134, in until
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -      rv = condition(self.marionette)
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py", line 924, in <lambda>
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -      lambda _: self.marionette.get_url() == self.test_page_slow_resource,
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1464, in get_url
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -      return self._send_message("WebDriver:GetCurrentURL", key="value")
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -      m._handle_socket_failure()
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_driver\marionette.py", line 712, in _handle_socket_failure
[task 2020-11-04T02:40:49.697Z] 02:40:49     INFO -      IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -      return func(*args, **kwargs)
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_driver\marionette.py", line 617, in _send_message
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -      msg = self.client.request(name, params)
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_driver\transport.py", line 288, in request
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -      return self.receive()
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -    File "C:\Users\task_1604449495\build\venv\lib\site-packages\marionette_driver\transport.py", line 192, in receive
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -      "Connection timed out after {}s".format(self.socket_timeout)
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -  TEST-INFO took 431250ms
[task 2020-11-04T02:40:49.698Z] 02:40:49     INFO -  Application command: C:\Users\task_1604449495\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1604449495\appdata\local\temp\tmp6r5mzw.mozrunner
[task 2020-11-04T02:40:49.859Z] 02:40:49     INFO -  DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2020-11-04T02:40:49.859Z] 02:40:49     INFO -  DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2020-11-04T02:40:49.859Z] 02:40:49     INFO -  DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2020-11-04T02:40:49.878Z] 02:40:49     INFO -  DEBUG: Adding blocker ClientManagerService: start destroying IPC actors early for phase xpcom-will-shutdown
[task 2020-11-04T02:40:49.928Z] 02:40:49     INFO -  DEBUG: Adding blocker Flush WebExtension StartupCache for phase profile-before-change
[task 2020-11-04T02:40:50.018Z] 02:40:50     INFO -  DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2020-11-04T02:40:50.023Z] 02:40:50     INFO -  DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2020-11-04T02:40:50.023Z] 02:40:50     INFO -  DEBUG: Completed blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2020-11-04T02:40:50.028Z] 02:40:50     INFO -  DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2020-11-04T02:40:50.028Z] 02:40:50     INFO -  DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2020-11-04T02:40:50.028Z] 02:40:50     INFO -  DEBUG: Adding blocker PluginProvider for phase AddonManager: Waiting for providers to shut down.
[task 2020-11-04T02:40:50.030Z] 02:40:50     INFO -  DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2020-11-04T02:40:50.032Z] 02:40:50     INFO -  DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase OS.File: Waiting for clients before profileBeforeChange
[task 2020-11-04T02:40:50.051Z] 02:40:50     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2020-11-04T02:40:50.074Z] 02:40:50     INFO -  DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2020-11-04T02:40:50.084Z] 02:40:50     INFO -  DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change```

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Hangs when trying to get the current URL:

[task 2020-11-04T02:33:38.544Z] 02:33:38     INFO -  1604457218541	Marionette	DEBUG	26 -> [0,4,"WebDriver:GetCurrentURL",{}]
[task 2020-11-04T02:33:38.544Z] 02:33:38     INFO -  1604457218542	Marionette	TRACE	[90] Frame script unloaded
[task 2020-11-04T02:33:38.548Z] 02:33:38     INFO -  1604457218546	Marionette	TRACE	[90] Frame script loaded
[task 2020-11-04T02:33:38.548Z] 02:33:38     INFO -  1604457218546	Marionette	TRACE	Detected remoteness change. New browsing context: 90

To get this fixed our actors have to be enabled for all builds. See bug 1669169.

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 8

Platform breakdown:

• windows10-64: 6
• windows7-32: 2

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

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Those failures were only logged on November 4th. Since then no more failures seem to have happened. Lets close the bug as incomplete for now.

Comment 5

[Natalia Csoregi [:nataliaCs]]

https://treeherder.mozilla.org/logviewer?job_id=321937122&repo=autoland&lineNumber=21796

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+1]]

The recent failures are:

[task 2020-11-16T19:12:24.990Z] 19:12:24     INFO -  1605553944985	Marionette	DEBUG	26 -> [0,4,"WebDriver:GetCurrentURL",{}]
[task 2020-11-16T19:12:24.990Z] 19:12:24     INFO -  1605553944988	Marionette	TRACE	[90] Frame script unloaded
[task 2020-11-16T19:12:25.009Z] 19:12:25     INFO -  1605553944997	Marionette	TRACE	[90] Frame script loaded
[task 2020-11-16T19:12:25.016Z] 19:12:25     INFO -  1605553945008	Marionette	TRACE	Detected remoteness change. New browsing context: 90
..
[task 2020-11-16T19:18:25.069Z] 19:18:25     INFO -  1605554305033	Marionette	DEBUG	Closed connection 26

So due to a browsing context swap the Get Current URL doesn't seem to return. Usually that shouldn't happen given that the actor gets destroyed and the proxy retries the command for the new browsing context.

Maybe lets wait for bug 1674329 being fixed.

Comment 7

[Intermittent Failures Robot]

54 failures in 4810 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #16 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:

• autoland: 50
• try: 4

Platform breakdown:

• windows7-32: 22
• windows10-64: 4
• linux1804-64: 7
• macosx1014-64-qr: 21

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1675173&startday=2020-11-16&endday=2020-11-22&tree=all

Comment 8

[Dorel Luca [:dluca]]

This bug failed 47 times in the last 7 days. Occurs on linux1804-64, macosx1014-64-qr, windows10-64 and windows7-32 on opt build types.

Recent log:
https://treeherder.mozilla.org/logviewer?job_id=322919120&repo=autoland&lineNumber=22277

Comment 9

[Intermittent Failures Robot]

41 failures in 1479 pushes (0.028 failures/push) were associated with this bug in the last 7 days.

This is the #9 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:

• autoland: 38
• try: 3

Platform breakdown:

• macosx1014-64-qr: 19
• windows7-32: 14
• linux1804-64: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1675173&startday=2020-11-23&endday=2020-11-29&tree=all

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+1]]

This only affects MnFr jobs now that are running as Tier 2. Lets see how often this happens. If it fails still too often we should skip the test when actors aren't enabled.

Comment 11

[Intermittent Failures Robot]

20 failures in 787 pushes (0.025 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 3
• autoland: 17

Platform breakdown:

• android-em-7-0-x86_64: 1
• windows7-32: 3
• macosx1014-64-qr: 8
• linux1804-64: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1675173&startday=2020-12-02&endday=2020-12-02&tree=all

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: Bug 1675173 - [marionette] Disable TestPageLoadStrategy.test_none when actors are disabled.

It's not worth the time to fix this particular bug in the old
framescript code that will go away early next year.

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/907b02c68bfb
[marionette] Disable TestPageLoadStrategy.test_none when actors are disabled. r=marionette-reviewers,jgraham

Comment 14

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/907b02c68bfb

Comment 15

[Intermittent Failures Robot]

59 failures in 3712 pushes (0.016 failures/push) were associated with this bug in the last 7 days.

This is the #15 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 51
• try: 8

Platform breakdown:

• windows7-32: 19
• linux1804-64: 15
• macosx1014-64-qr: 24
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1675173&startday=2020-11-30&endday=2020-12-06&tree=all

Comment 16

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.