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

[task 2021-09-14T15:43:29.910Z] 15:43:29     INFO - >> Verify Android boot completed: Attempt #1 of 30
[task 2021-09-14T15:43:29.942Z] Using adb 1.0.41
[task 2021-09-14T15:43:53.954Z] /system/bin/ls -1A supported
[task 2021-09-14T15:43:55.000Z] Native cp support: True
[task 2021-09-14T15:43:55.019Z] Native chmod -R support: True
[task 2021-09-14T15:43:55.038Z] Native chown -R support: True
[task 2021-09-14T15:43:55.112Z] Native flaky pidof support: True
[task 2021-09-14T15:43:56.478Z] adbd running as root
[task 2021-09-14T15:43:56.478Z] adbd restarted as root
[task 2021-09-14T15:43:56.552Z] Setting SELinux Permissive
[task 2021-09-14T15:43:56.879Z] Setting test_root to /data/local/tmp/test_root
[task 2021-09-14T15:43:58.629Z] 15:43:58     INFO - Found Android bogomips: 5000
[task 2021-09-14T15:43:58.630Z] 15:43:58     INFO - /builds/worker/fetches/android-sdk-linux/platform-tools/adb -s emulator-5554 logcat -v threadtime Trace:S StrictMode:S ExchangeService:S
[task 2021-09-14T15:43:58.806Z] 15:43:58     INFO - verify_device complete
[task 2021-09-14T15:43:58.806Z] 15:43:58     INFO - Running post-action listener: _resource_record_post_action
[task 2021-09-14T15:43:58.806Z] 15:43:58     INFO - [mozharness: 2021-09-14 15:43:58.806346Z] Finished verify-device step (success)
[task 2021-09-14T15:43:58.806Z] 15:43:58     INFO - [mozharness: 2021-09-14 15:43:58.806426Z] Running install step.
[task 2021-09-14T15:43:58.806Z] 15:43:58     INFO - Running pre-action listener: _resource_record_pre_action
[task 2021-09-14T15:43:58.806Z] 15:43:58     INFO - Running main action method: install
[task 2021-09-14T15:44:02.110Z] 15:44:02     INFO - Finished installing apps for emulator-5554
[task 2021-09-14T15:44:02.110Z] 15:44:02     INFO - Running post-action listener: _resource_record_post_action
[task 2021-09-14T15:44:02.110Z] 15:44:02     INFO - [mozharness: 2021-09-14 15:44:02.110407Z] Finished install step (success)
[task 2021-09-14T15:44:02.110Z] 15:44:02     INFO - [mozharness: 2021-09-14 15:44:02.110452Z] Skipping run-tests step.
[task 2021-09-14T15:44:02.110Z] 15:44:02     INFO - Running post-run listener: _resource_record_post_run
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - Total resource usage - Wall time: 32s; CPU: 73%; Read bytes: 0; Write bytes: 2007040; Read time: 0; Write time: 287
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - TinderboxPrint: CPU usage<br/>73.0%
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - TinderboxPrint: I/O read bytes / time<br/>0 / 0
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - TinderboxPrint: I/O write bytes / time<br/>2,007,040 / 287
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - TinderboxPrint: CPU guest<br/>892.1 (22.8%)
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - TinderboxPrint: CPU idle<br/>815.0 (20.8%)
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - TinderboxPrint: CPU system<br/>294.9 (7.5%)
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - TinderboxPrint: CPU user<br/>1,908.7 (48.7%)
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-09-14T15:44:02.190Z] 15:44:02     INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-09-14T15:44:02.194Z] 15:44:02     INFO - verify-device - Wall time: 29s; CPU: 73%; Read bytes: 0; Write bytes: 1982464; Read time: 0; Write time: 285
[task 2021-09-14T15:44:02.195Z] 15:44:02     INFO - install - Wall time: 3s; CPU: 74%; Read bytes: 0; Write bytes: 24576; Read time: 0; Write time: 2
[task 2021-09-14T15:44:02.356Z] 
[task 2021-09-14T15:44:02.356Z] # Run a custom mach command (this is typically used by action tasks to run
[task 2021-09-14T15:44:02.356Z] # harnesses in a particular way)
[task 2021-09-14T15:44:02.356Z] if [ "$CUSTOM_MACH_COMMAND" ]; then
[task 2021-09-14T15:44:02.356Z]     eval "'$WORKSPACE/build/venv/bin/python' '$WORKSPACE/build/tests/mach' ${CUSTOM_MACH_COMMAND} ${@}"
[task 2021-09-14T15:44:02.356Z]     exit $?
[task 2021-09-14T15:44:02.356Z] fi
[task 2021-09-14T15:44:02.356Z] + '[' 'geckoview-junit --log-tbpl=- --log-tbpl-level=info --setpref marionette.log.level=Info ' ']'
[task 2021-09-14T15:44:02.356Z] + eval ''\''/builds/worker/workspace/build/venv/bin/python'\'' '\''/builds/worker/workspace/build/tests/mach'\'' geckoview-junit --log-tbpl=- --log-tbpl-level=info --setpref marionette.log.level=Info  --test-suite=geckoview-junit' --enable-fission --enable-webrender --download-symbols=ondemand --no-run-tests
[task 2021-09-14T15:44:02.356Z] '/builds/worker/workspace/build/venv/bin/python' '/builds/worker/workspace/build/tests/mach' geckoview-junit --log-tbpl=- --log-tbpl-level=info --setpref marionette.log.level=Info  --test-suite=geckoview-junit --enable-fission --enable-webrender --download-symbols=ondemand --no-run-tests
[task 2021-09-14T15:44:02.356Z] ++ /builds/worker/workspace/build/venv/bin/python /builds/worker/workspace/build/tests/mach geckoview-junit --log-tbpl=- --log-tbpl-level=info --setpref marionette.log.level=Info --test-suite=geckoview-junit --enable-fission --enable-webrender --download-symbols=ondemand --no-run-tests
[task 2021-09-14T15:44:02.385Z] Traceback (most recent call last):
[task 2021-09-14T15:44:02.385Z]   File "/builds/worker/workspace/build/tests/mach", line 167, in <module>
[task 2021-09-14T15:44:02.385Z]     main(sys.argv[1:])
[task 2021-09-14T15:44:02.385Z]   File "/builds/worker/workspace/build/tests/mach", line 159, in main
[task 2021-09-14T15:44:02.385Z]     mach = check_and_get_mach(os.path.dirname(os.path.realpath(__file__)))
[task 2021-09-14T15:44:02.385Z]   File "/builds/worker/workspace/build/tests/mach", line 146, in check_and_get_mach
[task 2021-09-14T15:44:02.385Z]     return load_mach(dir_path, mach_path)
[task 2021-09-14T15:44:02.385Z]   File "/builds/worker/workspace/build/tests/mach", line 134, in load_mach
[task 2021-09-14T15:44:02.385Z]     return mach_initialize.initialize(dir_path)
[task 2021-09-14T15:44:02.385Z] AttributeError: module 'mach_initialize' has no attribute 'initialize'
[task 2021-09-14T15:44:02.389Z] cleanup
[task 2021-09-14T15:44:02.389Z] + cleanup
[task 2021-09-14T15:44:02.389Z] + local rv=1
[task 2021-09-14T15:44:02.389Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-09-14T15:44:02.389Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-09-14T15:44:02.392Z] + '[' ']'
[task 2021-09-14T15:44:02.392Z] + true
[task 2021-09-14T15:44:02.392Z] + cleanup_xvfb
[task 2021-09-14T15:44:02.393Z] ++ pidof Xvfb
[task 2021-09-14T15:44:02.399Z] + local xvfb_pid=54
[task 2021-09-14T15:44:02.399Z] + local vnc=false
[task 2021-09-14T15:44:02.399Z] + local interactive=false
[task 2021-09-14T15:44:02.399Z] + '[' -n 54 ']'
[task 2021-09-14T15:44:02.399Z] + [[ false == false ]]
[task 2021-09-14T15:44:02.399Z] + [[ false == false ]]
[task 2021-09-14T15:44:02.399Z] + kill 54
[task 2021-09-14T15:44:02.399Z] + screen -XS xvfb quit
[task 2021-09-14T15:44:02.434Z] + exit 1
[taskcluster 2021-09-14 15:44:03.048Z] === Task Finished ===
[taskcluster 2021-09-14 15:44:06.315Z] Unsuccessful task run with exit code: 1 completed in 142.271 seconds

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

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=366636014&repo=autoland

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

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=376665220&repo=autoland

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

This happens if a "retrigger-custom" test task gets requested from Treeherder:

1. Select task.
2. At the bottom left, click onto the "..."
3. Click onto "Custom Action..."
4. Request the task.

New "...-custom" task runs and fails with this error message.

glob, could your team take a look at this?

Set release status flags based on info from the regressing bug 1717051

Set release status flags based on info from the regressing bug 1717051

I am debugging a test failure which only reproducible on try server.
So I would like to retrigger a test with gecko log enabled to debug via custom action and got the same error.
Is there any workaround that I could enable the gecko log on try server?

I am running into this too, with an interactive task:

[...]
10:02:55     INFO - install - Wall time: 11s; CPU: 50%; Read bytes: 0; Write bytes: 24576; Read time: 0; Write time: 40
10:02:55     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
Mozharness has finished downloading the build and tests to:
/builds/worker/workspace/build
A limited mach environment has also been set up and added to the $PATH, but
it may be missing the command you need. To see a list of commands, run:
    $ mach help
Use the 'run-wizard' command to start this wizard again.
root@7bb12ab96ace:~/workspace/build/tests# mach help
Traceback (most recent call last):
  File "/builds/worker/bin/mach", line 96, in <module>
    main(sys.argv[1:])
  File "/builds/worker/bin/mach", line 88, in main
    mach = check_and_get_mach(os.path.dirname(os.path.realpath(__file__)))
  File "/builds/worker/bin/mach", line 35, in check_and_get_mach
    return load_mach(dir_path, mach_path)
  File "/builds/worker/bin/mach", line 21, in load_mach
    return mach_initialize.initialize(dir_path)
AttributeError: module 'mach_initialize' has no attribute 'initialize'

In the interactive task, it looks like mach attempts to load the mach_initialize module in /builds/worker/workspace/build/tests/tools/mach_initialize.py, which seems to be this file and it only contains a bootstrap function.

Fixing this issue does not make things better, though. The next error is:

root@7bb12ab96ace:~/workspace/build/tests# mach help
Traceback (most recent call last):
  File "/builds/worker/bin/mach", line 101, in <module>
    main(sys.argv[1:])
  File "/builds/worker/bin/mach", line 93, in main
    mach = check_and_get_mach(os.path.dirname(os.path.realpath(__file__)))
  File "/builds/worker/bin/mach", line 40, in check_and_get_mach
    return load_mach(dir_path, mach_path)
  File "/builds/worker/bin/mach", line 26, in load_mach
    return mach_initialize.bootstrap(dir_path)
  File "/builds/worker/workspace/build/tests/tools/mach_initialize.py", line 169, in bootstrap
    import mach.main
  File "/builds/worker/workspace/build/tests/tools/mach/mach/main.py", line 33, in <module>
    from .dispatcher import CommandAction
  File "/builds/worker/workspace/build/tests/tools/mach/mach/dispatcher.py", line 20, in <module>
    from .decorators import SettingsProvider
  File "/builds/worker/workspace/build/tests/tools/mach/mach/decorators.py", line 14, in <module>
    from mozbuild.base import MachCommandBase
ModuleNotFoundError: No module named 'mozbuild'

That seems to be Bug 1515743 or very similar, right?

I ran run-wizard again to checkout gecko and then I ran the following command to install mozbuild:

root@7bb12ab96ace:~/workspace/build/tests# pip install ../../../gecko/python/mozbuild/

That didn't work better so I first made sure to activate the provided venv (I didn't find much docs about interactive tasks to run mochitests so I am flying blind here):

root@7bb12ab96ace:~/workspace/build/tests# source ../venv/bin/activate
(venv) root@7bb12ab96ace:~/workspace/build/tests#

Then I installed all the python packages with the usual try (mach help)/fail/install/repeat. Some packages (starting with moz) were installed from the ../../../gecko/python/. Others from the PyPI registry. Eventually, I got the output below:

(venv) root@7bb12ab96ace:~/workspace/build/tests# mach mochitest browser/components/downloads/test/browser/browser_pdfjs_preview.js
/builds/worker/workspace/build/venv/lib/python3.6/site-packages/requests/__init__.py:91: RequestsDependencyWarning: urllib3 (1.26.13) or chardet (3.0.4) doesn't match 
a supported version!
  RequestsDependencyWarning)
Error running mach:
    ['mochitest', 'browser/components/downloads/test/browser/browser_pdfjs_preview.js']
The error occurred in mach itself. This is likely a bug in mach itself or a
fundamental problem with a loaded module.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file general| to report it. If |./mach busted| is
misbehaving, you can also inspect the dependencies of bug 1543241.
If filing a bug, please include the full output of mach, including this error
message.
The details of the failure are as follows:
TypeError: expected str, bytes or os.PathLike object, not NoneType
  File "/builds/worker/workspace/build/tests/tools/mach/mach/main.py", line 399, in run
    return self._run(argv)
  File "/builds/worker/workspace/build/tests/tools/mach/mach/main.py", line 433, in _run
    topsrcdir = Path(self.populate_context_handler("topdir"))
  File "/usr/lib/python3.6/pathlib.py", line 1001, in __new__
    self = cls._from_parts(args, init=False)
  File "/usr/lib/python3.6/pathlib.py", line 656, in _from_parts
    drv, root, parts = self._parse_args(args)
  File "/usr/lib/python3.6/pathlib.py", line 640, in _parse_args
    a = os.fspath(a)

At least the dependencies were resolved... Fortunately, this error was related to some error reporting (sentry) and we could use a NoopErrorReporter instead.

(venv) root@7bb12ab96ace:~/workspace/build/tests# mach help
/builds/worker/workspace/build/venv/lib/python3.6/site-packages/requests/__init__.py:91: RequestsDependencyWarning: urllib3 (1.26.13) or chardet (3.0.4) doesn't match 
a supported version!
  RequestsDependencyWarning)
usage: mach [global arguments] command [command arguments]
Global Arguments:
  -v, --verbose         Print verbose output.
  -l FILENAME, --log-file FILENAME
                        Filename to write log data to.
  --log-interval        Prefix log line with interval from last message rather
                        than relative time. Note that this is NOT execution
                        time if there are parallel operations.
  --no-interactive      Automatically selects the default option on any
                        interactive prompts. If the output is not a terminal,
                        then --no-interactive is assumed.
  --log-no-times        Do not prefix log lines with times. By default, mach
                        will prefix each output line with the time since
                        command start.
  -h, --help            Show this help message.
  --debug-command       Start a Python debugger when command is dispatched.
  --profile-command     Capture a Python profile of the mach process as
                        command is dispatched.
  --settings FILENAME   Path to settings file.
Testing:
  Run tests.
  geckoview-junit       Run the geckoview-junit harness.
  marionette-test       Run a Marionette test (Check UI or the internal
                        JavaScript using marionette).
  mochitest             Run the mochitest harness.

I then tried to run mach mochitest and it failed, ugh.

A wrong path somewhere that I fixed with a symlink:

(venv) root@7bb12ab96ace:~/workspace/build/tests# ln -s /builds/worker/gecko/ /builds/worker/checkouts/gecko

Then, a missing .mozconfig file:

(venv) root@7bb12ab96ace:~/workspace/build/tests# touch ~/gecko/.mozconfig

Then, a missing shell script when I installed mozbuild manually:

(venv) root@7bb12ab96ace:~/workspace/build/tests# ln -s /builds/worker/gecko/python/mozbuild/mozbuild/mozconfig_loader ../venv/lib/python3.6/site-packages/mozbuild/

Things still didn't work, likely because Bug 1636251 changed a few things around mach's context, especially the populate_context() signature:

-    def populate_context(context, key=None):
+    def populate_context(key=None):

I butchered some more python files to successfully run the mochitest framework but I couldn't run the test file I was interested in... (it ran nothing because it didn't find any tests to run or something like that).

[...]
 0:00.09 INFO Checking for xpcshell processes...
 0:00.39 ERROR No tests were found for flavor 'plain' and the following manifest filters:
skip_if, run_if, fail_if, subsuite(name=None), pathprefix(['browser/browser/components/downloads/test/browser/browser_pdfjs_preview.js'])
Make sure the test paths (if any) are spelt correctly and the corresponding
--flavor and --subsuite are being used. See `mach mochitest --help` for a
list of valid flavors.
 0:00.39 SUITE_START: mochitest-plain - running 0 tests
0 INFO TEST-START | Shutdown
1 INFO Passed:  0
2 INFO Failed:  0
3 INFO Todo:    0
4 INFO Mode:    e10s
5 INFO SimpleTest FINISHED
 0:00.39 INFO Buffered messages finished
 0:00.40 SUITE_END
mochitest-plain
~~~~~~~~~~~~~~~
Ran 0 checks ()
Expected results: 0
Unexpected results: 0
OK

:ahal, any ideas? Maybe mochitests aren't (or are no longer) supported in interactive tasks?

This suggests mach has been busted on test tasks for a while, and I'm not the least surprised, to be honest. That said, interactive tasks for tests are busted in other ways. At least they were when I tried a few weeks ago (without mach, you "just" need to run the commands listed in the test log, or use, I think, option 1 of run-wizard).

Yeah there's an entirely independent mach environment for interactive tasks, and I'm not surprised that it's busted (I would have been more surprised if it just worked out of the box). IIRC, interactive tasks themselves were broken for months or even years due to expired certificates and only fixed relatively recently. I've wondered in the past if we should just remove this whole feature to avoid developers wasting their time, but sounds like you may have made some progress towards getting it working again..

As for the mochitest issue, it looks like the flavor is set to plain (which I guess is the default of that subsuite(None) filter), but you are trying to run a browser-chrome test. Did you initially trigger the interactive task from a browser-chrome task? If so seems like another bug somewhere to be fixed. If not, trying that might get you going.