Closed Bug 1866267 Opened 1 year ago Closed 1 year ago

Perma Linux WD2 Automation Error: mozharness timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-', '--log-wptreport=/builds/worker/work

Categories

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

Product:
Remote Protocol
Component:
WebDriver BiDi
Type:
defect
Points:
1

Tracking

(firefox-esr115 unaffected, firefox120 unaffected, firefox121 unaffected, firefox122 fixed)

Status:
RESOLVED FIXED
Milestone:
122 Branch
Tracking Flags:
Tracking Status
firefox-esr115 --- unaffected
firefox120 --- unaffected
firefox121 --- unaffected
firefox122 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, intermittent-testcase, regression, Whiteboard: [webdriver:m9])

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

[task 2023-11-22T22:38:53.150Z] 22:38:53     INFO - PID 12117 | 1700692733149	RemoteAgent	TRACE	Module windowglobal-in-root/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:53.153Z] 22:38:53     INFO - PID 12117 | 1700692733153	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:53.154Z] 22:38:53     INFO - PID 12117 | 1700692733154	RemoteAgent	TRACE	Module windowglobal-in-root/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:53.213Z] 22:38:53     INFO - PID 12117 | 1700692733212	RemoteAgent	TRACE	Module windowglobal-in-root/realm-created.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:53.215Z] 22:38:53     INFO - PID 12117 | 1700692733213	RemoteAgent	TRACE	Module windowglobal-in-root/window-global-handler-created.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:53.217Z] 22:38:53     INFO - PID 12117 | 1700692733216	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session 79fbbb30-708c-46d4-a4d3-7ccddab5882a
[task 2023-11-22T22:38:53.219Z] 22:38:53     INFO - PID 12117 | 1700692733217	RemoteAgent	TRACE	Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2023-11-22T22:38:53.233Z] 22:38:53     INFO - PID 12117 | 1700692733232	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:53.234Z] 22:38:53     INFO - PID 12117 | 1700692733233	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:53.244Z] 22:38:53     INFO - PID 12117 | 1700692733243	RemoteAgent	TRACE	[3] ProgressListener Start: expectNavigation=true resolveWhenStarted=false unloadTimeout=1600 waitForExplicitStart=true
[task 2023-11-22T22:38:53.245Z] 22:38:53     INFO - PID 12117 | 1700692733244	RemoteAgent	TRACE	[3] ProgressListener Skip setting the unload timer
[task 2023-11-22T22:38:53.264Z] 22:38:53     INFO - PID 12117 | 1700692733263	RemoteAgent	TRACE	[3] ProgressListener Check loading state: isStart=1 isStop=0
[task 2023-11-22T22:38:53.265Z] 22:38:53     INFO - PID 12117 | 1700692733264	RemoteAgent	TRACE	[3] ProgressListener state=start: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html
[task 2023-11-22T22:38:53.405Z] 22:38:53     INFO - PID 12117 | 1700692733404	RemoteAgent	TRACE	[04b479cb-8941-4bd6-aac4-ed2baf0e9074] Navigation started for url: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html (a687a10a-7bda-462d-a371-81f0dd7a5c75)
[task 2023-11-22T22:38:53.445Z] 22:38:53     INFO - PID 12117 | 1700692733444	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session 79fbbb30-708c-46d4-a4d3-7ccddab5882a is being destroyed
[task 2023-11-22T22:38:53.448Z] 22:38:53     INFO - PID 12117 | 1700692733447	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session 79fbbb30-708c-46d4-a4d3-7ccddab5882a
[task 2023-11-22T22:38:53.469Z] 22:38:53     INFO - PID 12117 | 1700692733468	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 11
[task 2023-11-22T22:38:53.555Z] 22:38:53     INFO - PID 12117 | 1700692733554	RemoteAgent	TRACE	Module windowglobal/network.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:53.558Z] 22:38:53     INFO - PID 12117 | 1700692733556	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session 79fbbb30-708c-46d4-a4d3-7ccddab5882a
[task 2023-11-22T22:38:54.281Z] 22:38:54     INFO - PID 12117 | 1700692734280	RemoteAgent	TRACE	[11] NavigationListener onStateChange, stateFlags: 983041, status: 0, isStart: true, isStop: false, isNetwork: true, isBindingAborted: false, targetURI: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html
[task 2023-11-22T22:38:54.347Z] 22:38:54     INFO - PID 12117 | 1700692734346	RemoteAgent	TRACE	Module windowglobal-in-root/windowglobal-pagehide.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:54.388Z] 22:38:54     INFO - PID 12117 | 1700692734387	RemoteAgent	TRACE	[04b479cb-8941-4bd6-aac4-ed2baf0e9074] Skipping already tracked navigation, navigationId: a687a10a-7bda-462d-a371-81f0dd7a5c75
[task 2023-11-22T22:38:54.431Z] 22:38:54     INFO - PID 12117 | 1700692734429	RemoteAgent	TRACE	Module windowglobal/network.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:54.435Z] 22:38:54     INFO - PID 12117 | 1700692734433	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session 79fbbb30-708c-46d4-a4d3-7ccddab5882a
[task 2023-11-22T22:38:54.579Z] 22:38:54     INFO - PID 12117 | 1700692734577	RemoteAgent	TRACE	[11] NavigationListener onStateChange, stateFlags: 196612, status: 0, isStart: false, isStop: false, isNetwork: false, isBindingAborted: false, targetURI: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html
[task 2023-11-22T22:38:54.582Z] 22:38:54     INFO - PID 12117 | 1700692734578	RemoteAgent	TRACE	[11] NavigationListener onStateChange, stateFlags: 196612, status: 0, isStart: false, isStop: false, isNetwork: false, isBindingAborted: false, targetURI: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html
[task 2023-11-22T22:38:54.627Z] 22:38:54     INFO - PID 12117 | 1700692734626	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session 79fbbb30-708c-46d4-a4d3-7ccddab5882a is being destroyed
[task 2023-11-22T22:38:54.629Z] 22:38:54     INFO - PID 12117 | 1700692734627	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session 79fbbb30-708c-46d4-a4d3-7ccddab5882a
[task 2023-11-22T22:38:54.721Z] 22:38:54     INFO - PID 12117 | 1700692734715	RemoteAgent	TRACE	[11] NavigationListener onStateChange, stateFlags: 131088, status: 0, isStart: false, isStop: true, isNetwork: false, isBindingAborted: false, targetURI: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html
[task 2023-11-22T22:38:54.802Z] 22:38:54     INFO - PID 12117 | 1700692734800	RemoteAgent	TRACE	[04b479cb-8941-4bd6-aac4-ed2baf0e9074] Navigation finished for url: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html (a687a10a-7bda-462d-a371-81f0dd7a5c75)
[task 2023-11-22T22:38:54.807Z] 22:38:54     INFO - PID 12117 | 1700692734805	RemoteAgent	TRACE	[11] ProgressListener Check loading state: isStart=0 isStop=16
[task 2023-11-22T22:38:54.808Z] 22:38:54     INFO - PID 12117 | 1700692734805	RemoteAgent	TRACE	[11] ProgressListener state=stop: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html
[task 2023-11-22T22:38:54.809Z] 22:38:54     INFO - PID 12117 | 1700692734805	RemoteAgent	TRACE	[11] ProgressListener Stop: has error=false
[task 2023-11-22T22:38:54.809Z] 22:38:54     INFO - PID 12117 | 1700692734808	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 <- {"type":"success","id":3,"result":{"navigation":"a687a10a-7bda-462d-a371-81f0dd7a5c75","url":"https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html"}}
[task 2023-11-22T22:38:54.836Z] 22:38:54     INFO - PID 12117 | 1700692734830	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 <- {"type":"event","method":"network.responseCompleted","params":{"context":"04b479cb-8941-4bd6-aac4-ed2baf0e9074","isBlocked":false,"navigation":"a687a10a-7bda-462d-a371-81f0dd7a5c75","redirectCount":0,"request":{"bodySize":null,"cookies":[],"headers":[{"name":"Host","value":{"type":"string","value":"web-platform.test:8443"}},{"name":"User-Agent","value":{"type":"string","value":"Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0"}},{"name":"Accept","value":{"type":"string","value":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"}},{"name":"Accept-Language","value":{"type":"string","value":"en-US,en;q=0.5"}},{"name":"Accept-Encoding","value":{"type":"string","value":"gzip, deflate, br"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Upgrade-Insecure-Requests","value":{"type":"string","value":"1"}},{"name":"Sec-Fetch-Dest","value":{"type":"string","value":"document"}},{"name":"Sec-Fetch-Mode","value":{"type":"string","value":"navigate"}},{"name":"Sec-Fetch-Site","value":{"type":"string","value":"none"}},{"name":"Sec-Fetch-User","value":{"type":"string","value":"?1"}}],"headersSize":491,"method":"GET","request":"4","timings":{"timeOrigin":0,"requestTime":1700692733246749,"redirectStart":0,"redirectEnd":0,"fetchStart":1700692733310738,"dnsStart":1700692733310738,"dnsEnd":1700692733327791,"connectStart":1700692733330178,"connectEnd":1700692733372535,"tlsStart":1700692733331339,"tlsEnd":1700692733372535,"requestStart":1700692733372980,"responseStart":1700692733373175,"responseEnd":1700692733376079},"url":"https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html"},"timestamp":1700692734822,"response":{"bodySize":30,"content":{"size":30},"headersSize":116,"url":"https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html","bytesReceived":146,"fromCache":false,"headers":[{"name":"Content-Type","value":{"type":"string","value":"text/html"}},{"name":"Server","value":{"type":"string","value":"BaseHTTP/0.6 Python/3.7.5"}},{"name":"Date","value":{"type":"string","value":"Wed, 22 Nov 2023 22:38:53 GMT"}}],"mimeType":"text/html","protocol":"http/1.1","status":200,"statusText":"OK"}}}
[task 2023-11-22T22:38:54.869Z] 22:38:54     INFO - PID 12117 | 1700692734864	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 -> {"id":4,"method":"session.unsubscribe","params":{"events":["network.responseCompleted"],"contexts":["04b479cb-8941-4bd6-aac4-ed2baf0e9074"]}}
[task 2023-11-22T22:38:54.870Z] 22:38:54     INFO - PID 12117 | 1700692734865	RemoteAgent	TRACE	Module root/session.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.872Z] 22:38:54     INFO - PID 12117 | 1700692734865	RemoteAgent	TRACE	Received command session.unsubscribe for destination ROOT
[task 2023-11-22T22:38:54.873Z] 22:38:54     INFO - PID 12117 | 1700692734865	RemoteAgent	TRACE	Module root/session.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.874Z] 22:38:54     INFO - PID 12117 | 1700692734866	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.880Z] 22:38:54     INFO - PID 12117 | 1700692734877	RemoteAgent	TRACE	Module windowglobal-in-root/network.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:54.880Z] 22:38:54     INFO - PID 12117 | 1700692734878	RemoteAgent	TRACE	Module windowglobal/network.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:54.881Z] 22:38:54     INFO - PID 12117 | 1700692734878	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.882Z] 22:38:54     INFO - PID 12117 | 1700692734878	RemoteAgent	TRACE	Received command network._applySessionData for destination ROOT
[task 2023-11-22T22:38:54.883Z] 22:38:54     INFO - PID 12117 | 1700692734878	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.884Z] 22:38:54     INFO - PID 12117 | 1700692734881	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 <- {"type":"success","id":4,"result":{}}
[task 2023-11-22T22:38:54.905Z] 22:38:54     INFO - PID 12117 | 1700692734904	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 -> {"id":5,"method":"session.subscribe","params":{"events":["network.beforeRequestSent","network.responseStarted","network.responseCompleted"]}}
[task 2023-11-22T22:38:54.907Z] 22:38:54     INFO - PID 12117 | 1700692734905	RemoteAgent	TRACE	Module root/session.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.908Z] 22:38:54     INFO - PID 12117 | 1700692734905	RemoteAgent	TRACE	Received command session.subscribe for destination ROOT
[task 2023-11-22T22:38:54.908Z] 22:38:54     INFO - PID 12117 | 1700692734905	RemoteAgent	TRACE	Module root/session.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.909Z] 22:38:54     INFO - PID 12117 | 1700692734906	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.910Z] 22:38:54     INFO - PID 12117 | 1700692734907	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.911Z] 22:38:54     INFO - PID 12117 | 1700692734907	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.919Z] 22:38:54     INFO - PID 12117 | 1700692734918	RemoteAgent	TRACE	Module windowglobal-in-root/network.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:54.920Z] 22:38:54     INFO - PID 12117 | 1700692734918	RemoteAgent	TRACE	Module windowglobal/network.sys.mjs not found for WINDOW_GLOBAL
[task 2023-11-22T22:38:54.921Z] 22:38:54     INFO - PID 12117 | 1700692734919	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.922Z] 22:38:54     INFO - PID 12117 | 1700692734919	RemoteAgent	TRACE	Received command network._applySessionData for destination ROOT
[task 2023-11-22T22:38:54.922Z] 22:38:54     INFO - PID 12117 | 1700692734919	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:54.925Z] 22:38:54     INFO - PID 12117 | 1700692734923	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 <- {"type":"success","id":5,"result":{}}
[task 2023-11-22T22:38:55.140Z] 22:38:55     INFO - PID 12117 | 1700692735137	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 -> {"id":6,"method":"network.addIntercept","params":{"phases":["beforeRequestSent"],"urlPatterns":[{"type":"string","pattern":"https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.txt"}]}}
[task 2023-11-22T22:38:55.141Z] 22:38:55     INFO - PID 12117 | 1700692735138	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.143Z] 22:38:55     INFO - PID 12117 | 1700692735138	RemoteAgent	TRACE	Received command network.addIntercept for destination ROOT
[task 2023-11-22T22:38:55.144Z] 22:38:55     INFO - PID 12117 | 1700692735138	RemoteAgent	TRACE	Module root/network.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.155Z] 22:38:55     INFO - PID 12117 | 1700692735153	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 <- {"type":"success","id":6,"result":{"intercept":"be1797a3-fecb-40b9-9c11-fd7bcfcb09eb"}}
[task 2023-11-22T22:38:55.222Z] 22:38:55     INFO - PID 12117 | 1700692735220	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 -> {"id":7,"method":"session.subscribe","params":{"events":["browsingContext.load"],"contexts":["04b479cb-8941-4bd6-aac4-ed2baf0e9074"]}}
[task 2023-11-22T22:38:55.223Z] 22:38:55     INFO - PID 12117 | 1700692735221	RemoteAgent	TRACE	Module root/session.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.223Z] 22:38:55     INFO - PID 12117 | 1700692735221	RemoteAgent	TRACE	Received command session.subscribe for destination ROOT
[task 2023-11-22T22:38:55.224Z] 22:38:55     INFO - PID 12117 | 1700692735221	RemoteAgent	TRACE	Module root/session.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.225Z] 22:38:55     INFO - PID 12117 | 1700692735222	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.234Z] 22:38:55     INFO - PID 12117 | 1700692735233	RemoteAgent	TRACE	Module windowglobal-in-root/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.235Z] 22:38:55     INFO - PID 12117 | 1700692735233	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.236Z] 22:38:55     INFO - PID 12117 | 1700692735233	RemoteAgent	TRACE	Received command browsingContext._applySessionData for destination WINDOW_GLOBAL
[task 2023-11-22T22:38:55.237Z] 22:38:55     INFO - PID 12117 | 1700692735233	RemoteAgent	TRACE	Module windowglobal-in-root/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.237Z] 22:38:55     INFO - PID 12117 | 1700692735233	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.239Z] 22:38:55     INFO - PID 12117 | 1700692735238	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.242Z] 22:38:55     INFO - PID 12117 | 1700692735238	RemoteAgent	TRACE	Received command browsingContext._applySessionData for destination ROOT
[task 2023-11-22T22:38:55.242Z] 22:38:55     INFO - PID 12117 | 1700692735238	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.244Z] 22:38:55     INFO - PID 12117 | 1700692735239	RemoteAgent	TRACE	Received command browsingContext._applySessionData for destination WINDOW_GLOBAL
[task 2023-11-22T22:38:55.260Z] 22:38:55     INFO - PID 12117 | 1700692735259	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.261Z] 22:38:55     INFO - PID 12117 | 1700692735259	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.276Z] 22:38:55     INFO - PID 12117 | 1700692735275	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 <- {"type":"success","id":7,"result":{}}
[task 2023-11-22T22:38:55.327Z] 22:38:55     INFO - PID 12117 | 1700692735325	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 -> {"id":8,"method":"browsingContext.navigate","params":{"context":"04b479cb-8941-4bd6-aac4-ed2baf0e9074","url":"https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.txt","wait":"complete"}}
[task 2023-11-22T22:38:55.329Z] 22:38:55     INFO - PID 12117 | 1700692735326	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.329Z] 22:38:55     INFO - PID 12117 | 1700692735326	RemoteAgent	TRACE	Received command browsingContext.navigate for destination ROOT
[task 2023-11-22T22:38:55.329Z] 22:38:55     INFO - PID 12117 | 1700692735326	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
[task 2023-11-22T22:38:55.330Z] 22:38:55     INFO - PID 12117 | 1700692735327	RemoteAgent	TRACE	Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2023-11-22T22:38:55.331Z] 22:38:55     INFO - PID 12117 | 1700692735327	RemoteAgent	TRACE	Module windowglobal-in-root/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.331Z] 22:38:55     INFO - PID 12117 | 1700692735327	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.332Z] 22:38:55     INFO - PID 12117 | 1700692735330	RemoteAgent	TRACE	Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2023-11-22T22:38:55.332Z] 22:38:55     INFO - PID 12117 | 1700692735330	RemoteAgent	TRACE	Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-11-22T22:38:55.348Z] 22:38:55     INFO - PID 12117 | 1700692735347	RemoteAgent	TRACE	[11] ProgressListener Start: expectNavigation=true resolveWhenStarted=false unloadTimeout=1600 waitForExplicitStart=true
[task 2023-11-22T22:38:55.349Z] 22:38:55     INFO - PID 12117 | 1700692735347	RemoteAgent	TRACE	[11] ProgressListener Skip setting the unload timer
[task 2023-11-22T22:38:55.363Z] 22:38:55     INFO - PID 12117 | 1700692735363	RemoteAgent	TRACE	[11] ProgressListener Check loading state: isStart=1 isStop=0
[task 2023-11-22T22:38:55.364Z] 22:38:55     INFO - PID 12117 | 1700692735363	RemoteAgent	TRACE	[11] ProgressListener state=start: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.txt
[task 2023-11-22T22:38:55.380Z] 22:38:55     INFO - PID 12117 | 1700692735379	RemoteAgent	TRACE	[04b479cb-8941-4bd6-aac4-ed2baf0e9074] Navigation started for url: https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.txt (e94b397f-992b-468f-8d92-f6e6a77e2c53)
[task 2023-11-22T22:38:55.389Z] 22:38:55     INFO - PID 12117 | 1700692735385	RemoteAgent	DEBUG	WebDriverBiDiConnection 8664d67a-c994-4d17-8bbf-fa85e87bf431 <- {"type":"event","method":"network.beforeRequestSent","params":{"context":"04b479cb-8941-4bd6-aac4-ed2baf0e9074","isBlocked":true,"navigation":"e94b397f-992b-468f-8d92-f6e6a77e2c53","redirectCount":0,"request":{"bodySize":null,"cookies":[],"headers":[{"name":"Host","value":{"type":"string","value":"web-platform.test:8443"}},{"name":"User-Agent","value":{"type":"string","value":"Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0"}},{"name":"Accept","value":{"type":"string","value":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"}},{"name":"Accept-Language","value":{"type":"string","value":"en-US,en;q=0.5"}},{"name":"Accept-Encoding","value":{"type":"string","value":"gzip, deflate, br"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Upgrade-Insecure-Requests","value":{"type":"string","value":"1"}},{"name":"Sec-Fetch-Dest","value":{"type":"string","value":"document"}},{"name":"Sec-Fetch-Mode","value":{"type":"string","value":"navigate"}},{"name":"Sec-Fetch-Site","value":{"type":"string","value":"none"}},{"name":"Sec-Fetch-User","value":{"type":"string","value":"?1"}}],"headersSize":490,"method":"GET","request":"5","timings":{"timeOrigin":0,"requestTime":1700692735349221,"redirectStart":0,"redirectEnd":0,"fetchStart":1700692735374418,"dnsStart":1700692735374418,"dnsEnd":1700692735374748,"connectStart":1700692735376663,"connectEnd":1700692735377485,"tlsStart":1700692735377894,"tlsEnd":1700692735377485,"requestStart":0,"responseStart":0,"responseEnd":0},"url":"https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.txt"},"timestamp":1700692735378,"intercepts":["be1797a3-fecb-40b9-9c11-fd7bcfcb09eb"],"initiator":{"type":"other"}}}
[task 2023-11-22T22:55:35.390Z] 22:55:35     INFO - Automation Error: mozharness timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-', '--log-wptreport=/builds/worker/workspace/build/blobber_upload_dir/wptreport.json', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/wpt_errorsummary.log', '--symbols-path=None', '--stackwalk-binary=/builds/worker/fetches/minidump-stackwalk/minidump-stackwalk', '--stackfix-dir=/builds/worker/workspace/build/tests/bin', '--no-pause-after-test', '--instrument-to-file=/builds/worker/workspace/build/blobber_upload_dir/wpt_instruments.txt', '--specialpowers-path=/builds/worker/workspace/build/tests/extensions/specialpowers@mozilla.org.xpi', '--suppress-handler-traceback', '--processes=1', '--binary=/builds/worker/workspace/build/application/firefox/firefox', '--product=firefox', '--install-fonts', '--test-type=wdspec', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--setpref=javascript.options.mem.gc_parallel_marking=true', '--test-groups=/builds/worker/fetches/wpt_tests_by_group.json', '--webdriver-binary=/builds/worker/fetches/geckodriver', '--webdriver-arg=-vv', '--prefs-root=/builds/worker/workspace/build/tests/web-platform/prefs', '--config=/builds/worker/workspace/build/tests/web-platform/wptrunner.ini', '--ca-cert-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/cacert.pem', '--host-key-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/web-platform.test.key', '--host-cert-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/web-platform.test.pem', '--certutil-binary=/builds/worker/workspace/build/tests/bin/certutil', '/webdriver/tests/bidi/input/perform_actions', '/webdriver/tests/bidi/network/remove_intercept', '/webdriver/tests/bidi/session/unsubscribe', '/webdriver/tests/classic/find_element_from_shadow_root', '/webdriver/tests/classic/new_window', '/_mozilla/webdriver/classic/protocol', '/webdriver/tests/bidi/browsing_context/navigate', '/webdriver/tests/classic/set_window_rect', '/_mozilla/webdriver/bidi/browsing_context/set_viewport', '/webdriver/tests/classic/dismiss_alert', '/webdriver/tests/classic/get_computed_label', '/_mozilla/webdriver/cdp', '/webdriver/tests/classic/get_element_tag_name', '/webdriver/tests/bidi/script/get_realms', '/webdriver/tests/classic/get_window_rect', '/webdriver/tests/bidi/browsing_context/context_created']
[task 2023-11-22T22:55:35.394Z] 22:55:35     INFO - Return code: -9
[task 2023-11-22T22:55:35.395Z] 22:55:35    ERROR - No suite end message was emitted by this harness.
[task 2023-11-22T22:55:35.395Z] 22:55:35  WARNING - setting return code to 2
[task 2023-11-22T22:55:35.395Z] 22:55:35     INFO - Running post-action listener: _package_coverage_data
[task 2023-11-22T22:55:35.395Z] 22:55:35     INFO - Running post-action listener: _resource_record_post_action
[task 2023-11-22T22:55:35.395Z] 22:55:35     INFO - Running post-action listener: process_java_coverage_data
[task 2023-11-22T22:55:35.395Z] 22:55:35     INFO - Running post-action listener: stop_device
[task 2023-11-22T22:55:35.396Z] 22:55:35     INFO - [mozharness: 2023-11-22 22:55:35.395924Z] Finished run-tests step (success)
[task 2023-11-22T22:55:35.396Z] 22:55:35     INFO - Running post-run listener: _resource_record_post_run
[task 2023-11-22T22:55:36.256Z] 22:55:36     INFO - Total resource usage - Wall time: 1865s; CPU: 32%; Read bytes: 0; Write bytes: 3291549696; Read time: 0; Write time: 2839324
[task 2023-11-22T22:55:36.256Z] 22:55:36     INFO - TinderboxPrint: CPU usage<br/>31.9%
[task 2023-11-22T22:55:36.256Z] 22:55:36     INFO - TinderboxPrint: I/O read bytes / time<br/>0 / 0
[task 2023-11-22T22:55:36.256Z] 22:55:36     INFO - TinderboxPrint: I/O write bytes / time<br/>3,291,549,696 / 2,839,324
[task 2023-11-22T22:55:36.256Z] 22:55:36     INFO - TinderboxPrint: CPU idle<br/>5,005.1 (67.8%)
[task 2023-11-22T22:55:36.256Z] 22:55:36     INFO - TinderboxPrint: CPU system<br/>421.5 (5.7%)
[task 2023-11-22T22:55:36.256Z] 22:55:36     INFO - TinderboxPrint: CPU user<br/>1,948.4 (26.4%)
[task 2023-11-22T22:55:36.257Z] 22:55:36     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2023-11-22T22:55:36.260Z] 22:55:36     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-11-22T22:55:36.266Z] 22:55:36     INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-11-22T22:55:36.270Z] 22:55:36     INFO - verify-device - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-11-22T22:55:36.276Z] 22:55:36     INFO - install - Wall time: 39s; CPU: 26%; Read bytes: 0; Write bytes: 2221879296; Read time: 0; Write time: 1952576
[task 2023-11-22T22:55:36.407Z] 22:55:36     INFO - run-tests - Wall time: 1825s; CPU: 32%; Read bytes: 0; Write bytes: 1063378944; Read time: 0; Write time: 860592
[task 2023-11-22T22:55:40.588Z] 22:55:40  WARNING - returning nonzero exit status 2
[task 2023-11-22T22:55:40.758Z] cleanup
[task 2023-11-22T22:55:40.758Z] + cleanup
[task 2023-11-22T22:55:40.759Z] + local rv=2
[task 2023-11-22T22:55:40.759Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2023-11-22T22:55:40.759Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2023-11-22T22:55:40.760Z] + '[' ']'
[task 2023-11-22T22:55:40.760Z] + true
[task 2023-11-22T22:55:40.760Z] + cleanup_xvfb
[task 2023-11-22T22:55:40.761Z] ++ pidof Xvfb
[task 2023-11-22T22:55:40.773Z] + local xvfb_pid=52
[task 2023-11-22T22:55:40.773Z] + local vnc=false
[task 2023-11-22T22:55:40.773Z] + local interactive=false
[task 2023-11-22T22:55:40.773Z] + '[' -n 52 ']'
[task 2023-11-22T22:55:40.773Z] + [[ false == false ]]
[task 2023-11-22T22:55:40.773Z] + [[ false == false ]]
[task 2023-11-22T22:55:40.773Z] + kill 52
[task 2023-11-22T22:55:40.773Z] + screen -XS xvfb quit
[task 2023-11-22T22:55:40.778Z] XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
[task 2023-11-22T22:55:40.778Z]       after 9007 requests (9007 known processed) with 0 events remaining.
[task 2023-11-22T22:55:40.778Z] compizconfig - Info: Backend     : ini
[task 2023-11-22T22:55:40.778Z] compizconfig - Info: Integration : true
[task 2023-11-22T22:55:40.778Z] compizconfig - Info: Profile     : default
[task 2023-11-22T22:55:40.778Z] + exit 2
[taskcluster 2023-11-22 22:55:41.060Z] === Task Finished ===
[taskcluster 2023-11-22 22:55:42.822Z] Unsuccessful task run with exit code: 2 completed in 2132.035 seconds

