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

[task 2022-02-01T03:35:26.611Z] 03:35:26     INFO -  Successfully installed Automat-20.2.0 attrs-20.3.0 cffi-1.14.5 constantly-15.1.0 cryptography-3.4.6 hyperlink-21.0.0 incremental-17.5.0 pyasn1-0.4.8 pyasn1-modules-0.2.8 pycparser-2.20 txaio-21.2.1 zope.interface-5.2.0
[task 2022-02-01T03:35:26.662Z] 03:35:26     INFO - Return code: 0
[task 2022-02-01T03:35:26.662Z] 03:35:26     INFO - Done creating virtualenv /opt/worker/tasks/task_164368641339257/build/venv.
[task 2022-02-01T03:35:26.662Z] 03:35:26     INFO - Getting output from command: ['/opt/worker/tasks/task_164368641339257/build/venv/bin/pip', 'list', '--format', 'freeze']
[task 2022-02-01T03:35:26.662Z] 03:35:26     INFO - Copy/paste: /opt/worker/tasks/task_164368641339257/build/venv/bin/pip list --format freeze
[task 2022-02-01T03:35:27.274Z] 03:35:27     INFO - Reading from file tmpfile_stdout
[task 2022-02-01T03:35:27.274Z] 03:35:27     INFO - Reading from file tmpfile_stderr
[task 2022-02-01T03:35:27.274Z] 03:35:27     INFO - Current package versions:
[task 2022-02-01T03:35:27.274Z] 03:35:27     INFO -   Automat == 20.2.0
[task 2022-02-01T03:35:27.274Z] 03:35:27     INFO -   Twisted == 21.2.0
[task 2022-02-01T03:35:27.274Z] 03:35:27     INFO -   UNKNOWN == 0.0.0
[task 2022-02-01T03:35:27.274Z] 03:35:27     INFO -   attrs == 20.3.0
[task 2022-02-01T03:35:27.274Z] 03:35:27     INFO -   autobahn == 21.2.1
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   blessings == 1.7
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   browsermob-proxy == 0.8.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   certifi == 2018.4.16
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   cffi == 1.14.5
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   chardet == 4.0.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   constantly == 15.1.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   cryptography == 3.4.6
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   distro == 1.4.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   h2 == 3.2.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   hpack == 3.0.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   hyperframe == 5.2.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   hyperlink == 21.0.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   idna == 2.10
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   incremental == 17.5.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   ipaddr == 2.2.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   jsonschema == 2.5.1
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   manifestparser == 2.1.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   marionette-driver == 3.1.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   marionette-harness == 5.0.2
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   mock == 1.0.1
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   mod-pywebsocket == 3.0.1
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   mozInstall == 2.0.1
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   mozcrash == 2.0.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   mozdebug == 0.3.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   mozdevice == 4.0.3
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   mozfile == 2.1.0
[task 2022-02-01T03:35:27.275Z] 03:35:27     INFO -   mozgeckoprofiler == 1.0.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozhttpd == 0.7.1
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozinfo == 1.2.2
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozleak == 1.0.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozlog == 7.1.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   moznetwork == 1.1.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozpower == 1.1.2
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozprocess == 1.3.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozprofile == 2.5.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozproxy == 1.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozrunner == 8.2.1
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozscreenshot == 1.0.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozsystemmonitor == 0.4
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   moztest == 1.1.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   mozversion == 2.3.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   passlib == 1.7.4
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   pip == 21.2.3
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   psutil == 5.8.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   pyOpenSSL == 19.1.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   pyasn1 == 0.4.8
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   pyasn1-modules == 0.2.8
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   pycparser == 2.20
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   redo == 2.0.4
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   requests == 2.25.1
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   service-identity == 18.1.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   setuptools == 51.2.0
[task 2022-02-01T03:35:27.276Z] 03:35:27     INFO -   simplejson == 3.3.0
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO -   six == 1.13.0
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO -   txaio == 21.2.1
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO -   urllib3 == 1.26.4
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO -   vcversioner == 2.16.0.0
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO -   wheel == 0.37.0
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO -   wptserve == 3.0
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO -   zope.interface == 5.2.0
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO - Running post-action listener: _resource_record_post_action
[task 2022-02-01T03:35:27.277Z] 03:35:27     INFO - Running post-action listener: _start_resource_monitoring
[task 2022-02-01T03:35:27.292Z] 03:35:27     INFO - Starting resource monitoring.
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - [mozharness: 2022-02-01 03:35:27.296386Z] Finished create-virtualenv step (success)
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - [mozharness: 2022-02-01 03:35:27.297018Z] Running start-pulseaudio step.
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - Running pre-action listener: _resource_record_pre_action
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - Running main action method: start_pulseaudio
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - Running post-action listener: _resource_record_post_action
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - [mozharness: 2022-02-01 03:35:27.297731Z] Finished start-pulseaudio step (success)
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - [mozharness: 2022-02-01 03:35:27.297792Z] Running install step.
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - Running pre-action listener: _resource_record_pre_action
[task 2022-02-01T03:35:27.297Z] 03:35:27     INFO - Running main action method: install
[task 2022-02-01T03:35:27.298Z] 03:35:27     INFO - Getting output from command: ['/opt/worker/tasks/task_164368641339257/build/venv/bin/pip', 'list', '--format', 'freeze']
[task 2022-02-01T03:35:27.298Z] 03:35:27     INFO - Copy/paste: /opt/worker/tasks/task_164368641339257/build/venv/bin/pip list --format freeze
[task 2022-02-01T03:35:27.732Z] 03:35:27     INFO - Reading from file tmpfile_stdout
[task 2022-02-01T03:35:27.733Z] 03:35:27     INFO - Reading from file tmpfile_stderr
[task 2022-02-01T03:35:27.733Z] 03:35:27     INFO - Detecting whether we're running mozinstall >=1.0...
[task 2022-02-01T03:35:27.733Z] 03:35:27     INFO - Getting output from command: ['/opt/worker/tasks/task_164368641339257/build/venv/bin/mozinstall', '-h']
[task 2022-02-01T03:35:27.733Z] 03:35:27     INFO - Copy/paste: /opt/worker/tasks/task_164368641339257/build/venv/bin/mozinstall -h
[task 2022-02-01T03:35:27.903Z] 03:35:27     INFO - Reading from file tmpfile_stdout
[task 2022-02-01T03:35:27.903Z] 03:35:27     INFO - Output received:
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO -  Usage: mozinstall [options] installer
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO -  Options:
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO -    -h, --help            show this help message and exit
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO -    -d DEST, --destination=DEST
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO -                          Directory to install application into. [default:
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO -                          "/opt/worker/tasks/task_164368641339257"]
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO -    --app=APP             Application being installed. [default: firefox]
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO - mkdir: /opt/worker/tasks/task_164368641339257/build/application
[task 2022-02-01T03:35:27.904Z] 03:35:27     INFO - Getting output from command: ['/opt/worker/tasks/task_164368641339257/build/venv/bin/mozinstall', '/opt/worker/tasks/task_164368641339257/installer.dmg', '--destination', '/opt/worker/tasks/task_164368641339257/build/application']
[task 2022-02-01T03:35:27.905Z] 03:35:27     INFO - Copy/paste: /opt/worker/tasks/task_164368641339257/build/venv/bin/mozinstall /opt/worker/tasks/task_164368641339257/installer.dmg --destination /opt/worker/tasks/task_164368641339257/build/application
[task 2022-02-01T03:35:51.137Z] 03:35:51     INFO - Reading from file tmpfile_stdout
[task 2022-02-01T03:35:51.137Z] 03:35:51     INFO - Output received:
[task 2022-02-01T03:35:51.137Z] 03:35:51     INFO -  /opt/worker/tasks/task_164368641339257/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - Running post-action listener: _resource_record_post_action
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - [mozharness: 2022-02-01 03:35:51.138037Z] Finished install step (success)
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - [mozharness: 2022-02-01 03:35:51.138101Z] Running stage-files step.
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - Running pre-action listener: _resource_record_pre_action
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - Running main action method: stage_files
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - Running post-action listener: _resource_record_post_action
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - [mozharness: 2022-02-01 03:35:51.138494Z] Finished stage-files step (success)
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - [mozharness: 2022-02-01 03:35:51.138540Z] Running run-tests step.
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - Running pre-action listener: _resource_record_pre_action
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - Running pre-action listener: _set_gcov_prefix
[task 2022-02-01T03:35:51.138Z] 03:35:51     INFO - Running main action method: run_tests
[task 2022-02-01T03:35:51.143Z] 03:35:51     INFO - Running pre test command disable_dock with 'defaults write com.apple.dock autohide -bool true'
[task 2022-02-01T03:35:51.143Z] 03:35:51     INFO - Running command: ('defaults', 'write', 'com.apple.dock', 'autohide', '-bool', 'true') in /opt/worker/tasks/task_164368641339257/build
[task 2022-02-01T03:35:51.143Z] 03:35:51     INFO - Copy/paste: defaults write com.apple.dock autohide -bool true
[task 2022-02-01T03:35:51.175Z] 03:35:51     INFO - Return code: 0
[task 2022-02-01T03:35:51.180Z] 03:35:51     INFO - Running pre test command kill_dock with 'killall Dock'
[task 2022-02-01T03:35:51.180Z] 03:35:51     INFO - Running command: ('killall', 'Dock') in /opt/worker/tasks/task_164368641339257/build
[task 2022-02-01T03:35:51.180Z] 03:35:51     INFO - Copy/paste: killall Dock
[task 2022-02-01T03:35:51.186Z] 03:35:51     INFO - Return code: 0
[task 2022-02-01T03:35:51.189Z] 03:35:51     INFO - #### Running mochitest suites
[task 2022-02-01T03:35:51.189Z] 03:35:51     INFO - Structured output parser in use for mochitest.
[task 2022-02-01T03:35:51.199Z] 03:35:51    FATAL - A script class using structured logging must inherit from the MozbaseMixin to ensure that mozlog is available.
[task 2022-02-01T03:35:51.199Z] 03:35:51    FATAL - Running post_fatal callback...
[task 2022-02-01T03:35:51.199Z] 03:35:51    FATAL - Exiting -1
[task 2022-02-01T03:35:51.199Z] 03:35:51     INFO - Running post-action listener: _package_coverage_data
[task 2022-02-01T03:35:51.199Z] 03:35:51     INFO - Running post-action listener: _resource_record_post_action
[task 2022-02-01T03:35:51.199Z] 03:35:51     INFO - Running post-action listener: process_java_coverage_data
[task 2022-02-01T03:35:51.199Z] 03:35:51     INFO - [mozharness: 2022-02-01 03:35:51.199889Z] Finished run-tests step (failed)
[task 2022-02-01T03:35:51.199Z] 03:35:51     INFO - Running post-run listener: _resource_record_post_run
[task 2022-02-01T03:35:51.249Z] 03:35:51     INFO - instance_metadata.json not found; unable to determine instance type
[task 2022-02-01T03:35:51.250Z] 03:35:51     INFO - Validating Perfherder data against /opt/worker/tasks/task_164368641339257/mozharness/external_tools/performance-artifact-schema.json
[task 2022-02-01T03:35:51.252Z] 03:35:51     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-devtools-chrome.overall", "extraOptions": ["e10s", "buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 14.083333333333334}, {"name": "io_write_bytes", "value": 320905216}, {"name": "io.read_bytes", "value": 379160064}, {"name": "io_write_time", "value": 581}, {"name": "io_read_time", "value": 22082}]}, {"name": "mochitest.mochitest-devtools-chrome.start-pulseaudio", "subtests": [{"name": "time", "value": 0.0004589557647705078}]}, {"name": "mochitest.mochitest-devtools-chrome.install", "subtests": [{"name": "time", "value": 23.84013795852661}, {"name": "cpu_percent", "value": 14.083333333333334}]}, {"name": "mochitest.mochitest-devtools-chrome.stage-files", "subtests": [{"name": "time", "value": 0.0002892017364501953}]}, {"name": "mochitest.mochitest-devtools-chrome.run-tests", "subtests": [{"name": "time", "value": 0.061225175857543945}]}]}
[task 2022-02-01T03:35:51.252Z] 03:35:51     INFO - Total resource usage - Wall time: 24s; CPU: Can't collect data; Read bytes: 379160064; Write bytes: 320905216; Read time: 22082; Write time: 581
[task 2022-02-01T03:35:51.252Z] 03:35:51     INFO - TinderboxPrint: I/O read bytes / time<br/>379,160,064 / 22,082
[task 2022-02-01T03:35:51.252Z] 03:35:51     INFO - TinderboxPrint: I/O write bytes / time<br/>320,905,216 / 581
[task 2022-02-01T03:35:51.252Z] 03:35:51     INFO - TinderboxPrint: CPU idle<br/>245.4 (85.9%)
[task 2022-02-01T03:35:51.253Z] 03:35:51     INFO - TinderboxPrint: CPU system<br/>4.3 (1.5%)
[task 2022-02-01T03:35:51.253Z] 03:35:51     INFO - TinderboxPrint: CPU user<br/>35.9 (12.6%)
[task 2022-02-01T03:35:51.253Z] 03:35:51     INFO - TinderboxPrint: Swap in / out<br/>511,619,072 / 0
[task 2022-02-01T03:35:51.253Z] 03:35:51     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-02-01T03:35:51.253Z] 03:35:51     INFO - install - Wall time: 24s; CPU: 14%; Read bytes: 379160064; Write bytes: 320905216; Read time: 22082; Write time: 581
[task 2022-02-01T03:35:51.253Z] 03:35:51     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-02-01T03:35:51.253Z] 03:35:51     INFO - run-tests - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[taskcluster 2022-02-01T03:35:51.288Z]    Exit Code: 255
[taskcluster 2022-02-01T03:35:51.288Z]    User Time: 1m32.364514s
[taskcluster 2022-02-01T03:35:51.288Z]  Kernel Time: 20.759625s
[taskcluster 2022-02-01T03:35:51.288Z]    Wall Time: 2m9.018497s
[taskcluster 2022-02-01T03:35:51.288Z]       Result: FAILED

MozbaseMixin installs mozbase: https://searchfox.org/mozilla-central/rev/657dc24e7254dac44880c33a2434523d0849d28f/testing/mozharness/mozharness/mozilla/mozbase.py#19
StructuredOutputParser fails with this error if it cannot import mozlog: https://searchfox.org/mozilla-central/rev/657dc24e7254dac44880c33a2434523d0849d28f/testing/mozharness/mozharness/mozilla/structuredlog.py#59

Most of these failures are from the desktop_unittest.py script, which definitely inherits from MozbaseMixin. Also, logs show multiple installations of mozlog in the venv.
https://firefoxci.taskcluster-artifacts.net/aSptLzV3Qjq20kalBO6KVA/0/public/logs/live_backing.log

[task 2022-07-01T14:29:11.780Z] 14:29:11     INFO -  Successfully installed browsermob-proxy-0.8.0 certifi-2018.4.16 conditioned-profile-0.2 geckoprocesstypes h2-3.2.0 hpack-3.0.0 hyperframe-5.2.0 manifestparser marionette-driver-3.1.0 marionette-harness-5.0.2 mod-pywebsocket-3.0.1 mozInstall-2.0.1 mozcrash-2.0.0 mozdebug-0.3.0 mozdevice-4.0.3 mozfile-2.1.0 mozgeckoprofiler-1.0.0 mozhttpd-0.7.1 mozinfo-1.2.2 mozleak-1.0.0 mozlog-7.1.0 moznetwork-1.1.0 mozpower-1.1.2 mozprocess-1.3.0 mozprofile-2.5.0 mozproxy-1.0 mozrunner-8.2.1 mozscreenshot-1.0.0 mozterm moztest-1.1.0 mozversion-2.3.0 wptserve-3.0
...
[task 2022-07-01T14:29:56.949Z] 14:29:56     INFO - Current package versions:
...
[task 2022-07-01T14:29:56.951Z] 14:29:56     INFO -   mozlog == 7.1.0
...
[task 2022-07-01T14:30:16.708Z] 14:30:16     INFO - #### Running mochitest suites
[task 2022-07-01T14:30:16.709Z] 14:30:16     INFO - Structured output parser in use for mochitest.
[task 2022-07-01T14:30:16.845Z] 14:30:16    FATAL - A script class using structured logging must inherit from the MozbaseMixin to ensure that mozlog is available.
[task 2022-07-01T14:30:16.845Z] 14:30:16    FATAL - Running post_fatal callback...

I am surprised to see the mozbase requirements being installed multiple times (though I recall seeing that reported in another bug), but that shouldn't be causing this problem, as long as the most recent one succeeds. Is mozharness creating multiple virtual envs? Using the "wrong" one??

No failures since bug 1732228 was resolved, and I think that makes sense.