Closed Bug 1677750 Opened 4 years ago Closed 4 years ago

Frequent windows10 ccov TEST-UNEXPECTED-TIMEOUT | /_mozilla/webdriver/new_session/debugger_address.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

All
Windows
defect

Tracking

(firefox84 unaffected, firefox85 disabled, firefox118 disabled)

RESOLVED FIXED
85 Branch
Tracking Status
firefox84 --- unaffected
firefox85 --- disabled
firefox118 --- disabled

People

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

References

(Blocks 1 open bug, Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

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


[task 2020-11-17T12:21:46.448Z] 12:21:46     INFO - TEST-START | /_mozilla/webdriver/new_session/debugger_address.py
[task 2020-11-17T12:21:46.776Z] 12:21:46     INFO - STDOUT: ============================= test session starts =============================
[task 2020-11-17T12:21:46.776Z] 12:21:46     INFO - STDOUT: platform win32 -- Python 2.7.15, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- Z:\task_1605612265\build\venv\Scripts\python.exe
[task 2020-11-17T12:21:46.776Z] 12:21:46     INFO - STDOUT: rootdir: Z:\task_1605612265\build, inifile:
[task 2020-11-17T12:21:46.776Z] 12:21:46     INFO - STDOUT: collecting ... 
[task 2020-11-17T12:21:46.781Z] 12:21:46     INFO - STDOUT: collected 3 items
[task 2020-11-17T12:21:46.781Z] 12:21:46     INFO - STDOUT: tests/web-platform/mozilla/tests/webdriver/new_session/debugger_address.py::test_debugger_address_not_set 
[task 2020-11-17T12:21:46.788Z] 12:21:46     INFO - PID 1252 | 1605615706780	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"binary": "Z:\\task_1605612265\\build\\application\\firefox\\firefox.exe", "prefs": {"network.process.enabled": false, "media.peerconnection.mtransport_process": false, "layers.d3d11.enable-blacklist": false, "network.dns.localDomains": "www1.xn--n8j6ds53lwwkrqhv28a.web-platform.test,op88.web-platform.test,op36.not-web-platform.test,op53.not-web-platform.test,op50.not-web-platform.test,xn--lve-6lad.www.web-platform.test,op98.web-platform.test,op24.not-web-platform.test,op31.not-web-platform.test,op95.not-web-platform.test,op85.web-platform.test,op83.not-web-platform.test,www2.not-web-platform.test,xn--lve-6lad.www.not-web-platform.test,op73.not-web-platform.test,op8.web-platform.test,www2.www2.not-web-platform.test,op89.web-platform.test,op66.web-platform.test,xn--lve-6lad.web-platform.test,op19.not-web-platform.test,www1.www2.web-platform.test,op72.web-platform.test,op24.web-platform.test,op21.not-web-platform.test,xn--lve-6lad.not-web-platform.test,op41.web-platform.test,op79.web-platform.test,op81.not-web-platform.test,op70.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.not-web-platform.test,op78.not-web-platform.test,op6.not-web-platform.test,www1.www.not-web-platform.test,op40.not-web-platform.test,op25.not-web-platform.test,op3.not-web-platform.test,op65.not-web-platform.test,op91.web-platform.test,www.www2.web-platform.test,op80.not-web-platform.test,op59.web-platform.test,op52.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.web-platform.test,op68.not-web-platform.test,op45.not-web-platform.test,op71.not-web-platform.test,op72.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.web-platform.test,op39.web-platform.test,op90.not-web-platform.test,op60.web-platform.test,op58.web-platform.test,op28.web-platform.test,www1.web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.web-platform.test,op14.web-platform.test,op89.not-web-platform.test,op69.web-platform.test,op49.not-web-platform.test,op40.web-platform.test,op2.not-web-platform.test,op5.not-web-platform.test,www.www2.not-web-platform.test,op77.not-web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.web-platform.test,op7.web-platform.test,op74.web-platform.test,op79.not-web-platform.test,op82.not-web-platform.test,www.www1.web-platform.test,op12.not-web-platform.test,op39.not-web-platform.test,op31.web-platform.test,www.not-web-platform.test,www.www.not-web-platform.test,op44.not-web-platform.test,www1.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.web-platform.test,op58.not-web-platform.test,op14.not-web-platform.test,op30.not-web-platform.test,op62.not-web-platform.test,op61.not-web-platform.test,op92.not-web-platform.test,www2.xn--lve-6lad.web-platform.test,op29.not-web-platform.test,op18.web-platform.test,op73.web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.web-platform.test,op77.web-platform.test,op12.web-platform.test,op54.web-platform.test,op63.web-platform.test,op71.web-platform.test,www2.www1.not-web-platform.test,op95.web-platform.test,op16.web-platform.test,op36.web-platform.test,op27.web-platform.test,www.www.web-platform.test,op98.not-web-platform.test,op64.not-web-platform.test,op29.web-platform.test,op9.web-platform.test,op26.not-web-platform.test,op94.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.not-web-platform.test,op44.web-platform.test,op94.not-web-platform.test,op33.web-platform.test,op38.not-web-platform.test,op33.not-web-platform.test,op84.web-platform.test,www1.www1.not-web-platform.test,op23.not-web-platform.test,op57.not-web-platform.test,op54.not-web-platform.test,op85.not-web-platform.test,www2.www2.web-platform.test,op46.not-web-platform.test,op97.not-web-platform.test,op32.web-platform.test,op61.web-platform.test,op70.web-platform.test,www2.web-platform.test,op32.not-web-platform.test,op60.not-web-platform.test,op4.web-platform.test,op43.web-platform.test,op7.not-web-platform.test,op78.web-platform.test,op26.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.web-platform.test,op96.not-web-platform.test,op51.not-web-platform.test,op41.not-web-platform.test,op76.web-platform.test,op52.web-platform.test,op99.web-platform.test,op35.not-web-platform.test,op99.not-web-platform.test,op86.web-platform.test,not-web-platform.test,op42.not-web-platform.test,op46.web-platform.test,op67.not-web-platform.test,op17.web-platform.test,op90.web-platform.test,op93.web-platform.test,op37.not-web-platform.test,op48.not-web-platform.test,op10.web-platform.test,op55.not-web-platform.test,op4.not-web-platform.test,www1.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op55.web-platform.test,xn--lve-6lad.www2.web-platform.test,op47.web-platform.test,op51.web-platform.test,op45.web-platform.test,op80.web-platform.test,op68.web-platform.test,op49.web-platform.test,op57.web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op56.not-web-platform.test,op35.web-platform.test,op84.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op34.not-web-platform.test,op6.web-platform.test,web-platform.test,op67.web-platform.test,op69.not-web-platform.test,op11.not-web-platform.test,op93.not-web-platform.test,www1.www.web-platform.test,op86.not-web-platform.test,op8.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op92.web-platform.test,xn--lve-6lad.www1.not-web-platform.test,op15.web-platform.test,op13.not-web-platform.test,op13.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.web-platform.test,op75.web-platform.test,op20.not-web-platform.test,op76.not-web-platform.test,op64.web-platform.test,op97.web-platform.test,op37.web-platform.test,op56.web-platform.test,op62.web-platform.test,op82.web-platform.test,op25.web-platform.test,op11.web-platform.test,www.xn--lve-6lad.not-web-platform.test,www2.www1.web-platform.test,op27.not-web-platform.test,op50.web-platform.test,op17.not-web-platform.test,op38.web-platform.test,www2.www.not-web-platform.test,xn--lve-6lad.www1.web-platform.test,op75.not-web-platform.test,op83.web-platform.test,op81.web-platform.test,op15.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.not-web-platform.test,op20.web-platform.test,op3.web-platform.test,www1.www2.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op2.web-platform.test,op21.web-platform.test,op23.web-platform.test,op42.web-platform.test,op47.not-web-platform.test,www1.www1.web-platform.test,op18.not-web-platform.test,op22.web-platform.test,xn--lve-6lad.xn--lve-6lad.not-web-platform.test,op63.not-web-platform.test,op28.not-web-platform.test,op22.not-web-platform.test,op65.web-platform.test,www.www1.not-web-platform.test,www1.xn--lve-6lad.web-platform.test,op43.not-web-platform.test,op66.not-web-platform.test,www2.www.web-platform.test,op96.web-platform.test,op91.not-web-platform.test,www.xn--lve-6lad.web-platform.test,op1.web-platform.test,op74.not-web-platform.test,op87.web-platform.test,op59.not-web-platform.test,op19.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.not-web-platform.test,op9.not-web-platform.test,op88.not-web-platform.test,op53.web-platform.test,www2.xn--lve-6lad.not-web-platform.test,op87.not-web-platform.test,op30.web-platform.test,op10.not-web-platform.test,op48.web-platform.test,op16.not-web-platform.test,op34.web-platform.test,op1.not-web-platform.test,www.web-platform.test,op5.web-platform.test,www1.xn--lve-6lad.not-web-platform.test,xn--lve-6lad.www2.not-web-platform.test", "toolkit.asyncshutdown.log": true}}}}}
[task 2020-11-17T12:21:46.788Z] 12:21:46     INFO - PID 1252 | 1605615706781	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2020-11-17T12:21:46.788Z] 12:21:46     INFO - PID 1252 | 1605615706782	geckodriver::capabilities	DEBUG	Found version 85.0a1
[task 2020-11-17T12:21:46.793Z] 12:21:46     INFO - PID 1252 | 1605615706786	mozrunner::runner	INFO	Running command: "Z:\\task_1605612265\\build\\application\\firefox\\firefox.exe" "--marionette" "-foreground" "-no-remote" "-profile" "C:\\Users\\task_1605612265\\AppData\\Local\\Temp\\rust_mozprofileNqnk4h"
[task 2020-11-17T12:21:46.793Z] 12:21:46     INFO - PID 1252 | 1605615706787	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2020-11-17T12:21:47.242Z] 12:21:47     INFO - PID 1252 | DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2020-11-17T12:21:47.242Z] 12:21:47     INFO - PID 1252 | DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2020-11-17T12:21:47.261Z] 12:21:47     INFO - PID 1252 | DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2020-11-17T12:21:47.344Z] 12:21:47     INFO - PID 1252 | DEBUG: Adding blocker ClientManagerService: start destroying IPC actors early for phase xpcom-will-shutdown
[task 2020-11-17T12:21:47.567Z] 12:21:47     INFO - PID 1252 | DEBUG: Adding blocker Flush WebExtension StartupCache for phase profile-before-change
[task 2020-11-17T12:21:47.977Z] 12:21:47     INFO - PID 1252 | DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2020-11-17T12:21:47.982Z] 12:21:47     INFO - PID 1252 | DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2020-11-17T12:21:47.987Z] 12:21:47     INFO - PID 1252 | DEBUG: Completed blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2020-11-17T12:21:48.007Z] 12:21:48     INFO - PID 1252 | DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2020-11-17T12:21:48.012Z] 12:21:48     INFO - PID 1252 | DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2020-11-17T12:21:48.012Z] 12:21:48     INFO - PID 1252 | DEBUG: Adding blocker PluginProvider for phase AddonManager: Waiting for providers to shut down.
[task 2020-11-17T12:21:48.013Z] 12:21:48     INFO - PID 1252 | DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2020-11-17T12:21:48.031Z] 12:21:48     INFO - PID 1252 | 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-17T12:21:48.090Z] 12:21:48     INFO - PID 1252 | DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2020-11-17T12:21:48.155Z] 12:21:48     INFO - PID 1252 | DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2020-11-17T12:21:48.194Z] 12:21:48     INFO - PID 1252 | DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2020-11-17T12:21:48.203Z] 12:21:48     INFO - PID 1252 | 1605615708193	Marionette	TRACE	Marionette enabled
[task 2020-11-17T12:21:48.447Z] 12:21:48     INFO - PID 1252 | 1605615708437	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-11-17T12:21:49.102Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker MediaShutdownManager: shutdown for phase profile-before-change
[task 2020-11-17T12:21:49.180Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-11-17T12:21:49.180Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-11-17T12:21:49.182Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker Flush AddonRepository for phase profile-before-change
[task 2020-11-17T12:21:49.202Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker Remote Settings profile-before-change for phase profile-before-change
[task 2020-11-17T12:21:49.592Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker GMPProvider for phase AddonManager: Waiting for providers to shut down.
[task 2020-11-17T12:21:49.611Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker PluginFinder: finding plugins to load for phase profile-change-teardown
[task 2020-11-17T12:21:49.611Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker ContentParent: id=1d7674f5000 for phase xpcom-will-shutdown
[task 2020-11-17T12:21:49.611Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker ContentParent: id=1d7674f5000 for phase profile-before-change
[task 2020-11-17T12:21:49.793Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker ServiceWorkerShutdownBlocker: shutting down Service Workers for phase profile-change-teardown
[task 2020-11-17T12:21:49.832Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker ContentParent: id=1d7682a8000 for phase xpcom-will-shutdown[task 2020-11-17T12:21:49.832Z] 12:21:49     INFO - PID 1252 | DEBUG: Adding blocker ContentParent: id=1d7682a8000 for phase profile-before-change
[task 2020-11-17T12:21:50.430Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker Places Clients shutdown for phase profile-change-teardown
[task 2020-11-17T12:21:50.430Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker Places Connection shutdown for phase profile-before-change
[task 2020-11-17T12:21:50.470Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker PageActions: purging unregistered actions from cache for phase profile-before-change
[task 2020-11-17T12:21:50.572Z] 12:21:50     INFO - PID 1252 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
[task 2020-11-17T12:21:50.615Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker Sqlite.jsm shutdown blocker for phase profile-before-change
[task 2020-11-17T12:21:50.615Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker content-prefs.sqlite#0: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2020-11-17T12:21:50.615Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker Closing ContentPrefService2 connection. for phase Sqlite.jsm: wait until all clients have completed their task
[task 2020-11-17T12:21:50.637Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2020-11-17T12:21:50.757Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker sanitize.js: Sanitize on shutdown for phase Places Clients shutdown
[task 2020-11-17T12:21:50.918Z] 12:21:50     INFO - PID 1252 | DEBUG: Adding blocker DoHController: clear state and remove observers for phase profile-before-change
[task 2020-11-17T12:21:51.122Z] 12:21:51     INFO - PID 1252 | DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-11-17T12:21:51.224Z] 12:21:51     INFO - PID 1252 | DEBUG: Completed blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2020-11-17T12:21:51.289Z] 12:21:51     INFO - PID 1252 | DEBUG: Adding blocker Transaction (1) for phase content-prefs.sqlite#0: waiting for clients
[task 2020-11-17T12:21:51.289Z] 12:21:51     INFO - PID 1252 | DEBUG: Adding blocker Transaction (2) for phase content-prefs.sqlite#0: waiting for clients
[task 2020-11-17T12:21:51.352Z] 12:21:51     INFO - PID 1252 | DEBUG: Adding blocker IOUtils Blocker for phase profile-before-change
[task 2020-11-17T12:21:51.395Z] 12:21:51     INFO - PID 1252 | DEBUG: Adding blocker DownloadAutoSaveView: writing data for phase profile-before-change
[task 2020-11-17T12:21:51.546Z] 12:21:51     INFO - PID 1252 | DEBUG: Adding blocker Places Expiration: shutdown for phase Places Connection shutdown
[task 2020-11-17T12:21:51.576Z] 12:21:51     INFO - PID 1252 | DEBUG: Completed blocker Transaction (1) for phase content-prefs.sqlite#0: waiting for clients[task 2020-11-17T12:22:39.671Z] 12:22:39     INFO - PID 1252 | DEBUG: Starting phase profile-before-change-telemetry
[task 2020-11-17T12:22:39.671Z] 12:22:39     INFO - PID 1252 | DEBUG: Spinning the event loop
[task 2020-11-17T12:22:39.852Z] 12:22:39     INFO - PID 1252 | DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2020-11-17T12:22:39.862Z] 12:22:39     INFO - PID 1252 | DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2020-11-17T12:22:39.881Z] 12:22:39     INFO - PID 1252 | DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2020-11-17T12:22:39.899Z] 12:22:39     INFO - PID 1252 | DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2020-11-17T12:22:39.909Z] 12:22:39     INFO - PID 1252 | DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2020-11-17T12:22:39.934Z] 12:22:39     INFO - PID 1252 | DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2020-11-17T12:22:39.934Z] 12:22:39     INFO - PID 1252 | DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2020-11-17T12:22:39.939Z] 12:22:39     INFO - PID 1252 | DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2020-11-17T12:22:39.944Z] 12:22:39     INFO - PID 1252 | DEBUG: Completed blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2020-11-17T12:22:39.945Z] 12:22:39     INFO - PID 1252 | DEBUG: Finished phase profile-before-change-telemetry
[task 2020-11-17T12:22:39.946Z] 12:22:39     INFO - PID 1252 | 1605615759939	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2020-11-17T12:22:39.946Z] 12:22:39     INFO - PID 1252 | 1605615759940	Marionette	DEBUG	Resetting recommended pref apz.content_response_timeout
[task 2020-11-17T12:22:39.947Z] 12:22:39     INFO - PID 1252 | 1605615759940	Marionette	DEBUG	Resetting recommended pref browser.contentblocking.introCount
[task 2020-11-17T12:22:39.948Z] 12:22:39     INFO - PID 1252 | 1605615759941	Marionette	DEBUG	Resetting recommended pref browser.download.panel.shown
[task 2020-11-17T12:22:39.948Z] 12:22:39     INFO - PID 1252 | 1605615759941	Marionette	DEBUG	Resetting recommended pref browser.newtabpage.enabled
[task 2020-11-17T12:22:39.949Z] 12:22:39     INFO - PID 1252 | 1605615759943	Marionette	DEBUG	Resetting recommended pref browser.pagethumbnails.capturing_disabled
[task 2020-11-17T12:22:39.950Z] 12:22:39     INFO - PID 1252 | 1605615759943	Marionette	DEBUG	Resetting recommended pref browser.search.update
[task 2020-11-17T12:22:39.950Z] 12:22:39     INFO - PID 1252 | 1605615759943	Marionette	DEBUG	Resetting recommended pref browser.tabs.disableBackgroundZombification
[task 2020-11-17T12:22:39.951Z] 12:22:39     INFO - PID 1252 | 1605615759944	Marionette	DEBUG	Resetting recommended pref browser.tabs.remote.separatePrivilegedContentProcess
[task 2020-11-17T12:22:39.952Z] 12:22:39     INFO - PID 1252 | 1605615759944	Marionette	DEBUG	Resetting recommended pref browser.tabs.unloadOnLowMemory
[task 2020-11-17T12:22:39.953Z] 12:22:39     INFO - PID 1252 | 1605615759945	Marionette	DEBUG	Resetting recommended pref browser.tabs.warnOnCloseOtherTabs
[task 2020-11-17T12:22:39.953Z] 12:22:39     INFO - PID 1252 | 1605615759945	Marionette	DEBUG	Resetting recommended pref browser.tabs.warnOnOpen
[task 2020-11-17T12:22:39.954Z] 12:22:39     INFO - PID 1252 | 1605615759945	Marionette	DEBUG	Resetting recommended pref browser.toolbars.bookmarks.visibility
[task 2020-11-17T12:22:39.954Z] 12:22:39     INFO - PID 1252 | 1605615759946	Marionette	DEBUG	Resetting recommended pref browser.usedOnWindows10.introURL
[task 2020-11-17T12:22:39.955Z] 12:22:39     INFO - PID 1252 | 1605615759946	Marionette	DEBUG	Resetting recommended pref browser.urlbar.suggest.searches
[task 2020-11-17T12:22:39.956Z] 12:22:39     INFO - PID 1252 | 1605615759948	Marionette	DEBUG	Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted
[task 2020-11-17T12:22:39.956Z] 12:22:39     INFO - PID 1252 | 1605615759949	Marionette	DEBUG	Resetting recommended pref dom.disable_beforeunload
[task 2020-11-17T12:22:39.957Z] 12:22:39     INFO - PID 1252 | 1605615759949	Marionette	DEBUG	Resetting recommended pref dom.disable_open_during_load
[task 2020-11-17T12:22:39.958Z] 12:22:39     INFO - PID 1252 | 1605615759949	Marionette	DEBUG	Resetting recommended pref dom.file.createInChild
[task 2020-11-17T12:22:39.958Z] 12:22:39     INFO - PID 1252 | 1605615759950	Marionette	DEBUG	Resetting recommended pref dom.max_chrome_script_run_time
[task 2020-11-17T12:22:39.959Z] 12:22:39     INFO - PID 1252 | 1605615759950	Marionette	DEBUG	Resetting recommended pref dom.max_script_run_time
[task 2020-11-17T12:22:39.960Z] 12:22:39     INFO - PID 1252 | 1605615759952	Marionette	DEBUG	Resetting recommended pref dom.push.connection.enabled
[task 2020-11-17T12:22:39.960Z] 12:22:39     INFO - PID 1252 | 1605615759952	Marionette	DEBUG	Resetting recommended pref extensions.getAddons.cache.enabled
[task 2020-11-17T12:22:39.961Z] 12:22:39     INFO - PID 1252 | 1605615759953	Marionette	DEBUG	Resetting recommended pref extensions.getAddons.discovery.api_url
[task 2020-11-17T12:22:39.961Z] 12:22:39     INFO - PID 1252 | 1605615759953	Marionette	DEBUG	Resetting recommended pref network.http.prompt-temp-redirect
[task 2020-11-17T12:22:39.961Z] 12:22:39     INFO - PID 1252 | 1605615759953	Marionette	DEBUG	Resetting recommended pref privacy.trackingprotection.enabled
[task 2020-11-17T12:22:39.961Z] 12:22:39     INFO - PID 1252 | 1605615759953	Marionette	DEBUG	Resetting recommended pref security.fileuri.strict_origin_policy[task 2020-11-17T12:22:39.962Z] 12:22:39     INFO - PID 1252 | 1605615759954	Marionette	DEBUG	Resetting recommended pref security.notification_enable_delay
[task 2020-11-17T12:22:39.962Z] 12:22:39     INFO - PID 1252 | 1605615759954	Marionette	DEBUG	Resetting recommended pref signon.autofillForms
[task 2020-11-17T12:22:39.962Z] 12:22:39     INFO - PID 1252 | 1605615759956	Marionette	DEBUG	Resetting recommended pref signon.rememberSignons
[task 2020-11-17T12:22:39.964Z] 12:22:39     INFO - PID 1252 | 1605615759959	Marionette	DEBUG	Marionette stopped listening
[task 2020-11-17T12:22:39.964Z] 12:22:39     INFO - PID 1252 | DEBUG: Starting phase xpcom-will-shutdown
[task 2020-11-17T12:22:39.964Z] 12:22:39     INFO - PID 1252 | DEBUG: Spinning the event loop
[task 2020-11-17T12:22:40.053Z] 12:22:40     INFO - PID 1252 | DEBUG: Completed blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2020-11-17T12:22:40.078Z] 12:22:40     INFO - PID 1252 | DEBUG: Finished phase xpcom-will-shutdown
[task 2020-11-17T12:22:40.083Z] 12:22:40     INFO - PID 1252 | 
[task 2020-11-17T12:22:40.088Z] 12:22:40     INFO - PID 1252 | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-11-17T12:22:40.094Z] 12:22:40     INFO - PID 1252 | 
[task 2020-11-17T12:22:40.094Z] 12:22:40     INFO - PID 1252 | DEBUG: Starting phase web-workers-shutdown
[task 2020-11-17T12:22:40.094Z] 12:22:40     INFO - PID 1252 | DEBUG: Spinning the event loop
[task 2020-11-17T12:22:40.095Z] 12:22:40     INFO - PID 1252 | DEBUG: Finished phase web-workers-shutdown
[task 2020-11-17T12:22:40.278Z] 12:22:40     INFO - PID 1252 | 1605615760249	RemoteAgent	ERROR	unable to stop listener: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIWindowMediator.getEnumerator]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: chrome://remote/content/observers/TargetObserver.jsm :: stop :: line 59"  data: no] Stack trace: stop()@TargetObserver.jsm:59
[task 2020-11-17T12:22:40.278Z] 12:22:40     INFO - PID 1252 | unwatchForTabs()@TargetList.jsm:71
[task 2020-11-17T12:22:40.278Z] 12:22:40     INFO - PID 1252 | unwatchForTargets()@TargetList.jsm:38
[task 2020-11-17T12:22:40.279Z] 12:22:40     INFO - PID 1252 | destructor()@TargetList.jsm:110
[task 2020-11-17T12:22:40.279Z] 12:22:40     INFO - PID 1252 | close()@RemoteAgent.jsm:123
[task 2020-11-17T12:22:41.467Z] 12:22:41     INFO - TEST-UNEXPECTED-TIMEOUT | /_mozilla/webdriver/new_session/debugger_address.py | expected OK```
Component: General → geckodriver
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | mozilla/tests/webdriver/new_session/debugger_address.py | expected OK → Frequent windows10 TEST-UNEXPECTED-TIMEOUT | mozilla/tests/webdriver/new_session/debugger_address.py | expected OK

Note the following delay in startup:

[task 2020-11-17T12:21:51.576Z] 12:21:51     INFO - PID 1252 | DEBUG: Completed blocker Transaction (1) for phase content-prefs.sqlite#0: waiting for clients[task 2020-11-17T12:22:39.671Z] 12:22:39     INFO - PID 1252 | DEBUG: Starting phase profile-before-change-telemetry
[task 2020-11-17T12:22:39.671Z] 12:22:39     INFO - PID 1252 | DEBUG: Spinning the event loop
..
[task 2020-11-17T12:22:39.944Z] 12:22:39     INFO - PID 1252 | DEBUG: Completed blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2020-11-17T12:22:39.945Z] 12:22:39     INFO - PID 1252 | DEBUG: Finished phase profile-before-change-telemetry
[task 2020-11-17T12:22:39.946Z] 12:22:39     INFO - PID 1252 | 1605615759939	Marionette	TRACE	Received observer notification xpcom-will-shutdown

We are spending 48s after Starting phase profile-before-change-telemetry and before Spinning the event loop. And then Firefox just shutdown.

This failure can be seen since the test has been added via bug 1669218. I will try to run that job a couple of times with Pernosco enabled. Maybe we can figure out what's happening here. Also note this is only happening for opt/ccov builds. As such Marco might be interested in.

I will do a try push once the branch is open again.

Blocks: 1669746
Regressed by: 1669218
Summary: Frequent windows10 TEST-UNEXPECTED-TIMEOUT | mozilla/tests/webdriver/new_session/debugger_address.py | expected OK → Frequent windows10 ccov TEST-UNEXPECTED-TIMEOUT | mozilla/tests/webdriver/new_session/debugger_address.py | expected OK
Summary: Frequent windows10 ccov TEST-UNEXPECTED-TIMEOUT | mozilla/tests/webdriver/new_session/debugger_address.py | expected OK → Frequent windows10 ccov TEST-UNEXPECTED-TIMEOUT | /_mozilla/webdriver/new_session/debugger_address.py | expected OK

I always forget that Pernosco only works on Linux. Marco, I assume we should mark this test as flaky for ccov builds? It's not clear to me why it's hanging given that we use the same command line arguments also for all the other tests. Do you know of a similar issue while running other tests?

Flags: needinfo?(mcastelluccio)

Is there any chance this test causes Firefox to be restarted multiple times? That could be one reason why it takes so long (the ccov builds are super slow at shutdown, as they need to output the coverage counters in a lot of files).

Flags: needinfo?(mcastelluccio)

Yes, each test in this file has to restart Firefox. Each of the Firefox sessions is very-short lived. So I assume that we should just skip them for ccov?

Flags: needinfo?(mcastelluccio)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #6)

Yes, each test in this file has to restart Firefox. Each of the Firefox sessions is very-short lived. So I assume that we should just skip them for ccov?

I think that's the best course of action. This test is bound to be super slow under ccov.

Flags: needinfo?(mcastelluccio)

Ok, so given that this only happens for ccov builds on Windows, lets only disable the tests there.

OS: Unspecified → Windows
Hardware: Unspecified → All
Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Pushed by hskupin@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ff2a53ac9e8b [wdspec] Disable debugger_address.py for code coverage builds on Windows. r=webdriver-reviewers,marco,jgraham
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → 85 Branch

The patch landed in nightly and beta is affected.
:whimboo, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(hskupin)
Flags: needinfo?(hskupin)

This bug should not have been closed because the patch just disabled the test but didn't fix it. As it looks like I'm not allowed to reopen this bug.

Ryan, do you have a way to reopen?

Flags: needinfo?(ryanvm)

I don't. Very odd.

Flags: needinfo?(ryanvm)

I talked with dkl and it's a expected behavior right now for any kind of user. I filed bug 1790825 to allow reopening of old bugs by users with at least edit permissions. Will reopen once that bug is fixed.

Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol

Glob or dkl could one of you please reopen the bug? I would prefer that compared to cloning because web-platform-tests have metadata that include this bug as reference. Thanks.

Flags: needinfo?(glob)
Flags: needinfo?(dkl)

It isn't possible to reopen bugs that were closed so long ago, even for admins.
You'll have to file a new bug.

Flags: needinfo?(glob)
Flags: needinfo?(dkl)

Ok, thanks. Then there is bug 1849672 now.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: