Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=335380353&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FbOOZhPrQzWdZRoHYI-rKg/runs/0/artifacts/public/logs/live_backing.log
[task 2021-04-04T00:36:12.927Z] 00:36:12 INFO - TEST-OK | toolkit/components/antitracking/test/browser/browser_socialtracking.js | took 590ms
[task 2021-04-04T00:36:12.942Z] 00:36:12 INFO - checking window state
[task 2021-04-04T00:36:12.946Z] 00:36:12 INFO - TEST-START | toolkit/components/antitracking/test/browser/browser_socialtracking_save_image.js
[task 2021-04-04T00:36:13.370Z] 00:36:13 INFO - GECKO(6462) | Gdk-Message: 00:36:13.362: firefox: Fatal IO error 11 (Resource temporarily unavailable) on X server :0.
[task 2021-04-04T00:36:13.405Z] 00:36:13 INFO - GECKO(6462) | Exiting due to channel error.
[task 2021-04-04T00:36:13.407Z] 00:36:13 INFO - GECKO(6462) | Exiting due to channel error.
[task 2021-04-04T00:36:13.409Z] 00:36:13 INFO - GECKO(6462) | Exiting due to channel error.
[task 2021-04-04T00:36:13.410Z] 00:36:13 INFO - GECKO(6462) | Exiting due to channel error.
[task 2021-04-04T00:36:13.411Z] 00:36:13 INFO - GECKO(6462) | Exiting due to channel error.
[task 2021-04-04T00:36:13.412Z] 00:36:13 INFO - GECKO(6462) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2021-04-04T00:36:13.413Z] 00:36:13 INFO - GECKO(6462) | Exiting due to channel error.
[task 2021-04-04T00:36:13.414Z] 00:36:13 INFO - GECKO(6462) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2021-04-04T00:36:13.415Z] 00:36:13 INFO - GECKO(6462) | Exiting due to channel error.
[task 2021-04-04T00:36:13.416Z] 00:36:13 INFO - GECKO(6462) | Exiting due to channel error.
[task 2021-04-04T00:36:13.473Z] 00:36:13 INFO - TEST-INFO | Main app process: exit 1
[task 2021-04-04T00:36:13.475Z] 00:36:13 INFO - Buffered messages logged at 00:36:12
[task 2021-04-04T00:36:13.476Z] 00:36:13 INFO - Entering test bound setup
[task 2021-04-04T00:36:13.477Z] 00:36:13 INFO - Setting up the prefs.
[task 2021-04-04T00:36:13.477Z] 00:36:13 INFO - Setting MockFilePicker.
[task 2021-04-04T00:36:13.478Z] 00:36:13 INFO - Leaving test bound setup
[task 2021-04-04T00:36:13.479Z] 00:36:13 INFO - Entering test bound
[task 2021-04-04T00:36:13.480Z] 00:36:13 INFO - Open a new tab for testing
[task 2021-04-04T00:36:13.480Z] 00:36:13 INFO - Buffered messages logged at 00:36:13
[task 2021-04-04T00:36:13.480Z] 00:36:13 INFO - Open the context menu.
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - Global property added while loading chrome://browser/content/nsContextMenu.js: screenshotsDisabled
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - Triggering the save process.
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - Wait until the save is finished.
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - MockFilePicker showCallback
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_socialtracking_save_image.js | Image should have been downloaded successfully -
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - Close the context menu.
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - Buffered messages finished
[task 2021-04-04T00:36:13.481Z] 00:36:13 ERROR - TEST-UNEXPECTED-FAIL | toolkit/components/antitracking/test/browser/browser_socialtracking_save_image.js | application terminated with exit code 1
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - runtests.py | Application ran for: 0:12:53.029240
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - zombiecheck | Reading PID log: /tmp/tmpOuwgEIpidlog
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 6482
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 6523
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 6537
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 6624
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 6661
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 6689
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 6720
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 6798
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 7755
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - ==> process 6462 launched child process 7814
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 6624
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 6689
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 6661
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 7814
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 6537
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 7755
[task 2021-04-04T00:36:13.481Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 6798
[task 2021-04-04T00:36:13.487Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 6482
[task 2021-04-04T00:36:13.488Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 6720
[task 2021-04-04T00:36:13.488Z] 00:36:13 INFO - zombiecheck | Checking for orphan process with PID: 6523
[task 2021-04-04T00:36:13.488Z] 00:36:13 INFO - Stopping web server
[task 2021-04-04T00:36:13.488Z] 00:36:13 INFO - Server shut down.
[task 2021-04-04T00:36:13.511Z] 00:36:13 INFO - Web server killed.
[task 2021-04-04T00:36:13.512Z] 00:36:13 INFO - Stopping web socket server
[task 2021-04-04T00:36:13.532Z] 00:36:13 INFO - Stopping ssltunnel
[task 2021-04-04T00:36:13.552Z] 00:36:13 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-04-04T00:36:13.553Z] 00:36:13 INFO - runtests.py | Running tests: end.
[task 2021-04-04T00:36:13.576Z] 00:36:13 INFO - Buffered messages finished
[task 2021-04-04T00:36:13.577Z] 00:36:13 INFO - Running manifest: toolkit/components/mozprotocol/tests/browser.ini
[task 2021-04-04T00:36:13.605Z] 00:36:13 INFO - Setting pipeline to PAUSED ...
[task 2021-04-04T00:36:13.605Z] 00:36:13 INFO - Pipeline is PREROLLING ...
[task 2021-04-04T00:36:13.606Z] 00:36:13 INFO - Pipeline is PREROLLED ...
[task 2021-04-04T00:36:13.607Z] 00:36:13 INFO - Setting pipeline to PLAYING ...
[task 2021-04-04T00:36:13.607Z] 00:36:13 INFO - New clock: GstSystemClock
[task 2021-04-04T00:36:13.645Z] 00:36:13 INFO - Got EOS from element "pipeline0".
[task 2021-04-04T00:36:13.645Z] 00:36:13 INFO - Execution ended after 0:00:00.033360911
[task 2021-04-04T00:36:13.645Z] 00:36:13 INFO - Setting pipeline to PAUSED ...
[task 2021-04-04T00:36:13.645Z] 00:36:13 INFO - Setting pipeline to READY ...
[task 2021-04-04T00:36:13.645Z] 00:36:13 INFO - (gst-launch-1.0:8269): GStreamer-CRITICAL **: 00:36:13.639: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2021-04-04T00:36:13.645Z] 00:36:13 INFO - Setting pipeline to NULL ...
[task 2021-04-04T00:36:13.645Z] 00:36:13 INFO - Freeing pipeline ...
[task 2021-04-04T00:36:14.062Z] 00:36:14 INFO - PID 8285 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2021-04-04T00:36:14.105Z] 00:36:14 INFO - MochitestServer : launching [u'/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-f', '/builds/worker/workspace/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpi7z8jw.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2021-04-04T00:36:14.105Z] 00:36:14 INFO - runtests.py | Server pid: 8288
[task 2021-04-04T00:36:14.129Z] 00:36:14 INFO - runtests.py | Websocket server pid: 8291
[task 2021-04-04T00:36:14.149Z] 00:36:14 INFO - runtests.py | SSL tunnel pid: 8296
[task 2021-04-04T00:36:14.205Z] 00:36:14 INFO - runtests.py | Running with scheme: http
[task 2021-04-04T00:36:14.206Z] 00:36:14 INFO - runtests.py | Running with e10s: True
[task 2021-04-04T00:36:14.206Z] 00:36:14 INFO - runtests.py | Running with fission: False
[task 2021-04-04T00:36:14.207Z] 00:36:14 INFO - runtests.py | Running with cross-origin iframes: False
[task 2021-04-04T00:36:14.207Z] 00:36:14 INFO - runtests.py | Running with serviceworker_e10s: True
[task 2021-04-04T00:36:14.207Z] 00:36:14 INFO - runtests.py | Running with socketprocess_e10s: False
[task 2021-04-04T00:36:14.207Z] 00:36:14 INFO - runtests.py | Running tests: start.
[task 2021-04-04T00:36:14.207Z] 00:36:14 INFO -
[task 2021-04-04T00:36:14.248Z] 00:36:14 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpi7z8jw.mozrunner
[task 2021-04-04T00:36:14.263Z] 00:36:14 INFO - runtests.py | Application pid: 8312
[task 2021-04-04T00:36:14.263Z] 00:36:14 INFO - TEST-INFO | started process GECKO(8312)
[task 2021-04-04T00:36:14.721Z] 00:36:14 INFO - GECKO(8312) | 1617496574715 Marionette INFO Marionette enabled
[task 2021-04-04T00:36:14.797Z] 00:36:14 INFO - GECKO(8312) | 1617496574787 Marionette TRACE Received observer notification toplevel-window-ready
[task 2021-04-04T00:36:16.510Z] 00:36:16 INFO - GECKO(8312) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
[task 2021-04-04T00:36:17.316Z] 00:36:17 INFO - GECKO(8312) | 1617496577310 Marionette TRACE Received observer notification marionette-startup-requested
[task 2021-04-04T00:36:17.317Z] 00:36:17 INFO - GECKO(8312) | 1617496577310 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2021-04-04T00:36:17.333Z] 00:36:17 INFO - GECKO(8312) | 1617496577323 Marionette TRACE All scripts recorded.
[task 2021-04-04T00:36:17.334Z] 00:36:17 INFO - GECKO(8312) | 1617496577324 Marionette INFO Listening on port 2828
[task 2021-04-04T00:36:17.335Z] 00:36:17 INFO - GECKO(8312) | 1617496577324 Marionette DEBUG Marionette is listening
[task 2021-04-04T00:36:17.381Z] 00:36:17 INFO - GECKO(8312) | 1617496577376 Marionette DEBUG Accepted connection 0 from 127.0.0.1:47760
[task 2021-04-04T00:36:17.381Z] 00:36:17 INFO - GECKO(8312) | 1617496577379 Marionette DEBUG Accepted connection 1 from 127.0.0.1:47762
[task 2021-04-04T00:36:17.381Z] 00:36:17 INFO - GECKO(8312) | 1617496577379 Marionette DEBUG Closed connection 0
[task 2021-04-04T00:36:17.389Z] 00:36:17 INFO - GECKO(8312) | 1617496577387 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-04-04T00:36:17.404Z] 00:36:17 INFO - GECKO(8312) | 1617496577399 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"22ce3688-696d-47d6-8b5f-eefe226d6aba","capabilities":{"browserName":"firefox","browserVersion":"88.0" ... mp/tmpi7z8jw.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2021-04-04T00:36:17.433Z] 00:36:17 INFO - GECKO(8312) | 1617496577427 Marionette DEBUG 1 -> [0,2,"Addon:Install",{"path":"/tmp/tmpEtMHj3.zip","temporary":false}]
[task 2021-04-04T00:36:17.572Z] 00:36:17 INFO - GECKO(8312) | 1617496577564 Marionette DEBUG 1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2021-04-04T00:36:17.592Z] 00:36:17 INFO - GECKO(8312) | 1617496577589 Marionette DEBUG 1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpoiwX6Z.zip","temporary":false}]
[task 2021-04-04T00:36:17.612Z] 00:36:17 INFO - GECKO(8312) | 1617496577610 Marionette DEBUG 1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2021-04-04T00:36:17.616Z] 00:36:17 INFO - GECKO(8312) | 1617496577611 Marionette DEBUG 1 -> [0,4,"Marionette:GetContext",{}]
[task 2021-04-04T00:36:17.618Z] 00:36:17 INFO - GECKO(8312) | 1617496577612 Marionette DEBUG 1 <- [1,4,null,{"value":"content"}]
[task 2021-04-04T00:36:17.618Z] 00:36:17 INFO - GECKO(8312) | 1617496577613 Marionette DEBUG 1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-04-04T00:36:17.619Z] 00:36:17 INFO - GECKO(8312) | 1617496577613 Marionette DEBUG 1 <- [1,5,null,{"value":null}]
[task 2021-04-04T00:36:17.620Z] 00:36:17 INFO - GECKO(8312) | 1617496577616 Marionette DEBUG 1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... testUrl":"about:blank","flavor":"browser-chrome"}],"filename":"tests/mochitest/runtests.py","sandbox":"default","line":1933}]
[task 2021-04-04T00:36:17.636Z] 00:36:17 INFO - GECKO(8312) | 1617496577624 Marionette TRACE [7] MarionetteCommands actor created for window id 2
[task 2021-04-04T00:36:17.638Z] 00:36:17 INFO - GECKO(8312) | 1617496577627 Marionette TRACE [19] MarionetteEvents actor created for window id 2147483649
[task 2021-04-04T00:36:17.666Z] 00:36:17 INFO - GECKO(8312) | 1617496577657 Marionette TRACE Received observer notification toplevel-window-ready
[task 2021-04-04T00:36:17.670Z] 00:36:17 INFO - GECKO(8312) | 1617496577657 Marionette TRACE Received observer notification toplevel-window-ready
[task 2021-04-04T00:36:17.673Z] 00:36:17 INFO - GECKO(8312) | 1617496577670 Marionette DEBUG 1 <- [1,6,null,{"value":null}]
[task 2021-04-04T00:36:17.693Z] 00:36:17 INFO - GECKO(8312) | 1617496577684 Marionette TRACE [19] MarionetteEvents actor created for window id 2147483650
[task 2021-04-04T00:36:17.734Z] 00:36:17 INFO - GECKO(8312) | 1617496577732 Marionette DEBUG 1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2021-04-04T00:36:17.740Z] 00:36:17 INFO - GECKO(8312) | 1617496577734 Marionette DEBUG 1 <- [1,7,null,{"value":null}]
[task 2021-04-04T00:36:17.776Z] 00:36:17 INFO - runtests.py | Waiting for browser...
[task 2021-04-04T00:36:17.776Z] 00:36:17 INFO - GECKO(8312) | 1617496577766 Marionette DEBUG 1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2021-04-04T00:36:17.776Z] 00:36:17 INFO - GECKO(8312) | 1617496577772 Marionette DEBUG 1 <- [1,8,null,{"value":null}]
[task 2021-04-04T00:36:17.778Z] 00:36:17 INFO - GECKO(8312) | 1617496577775 Marionette DEBUG Closed connection 1
[task 2021-04-04T00:36:17.860Z] 00:36:17 INFO - GECKO(8312) | 1617496577858 Marionette TRACE [39] MarionetteEvents actor created for window id 6442450945
[task 2021-04-04T00:36:17.861Z] 00:36:17 INFO - GECKO(8312) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'
[task 2021-04-04T00:36:18.081Z] 00:36:18 INFO - TEST-START | toolkit/components/mozprotocol/tests/browser_mozprotocol.js
[task 2021-04-04T00:36:18.572Z] 00:36:18 INFO - GECKO(8312) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2021-04-04T00:36:18.573Z] 00:36:18 INFO - GECKO(8312) | MEMORY STAT | vsize 2767MB | residentFast 269MB | heapAllocated 107MB
[task 2021-04-04T00:36:18.573Z] 00:36:18 INFO - TEST-OK | toolkit/components/mozprotocol/tests/browser_mozprotocol.js | took 496ms
[task 2021-04-04T00:36:18.601Z] 00:36:18 INFO - checking window state
[task 2021-04-04T00:36:18.912Z] 00:36:18 INFO - GECKO(8312) | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-04-04T00:36:19.974Z] 00:36:19 INFO - GECKO(8312) | Completed ShutdownLeaks collections in process 8460
[task 2021-04-04T00:36:19.975Z] 00:36:19 INFO - GECKO(8312) | Completed ShutdownLeaks collections in process 8491
[task 2021-04-04T00:36:19.990Z] 00:36:19 INFO - GECKO(8312) | Completed ShutdownLeaks collections in process 8393
[task 2021-04-04T00:36:19.990Z] 00:36:19 INFO - GECKO(8312) | Completed ShutdownLeaks collections in process 8378
[task 2021-04-04T00:36:20.167Z] 00:36:20 INFO - GECKO(8312) | Completed ShutdownLeaks collections in process 8312
[task 2021-04-04T00:36:20.168Z] 00:36:20 INFO - TEST-START | Shutdown```
Description
•