Closed Bug 1839989 Opened 3 years ago Closed 2 years ago

Intermittent Android WD expected OK after Connection to Marionette established on 127.0.0.1

Tracking

(Not tracked)

Status:

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Treeherder Bug Filer

Reporter

Description

•

3 years ago

treeherder

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

[task 2023-06-22T22:36:06.244Z] 22:36:06     INFO - PID 3067 | 1687473366243	geckodriver::android	DEBUG	Content of generated GeckoView config file:
[task 2023-06-22T22:36:06.244Z] 22:36:06     INFO - PID 3067 | ## GeckoView configuration YAML
[task 2023-06-22T22:36:06.245Z] 22:36:06     INFO - PID 3067 | ##
[task 2023-06-22T22:36:06.245Z] 22:36:06     INFO - PID 3067 | ## Auto-generated by geckodriver.
[task 2023-06-22T22:36:06.245Z] 22:36:06     INFO - PID 3067 | ## See https ... "--profile"
[task 2023-06-22T22:36:06.245Z] 22:36:06     INFO - PID 3067 |   - /tmp/tmpnau98c0z.mozrunner
[task 2023-06-22T22:36:06.245Z] 22:36:06     INFO - PID 3067 |   - "--remote-debugging-port"
[task 2023-06-22T22:36:06.246Z] 22:36:06     INFO - PID 3067 |   - "9222"
[task 2023-06-22T22:36:06.246Z] 22:36:06     INFO - PID 3067 |   - "--remote-allow-hosts"
[task 2023-06-22T22:36:06.246Z] 22:36:06     INFO - PID 3067 |   - localhost
[task 2023-06-22T22:36:06.246Z] 22:36:06     INFO - PID 3067 | 1687473366243	geckodriver::android	DEBUG	Pushing GeckoView configuration file to /data/local/tmp/org.mozilla.geckoview.test_runner-geckoview-config.yaml
[task 2023-06-22T22:36:06.247Z] 22:36:06     INFO - PID 3067 | 1687473366243	mozdevice	TRACE	execute_host_command: >> "host:transport:emulator-5554"
[task 2023-06-22T22:36:06.247Z] 22:36:06     INFO - PID 3067 | 1687473366243	mozdevice	TRACE	execute_host_command: << []
[task 2023-06-22T22:36:06.247Z] 22:36:06     INFO - PID 3067 | 1687473366243	mozdevice	TRACE	execute_host_command: >> "shell:ls /data/local/tmp"
[task 2023-06-22T22:36:06.252Z] 22:36:06     INFO - PID 3067 | 1687473366251	mozdevice	TRACE	execute_host_command: << "test_root\n"
[task 2023-06-22T22:36:06.292Z] 22:36:06     INFO - PID 3067 | 1687473366291	mozdevice	TRACE	execute_host_command: >> "host:transport:emulator-5554"
[task 2023-06-22T22:36:06.292Z] 22:36:06     INFO - PID 3067 | 1687473366291	mozdevice	TRACE	execute_host_command: << []
[task 2023-06-22T22:36:06.292Z] 22:36:06     INFO - PID 3067 | 1687473366291	mozdevice	TRACE	execute_host_command: >> "shell:am set-debug-app --persistent org.mozilla.geckoview.test_runner"
[task 2023-06-22T22:36:06.468Z] 22:36:06     INFO - PID 3067 | 1687473366467	mozdevice	TRACE	execute_host_command: << ""
[task 2023-06-22T22:36:06.468Z] 22:36:06     INFO - PID 3067 | 1687473366467	geckodriver::android	DEBUG	Launching org.mozilla.geckoview.test_runner/.App
[task 2023-06-22T22:36:06.469Z] 22:36:06     INFO - PID 3067 | 1687473366468	mozdevice	TRACE	execute_host_command: >> "host:transport:emulator-5554"
[task 2023-06-22T22:36:06.469Z] 22:36:06     INFO - PID 3067 | 1687473366468	mozdevice	TRACE	execute_host_command: << []
[task 2023-06-22T22:36:06.469Z] 22:36:06     INFO - PID 3067 | 1687473366468	mozdevice	TRACE	execute_host_command: >> "shell:am start -W -n org.mozilla.geckoview.test_runner/.App -a android.intent.action.VIEW -d about: ... dcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile\""
[task 2023-06-22T22:36:07.424Z] 22:36:07     INFO - PID 3067 | 1687473367423	mozdevice	TRACE	execute_host_command: << "Starting: Intent { act=android.intent.action.VIEW dat=about:blank cmp=org.mozilla.geckoview.test_ru ... s) }\nStatus: ok\nActivity: org.mozilla.geckoview.test_runner/.App\nThisTime: 752\nTotalTime: 752\nWaitTime: 760\nComplete\n"
[task 2023-06-22T22:36:07.424Z] 22:36:07     INFO - PID 3067 | 1687473367423	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2023-06-22T22:36:07.424Z] 22:36:07     INFO - PID 3067 | 1687473367424	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-06-22T22:36:07.692Z] 22:36:07     INFO - PID 3067 | 1687473367691	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:45179.
[task 2023-06-22T22:36:08.531Z] 22:36:08     INFO - PID 3067 | 1687473368530	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"05abc05a-0a6e-4983-82a1-3d0f22636e9e","capabilities":{"acceptInsecureCerts":false,"browserNa ... dledPromptBehavior":"dismiss and notify","webSocketUrl":"ws://127.0.0.1:9222/session/05abc05a-0a6e-4983-82a1-3d0f22636e9e"}}}
[task 2023-06-22T22:37:25.053Z] 22:37:25     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/script/remove_preload_script/remove_preload_script.py | expected OK
[task 2023-06-22T22:37:25.053Z] 22:37:25     INFO - TEST-INFO took 80003ms

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