Hello James! Could you please take a look at this? From the range of backfills and retriggers looks like this popped up after yesterday's merge. That merge also contained a wpt sync. Could this be related to that?

Thank you!

Flags: needinfo?(james)

This permafails on central but does not fail on autoland. Could it be pulling a wrong dependency?

Flags: needinfo?(hskupin)

The problematic test here is:
tests/web-platform/tests/webdriver/tests/bidi/network/remove_intercept/remove_intercept.py::test_remove_intercept[beforeRequestSent]:

https://searchfox.org/mozilla-central/rev/f030995a79461379153293c0e07f4982afe9ac28/testing/web-platform/tests/webdriver/tests/bidi/network/remove_intercept/remove_intercept.py#15-99

As it looks like we are waiting for some event but do actually not have a timeout set so that we wait around 17 minutes! I wonder why the wpt test timeout doesn't kick-in here and stop us after 2 minutes (25s and multiplier of 8).

I assume that the causing change here is from bug 1862012, but not sure what's going on.

Flags: needinfo?(hskupin)

There is actually also bug 1864467 which changed the page load from a simple fetch to browsingContext.load. Not sure if that makes a difference in the number of events that we emit.

Component: web-platform-tests → WebDriver BiDi
Product: Testing → Remote Protocol
Whiteboard: [webdriver:triage]
Whiteboard: [webdriver:triage]

