Filed by: amarc [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=495908972&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/OukrCM7mSSqBItVVVhKqmw/runs/0/artifacts/public/logs/live_backing.log
[task 2025-02-20T21:51:21.565Z] 21:51:21 INFO - TEST-START | toolkit/components/satchel/megalist/content/tests/browser/browser_passwords_primary_password.js
[task 2025-02-20T21:51:21.576Z] 21:51:21 INFO - GECKO(1407) | MP change from to omgsecret!
[task 2025-02-20T21:52:09.467Z] 21:52:09 INFO - TEST-INFO | started process screentopng
[task 2025-02-20T21:52:09.607Z] 21:52:09 INFO - TEST-INFO | screentopng: exit 0
[task 2025-02-20T21:52:09.608Z] 21:52:09 INFO - Buffered messages logged at 21:51:21
[task 2025-02-20T21:52:09.608Z] 21:52:09 INFO - Entering setup bound
[task 2025-02-20T21:52:09.608Z] 21:52:09 INFO - Leaving setup bound
[task 2025-02-20T21:52:09.609Z] 21:52:09 INFO - Entering test bound test_primary_password_authentication_causes_refresh
[task 2025-02-20T21:52:09.609Z] 21:52:09 INFO - TEST-PASS | toolkit/components/satchel/megalist/content/tests/browser/browser_passwords_primary_password.js | Pref should be set to default value of empty string to start the test - "" == "" -
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Adding mock passwords
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Saving login: bob, pass1, https://example1.com
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Saving login: sally, pass2, https://example2.com
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Saving login: ned, pass3, https://example3.com
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Wait for PP dialog for 5000 ms and cancel.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Open Passwords sidebar
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Buffered messages logged at 21:51:26
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Waiting for PP dialog timed out after 5000 ms.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Wait for PP dialog for 5000 ms and cancel.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Notify LoginDataSource and try to cancel the primary password dialog again.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - No logins should be displayed if the user is not authenticated.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Wait for PP dialog for 5000 ms and authenticate.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Open about:logins.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Buffered messages logged at 21:51:27
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Authenticate user in aboutlogins.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Authentication in aboutlogins should cause megalist to render all logins.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Check that all logins are rendered.
[task 2025-02-20T21:52:09.616Z] 21:52:09 INFO - Buffered messages finished
[task 2025-02-20T21:52:09.617Z] 21:52:09 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/satchel/megalist/content/tests/browser/browser_passwords_primary_password.js | Test timed out -
[task 2025-02-20T21:52:09.617Z] 21:52:09 INFO - GECKO(1407) | Completed ShutdownLeaks collections in process 1407
[task 2025-02-20T21:52:09.617Z] 21:52:09 INFO - TEST-START | Shutdown
[task 2025-02-20T21:52:09.618Z] 21:52:09 INFO - Browser Chrome Test Summary
[task 2025-02-20T21:52:09.618Z] 21:52:09 INFO - Passed: 37
[task 2025-02-20T21:52:09.619Z] 21:52:09 INFO - Failed: 1
[task 2025-02-20T21:52:09.619Z] 21:52:09 INFO - Todo: 0
[task 2025-02-20T21:52:09.619Z] 21:52:09 INFO - Mode: e10s
[task 2025-02-20T21:52:09.620Z] 21:52:09 INFO - *** End BrowserChrome Test Results ***
[task 2025-02-20T21:52:09.620Z] 21:52:09 INFO - GECKO(1407) | Exiting due to channel error.
[task 2025-02-20T21:52:09.620Z] 21:52:09 INFO - GECKO(1407) | Exiting due to channel error.
[task 2025-02-20T21:52:09.621Z] 21:52:09 INFO - GECKO(1407) | Exiting due to channel error.
[task 2025-02-20T21:52:09.621Z] 21:52:09 INFO - GECKO(1407) | Exiting due to channel error.
[task 2025-02-20T21:52:09.621Z] 21:52:09 INFO - GECKO(1407) | Exiting due to channel error.
[task 2025-02-20T21:52:09.622Z] 21:52:09 INFO - GECKO(1407) | Exiting due to channel error.
[task 2025-02-20T21:52:09.622Z] 21:52:09 INFO - GECKO(1407) | Exiting due to channel error.
[task 2025-02-20T21:52:09.622Z] 21:52:09 INFO - TEST-INFO | Main app process: exit 0
[task 2025-02-20T21:52:09.623Z] 21:52:09 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/satchel/megalist/content/tests/browser/browser_passwords_primary_password.js | Application shut down (without crashing) in the middle of a test!
[task 2025-02-20T21:52:09.623Z] 21:52:09 INFO - TEST-INFO took 47436ms
[task 2025-02-20T21:52:09.623Z] 21:52:09 INFO - runtests.py | Application ran for: 0:00:56.420017
[task 2025-02-20T21:52:09.623Z] 21:52:09 INFO - zombiecheck | Reading PID log: /tmp/tmplv7nhyh6pidlog
[task 2025-02-20T21:52:09.623Z] 21:52:09 INFO - ==> process 1407 launched child process 1493
[task 2025-02-20T21:52:09.624Z] 21:52:09 INFO - zombiecheck | Checking for orphan process with PID: 1493
[task 2025-02-20T21:52:09.624Z] 21:52:09 INFO - Stopping web server
[task 2025-02-20T21:52:09.624Z] 21:52:09 INFO - Server shut down.
[task 2025-02-20T21:52:09.624Z] 21:52:09 INFO - Web server killed.
[task 2025-02-20T21:52:09.624Z] 21:52:09 INFO - Stopping web socket server
[task 2025-02-20T21:52:09.625Z] 21:52:09 INFO - Stopping ssltunnel
[task 2025-02-20T21:52:09.625Z] 21:52:09 INFO - Stopping gst for v4l2loopback
[task 2025-02-20T21:52:09.625Z] 21:52:09 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2025-02-20T21:52:09.625Z] 21:52:09 INFO - runtests.py | Running tests: end.
[task 2025-02-20T21:52:09.714Z] 21:52:09 INFO - Buffered messages finished
[task 2025-02-20T21:52:09.715Z] 21:52:09 INFO - Running manifest: toolkit/components/url-classifier/tests/browser/browser.toml
[task 2025-02-20T21:52:09.779Z] 21:52:09 INFO - Setting pipeline to PAUSED ...
[task 2025-02-20T21:52:09.780Z] 21:52:09 INFO - Pipeline is PREROLLING ...
[task 2025-02-20T21:52:09.781Z] 21:52:09 INFO - Pipeline is PREROLLED ...
[task 2025-02-20T21:52:09.781Z] 21:52:09 INFO - Setting pipeline to PLAYING ...
[task 2025-02-20T21:52:09.781Z] 21:52:09 INFO - New clock: GstSystemClock
[task 2025-02-20T21:52:09.814Z] 21:52:09 INFO - Got EOS from element "pipeline0".
[task 2025-02-20T21:52:09.815Z] 21:52:09 INFO - Execution ended after 0:00:00.033432917
[task 2025-02-20T21:52:09.815Z] 21:52:09 INFO - Setting pipeline to PAUSED ...
[task 2025-02-20T21:52:09.815Z] 21:52:09 INFO - Setting pipeline to READY ...
[task 2025-02-20T21:52:09.815Z] 21:52:09 INFO - (gst-launch-1.0:1888): GStreamer-CRITICAL **: 21:52:09.814: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2025-02-20T21:52:09.815Z] 21:52:09 INFO - Setting pipeline to NULL ...
[task 2025-02-20T21:52:09.816Z] 21:52:09 INFO - Freeing pipeline ...
[task 2025-02-20T21:52:10.544Z] 21:52:10 INFO - PID 1905 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2025-02-20T21:52:10.544Z] 21:52:10 INFO -
[task 2025-02-20T21:52:10.556Z] 21:52:10 INFO - MochitestServer : launching ['/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-e', "const _PROFILE_PATH = '/tmp/tmpi7a3m2sg.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false; const _HTTPD_PATH = '/builds/worker/workspace/build/tests/bin/components';", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2025-02-20T21:52:10.556Z] 21:52:10 INFO - runtests.py | Server pid: 1907
[task 2025-02-20T21:52:10.558Z] 21:52:10 INFO - runtests.py | Websocket server pid: 1908
[task 2025-02-20T21:52:10.562Z] 21:52:10 INFO - runtests.py | SSL tunnel pid: 1909
[task 2025-02-20T21:52:10.613Z] 21:52:10 INFO - use http3 server: 0
[task 2025-02-20T21:52:10.614Z] 21:52:10 INFO - runtests.py | Running with scheme: http
[task 2025-02-20T21:52:10.615Z] 21:52:10 INFO - runtests.py | Running with e10s: True
[task 2025-02-20T21:52:10.616Z] 21:52:10 INFO - runtests.py | Running with fission: True
[task 2025-02-20T21:52:10.616Z] 21:52:10 INFO - runtests.py | Running with cross-origin iframes: False
[task 2025-02-20T21:52:10.617Z] 21:52:10 INFO - runtests.py | Running with socketprocess_e10s: True
[task 2025-02-20T21:52:10.617Z] 21:52:10 INFO - runtests.py | Running tests: start.
[task 2025-02-20T21:52:10.617Z] 21:52:10 INFO -
[task 2025-02-20T21:52:10.696Z] 21:52:10 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpi7a3m2sg.mozrunner
[task 2025-02-20T21:52:10.702Z] 21:52:10 INFO - runtests.py | Application pid: 1945
[task 2025-02-20T21:52:10.702Z] 21:52:10 INFO - TEST-INFO | started process GECKO(1945)
[task 2025-02-20T21:52:11.086Z] 21:52:11 INFO - GECKO(1945) | ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2025-02-20T21:52:11.106Z] 21:52:11 INFO - GECKO(1945) | 1740088331105 Marionette INFO Marionette enabled
[task 2025-02-20T21:52:11.107Z] 21:52:11 INFO - GECKO(1945) | 1740088331106 Marionette TRACE Received observer notification final-ui-startup
[task 2025-02-20T21:52:11.151Z] 21:52:11 INFO - GECKO(1945) | console.error: "Warning: unrecognized command line flag" "-foreground"
[task 2025-02-20T21:52:11.158Z] 21:52:11 INFO - GECKO(1945) | ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2025-02-20T21:52:11.202Z] 21:52:11 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_socket_pid2035.log
[task 2025-02-20T21:52:11.208Z] 21:52:11 INFO - GECKO(1945) | 1740088331208 Marionette INFO Listening on port 2828
[task 2025-02-20T21:52:11.211Z] 21:52:11 INFO - GECKO(1945) | 1740088331210 Marionette DEBUG Marionette is listening
[task 2025-02-20T21:52:11.222Z] 21:52:11 INFO - GECKO(1945) | 1740088331222 Marionette DEBUG Accepted connection 0 from 127.0.0.1:54956
[task 2025-02-20T21:52:11.236Z] 21:52:11 INFO - GECKO(1945) | 1740088331236 Marionette DEBUG Closed connection 0
[task 2025-02-20T21:52:11.237Z] 21:52:11 INFO - GECKO(1945) | 1740088331236 Marionette DEBUG Accepted connection 1 from 127.0.0.1:54958
[task 2025-02-20T21:52:11.370Z] 21:52:11 INFO - GECKO(1945) | 1740088331369 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2025-02-20T21:52:11.372Z] 21:52:11 INFO - GECKO(1945) | 1740088331371 Marionette DEBUG Waiting for initial application window
[task 2025-02-20T21:52:11.424Z] 21:52:11 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_tab_pid2059.log
[task 2025-02-20T21:52:11.430Z] 21:52:11 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_rdd_pid2068.log
[task 2025-02-20T21:52:11.552Z] 21:52:11 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_tab_pid2107.log
[task 2025-02-20T21:52:13.271Z] 21:52:13 INFO - GECKO(1945) | console.error: ({})
[task 2025-02-20T21:52:14.143Z] 21:52:14 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_utility_pid2161.log
[task 2025-02-20T21:52:14.155Z] 21:52:14 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_tab_pid2168.log
[task 2025-02-20T21:52:14.158Z] 21:52:14 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_tab_pid2173.log
[task 2025-02-20T21:52:14.199Z] 21:52:14 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_tab_pid2214.log
[task 2025-02-20T21:52:14.228Z] 21:52:14 INFO - GECKO(1945) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi7a3m2sg.mozrunner/runtests_leaks_tab_pid2242.log
[task 2025-02-20T21:52:14.276Z] 21:52:14 INFO - GECKO(1945) | 1740088334275 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2025-02-20T21:52:14.281Z] 21:52:14 INFO - GECKO(1945) | 1740088334280 RemoteAgent TRACE [9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=5000 waitForExplicitStart=false
[task 2025-02-20T21:52:14.282Z] 21:52:14 INFO - GECKO(1945) | 1740088334280 RemoteAgent TRACE [9] ProgressListener Setting unload timer (5000ms)
[task 2025-02-20T21:52:14.282Z] 21:52:14 INFO - GECKO(1945) | 1740088334280 RemoteAgent TRACE [9] Wait for initial navigation: isInitial=false, isLoadingDocument=false
[task 2025-02-20T21:52:14.283Z] 21:52:14 INFO - GECKO(1945) | 1740088334280 RemoteAgent TRACE [9] Document already finished loading: about:blank
[task 2025-02-20T21:52:14.283Z] 21:52:14 INFO - GECKO(1945) | 1740088334280 RemoteAgent TRACE [9] ProgressListener Stop: has error=false url=about:blank
[task 2025-02-20T21:52:14.292Z] 21:52:14 INFO - GECKO(1945) | 1740088334290 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"7ea76481-aa46-4afa-be60-7f166560194e","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"137.0a1","platformName":"linux","unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:137.0) Gecko/20100101 Firefox/137.0","moz:buildID":"20250220185215","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":1945,"moz:profile":"/tmp/tmpi7a3m2sg.mozrunner","moz:shutdownTimeout":60000,"pageLoadStrategy":"normal","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"setWindowRect":true,"strictFileInteractability":true,"moz:accessibilityChecks":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2025-02-20T21:52:14.300Z] 21:52:14 INFO - GECKO(1945) | 1740088334299 Marionette DEBUG 1 -> [0,2,"Addon:Install",{"path":"/tmp/tmps4kr2f9p.zip","temporary":false}]
[task 2025-02-20T21:52:14.546Z] 21:52:14 INFO - GECKO(1945) | 1740088334544 Marionette DEBUG 1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2025-02-20T21:52:14.577Z] 21:52:14 INFO - GECKO(1945) | 1740088334576 Marionette DEBUG 1 -> [0,3,"Addon:Install",{"path":"/tmp/tmp6o692npn.zip","temporary":false}]
[task 2025-02-20T21:52:14.636Z] 21:52:14 INFO - GECKO(1945) | 1740088334634 Marionette DEBUG 1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2025-02-20T21:52:14.648Z] 21:52:14 INFO - GECKO(1945) | 1740088334647 Marionette DEBUG 1 -> [0,4,"Marionette:GetContext",{}]
[task 2025-02-20T21:52:14.648Z] 21:52:14 INFO - GECKO(1945) | 1740088334647 Marionette DEBUG 1 <- [1,4,null,{"value":"content"}]
[task 2025-02-20T21:52:14.651Z] 21:52:14 INFO - GECKO(1945) | 1740088334650 Marionette DEBUG 1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2025-02-20T21:52:14.652Z] 21:52:14 INFO - GECKO(1945) | 1740088334650 Marionette DEBUG 1 <- [1,5,null,{"value":null}]
[task 2025-02-20T21:52:14.653Z] 21:52:14 INFO - GECKO(1945) | 1740088334652 Marionette DEBUG 1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, v. 2.0. If a copy of the MPL was not distr ... s which flavor and url to load.\nlet ev = new CustomEvent(\"mochitest-load\", { detail: [flavor, url] });\nwin.dispatchEvent(ev);","args":[{"flavor":"browser-chrome","testUrl":"about:blank"}],"newSandbox":true,"sandbox":"default","line":2171,"filename":"tests/mochitest/runtests.py"}]
[task 2025-02-20T21:52:14.656Z] 21:52:14 INFO - GECKO(1945) | 1740088334655 RemoteAgent TRACE WebDriverProcessData actor created for PID 1945
[task 2025-02-20T21:52:14.657Z] 21:52:14 INFO - GECKO(1945) | 1740088334656 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2025-02-20T21:52:14.677Z] 21:52:14 INFO - GECKO(1945) | 1740088334676 RemoteAgent TRACE Received observer notification domwindowopened
[task 2025-02-20T21:52:14.681Z] 21:52:14 INFO - GECKO(1945) | 1740088334680 Marionette DEBUG 1 <- [1,6,null,{"value":null}]
[task 2025-02-20T21:52:14.690Z] 21:52:14 INFO - GECKO(1945) | 1740088334689 Marionette DEBUG 1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2025-02-20T21:52:14.690Z] 21:52:14 INFO - GECKO(1945) | 1740088334689 Marionette DEBUG 1 <- [1,7,null,{"value":null}]
[task 2025-02-20T21:52:14.701Z] 21:52:14 INFO - GECKO(1945) | 1740088334700 Marionette DEBUG 1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2025-02-20T21:52:14.701Z] 21:52:14 INFO - GECKO(1945) | 1740088334700 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2025-02-20T21:52:14.702Z] 21:52:14 INFO - GECKO(1945) | 1740088334702 Marionette DEBUG 1 <- [1,8,null,{"value":null}]
[task 2025-02-20T21:52:14.704Z] 21:52:14 INFO - runtests.py | Waiting for browser...
[task 2025-02-20T21:52:14.704Z] 21:52:14 INFO - GECKO(1945) | 1740088334702 Marionette DEBUG Closed connection 1
[task 2025-02-20T21:52:14.964Z] 21:52:14 INFO - *** Start BrowserChrome Test Results ***
[task 2025-02-20T21:52:14.988Z] 21:52:14 INFO - checking window state
[task 2025-02-20T21:52:15.015Z] 21:52:15 INFO - TEST-START | toolkit/components/url-classifier/tests/browser/browser_emailtracking_telemetry.js
Description
•