Comment 1

•

3 years ago

This happens while creating a new tab in GeckoView. Here an excerpt from the adb log:

06-22 22:36:08.105 23143 23158 I Gecko   : 1687473368105	RemoteAgent	DEBUG	WebDriverBiDiConnection ef67afb8-1157-4bcf-9a5e-ed758e1913ca -> {"id":5,"method":"browsingContext.create","params":{"type":"tab"}}
[...]
06-22 22:36:08.249 23143 23158 D GeckoViewModule: registerListener ["GeckoView:WebExtension:SetTabActive"]
06-22 22:36:08.252 23143 23158 I GeckoSession: zerdatime 499540 - chrome startup finished
06-22 22:36:08.253 23143 23158 I Gecko   : 1687473368253	RemoteAgent	TRACE	Received DOM event load for [object HTMLDocument]
06-22 22:36:08.253 23171 23187 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
06-22 22:36:08.254 23143 23158 I Gecko   : nsWindow[0x781dc0196400]::Show 1
06-22 22:36:08.254 23171 23187 D GeckoViewClipboardPermissionChild[C]: handleEvent: deactivate
06-22 22:36:08.259 23293 23308 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
06-22 22:36:08.260 23143 23158 I Gecko   : nsWindow[0x781dc0196400]::Resize [0.000000 0.000000 800.000000 1136.000000] (repaint 0)
06-22 22:36:08.260 23143 23158 I Gecko   : nsWindow: 0x781dc0196400 OnSizeChanged [800 1136]
06-22 22:36:08.261 23293 23308 D GeckoViewClipboardPermissionChild[C]: handleEvent: deactivate
06-22 22:36:08.262 23171 23187 D GeckoViewSettings[C]: receiveMessage: SettingsUpdate
06-22 22:36:08.268 23143 23158 I Gecko   : nsWindow[0x781dc0196400]::Resize [0.000000 0.000000 800.000000 1136.000000] (repaint 0)
06-22 22:36:08.272 23171 23187 W GeckoEditableChild: No editable parent
06-22 22:36:08.277 23143 23158 D GeckoViewModule: dispatch GeckoView:WebExtension:SetTabActive, data={"active":true}
06-22 22:36:08.277 23143 23158 D GeckoViewTab: onEvent: event=GeckoView:WebExtension:SetTabActive, data={"active":true}
06-22 22:36:08.281 23143 23158 D GeckoViewClipboardPermissionParent: receiveMessage: DispatcherMessage
06-22 22:36:08.282 23143 23158 W GeckoEventDispatcher: No listener for GeckoView:DismissClipboardPermissionRequest
06-22 22:36:08.283 23208 23243 D EGL_emulation: eglMakeCurrent: 0x781dec235a00: ver 3 0 (tinfo 0x781dec20c660)
06-22 22:36:08.283 23143 23158 D GeckoViewClipboardPermissionParent: receiveMessage: DispatcherMessage
06-22 22:36:08.283 23143 23158 W GeckoEventDispatcher: No listener for GeckoView:DismissClipboardPermissionRequest
06-22 22:36:08.284 23208 23243 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
06-22 22:36:08.285 23143 23158 D GeckoViewXUL: receiveMessage GeckoView:ContentModuleLoaded {"module":"SessionStateAggregator"}
06-22 22:36:08.310 23208 23243 D EGL_emulation: eglMakeCurrent: 0x781dec235a00: ver 3 0 (tinfo 0x781dec20c660)
06-22 22:36:08.311 23208 23243 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
06-22 22:36:08.353 23208 23243 W webrender::device::gl: Cropping texture upload Box2D((0, 0), (0, 1)) to None
06-22 22:36:08.354 23208 23243 W webrender::device::gl: Cropping texture upload Box2D((0, 0), (0, 1)) to None
06-22 22:36:08.359 23208 23243 W webrender::device::gl: Cropping texture upload Box2D((0, 0), (0, 1)) to None
06-22 22:36:08.378 23143 23158 I Gecko   : 1687473368378	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
06-22 22:36:08.685  1658  1732 E TaskPersister: File error accessing recents directory (directory doesn't exist?).
06-22 22:36:08.994 23143 23158 W GeckoEventDispatcher: No listener for GeckoView:StateUpdated
06-22 22:36:09.299 23143 23158 W GeckoEventDispatcher: No listener for GeckoView:StateUpdated
06-22 22:36:11.841 23143 23338 D ProfileInstaller: Installing profile for org.mozilla.geckoview.test_runner
06-22 22:36:12.544 23143 23158 D GeckoIdleService: Get idle time: time since reset 5011 msec
06-22 22:36:12.544 23143 23158 D GeckoIdleService: Idle timer callback: current idle time 5011 msec
06-22 22:36:12.544 23143 23158 D GeckoIdleService: next timeout 4294967289988 msec from now
06-22 22:36:12.544 23143 23158 D GeckoIdleService: SetTimerExpiryIfBefore: next timeout 4294967289988 msec from now
06-22 22:36:12.544 23143 23158 D GeckoIdleService: reset timer expiry to 4294967289998 msec from now
06-22 22:36:12.544 23143 23158 D GeckoIdleService: Idle timer callback: tell observer 0x781dc0315468 user is idle
06-22 22:36:36.765 23143 23201 W rkv::backend::impl_safe::environment: `load_ratio()` is irrelevant for this storage backend.
06-22 22:36:36.791 23143 23158 I Gecko   : console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
06-22 22:36:36.793 23143 23158 E GeckoConsole: [JavaScript Error: "Error: Polling for changes failed: Unexpected content-type "text/plain;charset=US-ASCII"."]
06-22 22:36:40.323 23143 23158 D GeckoIdleService: Get idle time: time since reset 32790 msec
06-22 22:37:24.117 23143 23158 I Gecko   : 1687473444117	WebDriver BiDi	DEBUG	Unregistered session handler: /session/05abc05a-0a6e-4983-82a1-3d0f22636e9e

Then we never seem to return from this call maybe due to the tab not loading correctly. I do not see any page load activity for more than a minute. Lets observe if this is happening again.

Comment hidden (Intermittent Failures Robot)

BugBot [:suhaib / :marco/ :calixte]

Comment 3

•

2 years ago

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: NEW → RESOLVED

Closed: 2 years ago

Resolution: --- → INCOMPLETE

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

Bugzilla

Intermittent Android WD expected OK after Connection to Marionette established on 127.0.0.1

Categories

(Remote Protocol :: WebDriver BiDi, defect, P5)

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3