FYI James will have a look why wptrunner doesn't trigger a test timeout but causes a hang of 17 minutes. For that we most likely will need a separate bug so that we can also fix the test hang.

This is actually a regression from bug 1864467, and I now think that we used fetch and not browsingContext.load on purpose. I'll have to dig more into that regression.

Btw. both Chrome and Edge fail as well for this test as I've commented on https://github.com/web-platform-tests/wpt/pull/43116#issuecomment-1830490662. But that means that it is also visible for opt builds and not such tsan and ccov.

I'll revert the changes for just this affected test so it uses fetch again.

Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Points: --- → 1
status-firefox120: --- → unaffected
status-firefox121: --- → unaffected
status-firefox122: --- → affected
status-firefox-esr115: --- → unaffected
Keywords: regression
Priority: P5 → P1
Regressed by: 1864467
Whiteboard: [webdriver:m9]

Btw the patch got accidentally added to bug 1864467, and landed via https://hg.mozilla.org/mozilla-central/rev/5b6f71a5f466.

The upstream PR to get this merged was: https://github.com/web-platform-tests/wpt/pull/43411

I'm going to leave the needinfo for James given that it would still be good to know why it didn't trigger the test timeout.

Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
status-firefox122: affected → fixed
Target Milestone: --- → 122 Branch
Flags: needinfo?(james)
You need to log in before you can comment on or make changes to this bug.