Closed Bug 1670828 Opened 4 years ago Closed 3 years ago

Fail on `$./mach install` (machBuildFaster FAILED) and `$./mach build faster` when building Firefox

Categories

(Firefox Build System :: Mach Core, defect, P3)

Product:
Firefox Build System
Component:
Mach Core
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: alwu, Unassigned)

References

(Blocks 1 open bug)

Details

I encouter this error when running $./mach install

mozilla-central ./mach install
 0:00.24 adb INFO Using adb 1.0.41
 0:00.89 adb INFO /system/bin/ls -1A supported
 0:01.00 adb INFO Native cp support: True
 0:01.11 adb INFO Native chmod -R support: True
 0:01.22 adb INFO Native chown -R support: True
 0:01.65 adb INFO Native normal pidof support: True
 0:02.07 adb INFO adbd not restarted as root
 0:02.18 adb INFO su -c setenforce 0 exitcode 127, stdout: None
 0:02.82 adb WARNING Unable to set SELinux Permissive due to args: /Users/alastor/.mozbuild/android-sdk-macosx/platform-tools/adb wait-for-device shell setenforce Permissive, exitcode: 1, stdout: setenforce: Couldn't set enforcing status to 'Permissive': Permission denied.
 0:04.31 adb INFO Setting test_root to /data/local/tmp/test_root
It looks like org.mozilla.geckoview_example is not installed on this device.
Installing geckoview_example...
 0:06.23 /Users/alastor/mozilla-dev/mozilla-central/gradlew geckoview_example:installWithGeckoBinariesDebug geckoview:installWithGeckoBinariesDebugAndroidTest
Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=utf-8

> Task :machBuildFaster
Executing task :machBuildFaster
:machBuildFaster>  0:02.20 /usr/bin/make -C faster -j8 -s
:machBuildFaster>  0:02.94 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin/gmp-fakeopenh264/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
:machBuildFaster>  0:02.95 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin/gmp-fake/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
:machBuildFaster>  0:03.00 Elapsed: 0.06s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin/localization: Kept 49 existing; Added/updated 0; Removed 0 files and 0 directories.
:machBuildFaster>  0:03.03 Elapsed: 0.09s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin/gmp-clearkey/0.1: Kept 0 existing; Added/updated 1; Removed 0 files and 0 directories.
:machBuildFaster>  0:03.95 Elapsed: 0.81s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin: Kept 1791 existing; Added/updated 29; Removed 0 files and 0 directories.
:machBuildFaster>  0:05.54  0:01.58 /Users/alastor/mozilla-dev/mozilla-central/gradlew geckoview:generateJNIWrappersForGeneratedWithGeckoBinariesDebug -x lint
:machBuildFaster>  0:05.63 Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=utf-8
:machBuildFaster>  0:06.39 Starting a Gradle Daemon, 1 busy Daemon could not be reused, use --status for details
:machBuildFaster>  0:22.59 > Task :geckoview:preBuild UP-TO-DATE
:machBuildFaster>  0:22.59 > Task :geckoview:preWithGeckoBinariesDebugBuild UP-TO-DATE
:machBuildFaster>  0:22.79 > Task :annotations:compileJava UP-TO-DATE
:machBuildFaster>  0:22.79 > Task :annotations:processResources NO-SOURCE
:machBuildFaster>  0:22.79 > Task :annotations:classes UP-TO-DATE
:machBuildFaster>  0:22.89 > Task :annotations:jar UP-TO-DATE
:machBuildFaster>  0:22.99 > Task :geckoview:compileWithGeckoBinariesDebugAidl UP-TO-DATE
:machBuildFaster>  0:22.99 > Task :geckoview:compileWithGeckoBinariesDebugRenderscript NO-SOURCE
:machBuildFaster>  0:22.99 > Task :geckoview:checkWithGeckoBinariesDebugManifest UP-TO-DATE
:machBuildFaster>  0:22.99 > Task :geckoview:generateWithGeckoBinariesDebugBuildConfig UP-TO-DATE
:machBuildFaster>  0:22.99 > Task :geckoview:generateWithGeckoBinariesDebugResValues UP-TO-DATE
:machBuildFaster>  0:22.99 > Task :geckoview:generateWithGeckoBinariesDebugResources UP-TO-DATE
:machBuildFaster>  0:23.09 > Task :geckoview:packageWithGeckoBinariesDebugResources UP-TO-DATE
:machBuildFaster>  0:23.09 > Task :geckoview:processWithGeckoBinariesDebugManifest UP-TO-DATE
:machBuildFaster>  0:23.19 > Task :geckoview:generateWithGeckoBinariesDebugRFile UP-TO-DATE
:machBuildFaster>  0:23.89 > Task :geckoview:compileWithGeckoBinariesDebugKotlin UP-TO-DATE
:machBuildFaster>  0:23.89 > Task :geckoview:prepareLintJar UP-TO-DATE
:machBuildFaster>  0:23.89 > Task :geckoview:generateWithGeckoBinariesDebugSources UP-TO-DATE
:machBuildFaster>  0:23.89 > Task :geckoview:javaPreCompileWithGeckoBinariesDebug UP-TO-DATE
:machBuildFaster>  0:24.29 > Task :geckoview:compileWithGeckoBinariesDebugJavaWithJavac UP-TO-DATE
:machBuildFaster>  0:24.29 > Task :geckoview:bundleLibRuntimeWithGeckoBinariesDebug UP-TO-DATE
:machBuildFaster>  0:24.29 > Task :geckoview:generateJNIWrappersForGeneratedWithGeckoBinariesDebug UP-TO-DATE
:machBuildFaster>  0:24.39 Deprecated Gradle features were used in this build, making it incompatible with Gradle 6.0.
:machBuildFaster>  0:24.39 Use '--warning-mode all' to show the individual deprecation warnings.
:machBuildFaster>  0:24.39 See https://docs.gradle.org/5.1.1/userguide/command_line_interface.html#sec:command_line_warnings
:machBuildFaster>  0:24.39 BUILD SUCCESSFUL in 18s
:machBuildFaster>  0:24.39 15 actionable tasks: 15 up-to-date
:machBuildFaster>  0:24.88 462 compiler warnings present.
:machBuildFaster> Error running mach:
:machBuildFaster>
:machBuildFaster>     ['build', 'faster']
:machBuildFaster>
:machBuildFaster> The error occurred in code that was called by the mach command. This is either
:machBuildFaster> a bug in the called code itself or in the way that mach is calling it.
:machBuildFaster> You can invoke |./mach busted| to check if this issue is already on file. If it
:machBuildFaster> isn't, please use |./mach busted file build| to report it. If |./mach busted| is
:machBuildFaster> misbehaving, you can also inspect the dependencies of bug 1543241.
:machBuildFaster>
:machBuildFaster> If filing a bug, please include the full output of mach, including this error
:machBuildFaster> message.
:machBuildFaster>
:machBuildFaster> The details of the failure are as follows:
:machBuildFaster>
:machBuildFaster> AssertionError
:machBuildFaster>
:machBuildFaster>   File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
:machBuildFaster>     return driver.build(
:machBuildFaster>   File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1252, in build
:machBuildFaster>     monitor.finish(record_usage=record_usage)
:machBuildFaster>   File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 729, in __exit__
:machBuildFaster>     self.monitor.stop_resource_recording()
:machBuildFaster>   File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
:machBuildFaster>     self.resources.stop()
:machBuildFaster>   File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 314, in stop
:machBuildFaster>     assert self._running
:machBuildFaster> Sentry is attempting to send 0 pending error messages
:machBuildFaster> Waiting up to 2 seconds
:machBuildFaster> Press Ctrl-C to quit

> Task :machBuildFaster FAILED

FAILURE: Build failed with an exception.

* What went wrong:
Execution failed for task ':machBuildFaster'.
> Process 'command '/Users/alastor/mozilla-dev/mozilla-central/objdir-android/_virtualenvs/init_py3/bin/python'' finished with non-zero exit value 1

* Try:
Run with --stacktrace option to get the stack trace. Run with --info or --debug option to get more log output. Run with --scan to get full insights.

* Get more help at https://help.gradle.org

Deprecated Gradle features were used in this build, making it incompatible with Gradle 6.0.
Use '--warning-mode all' to show the individual deprecation warnings.
See https://docs.gradle.org/5.1.1/userguide/command_line_interface.html#sec:command_line_warnings

BUILD FAILED in 31s
58 actionable tasks: 1 executed, 57 up-to-date
Execute `mach android build-geckoview_example` to just build the geckoview_example and test APKs.
 0:36.52 adb INFO Setting run_as_package to org.mozilla.geckoview_example
Error running mach:

    ['install']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file install| 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:

mozdevice.adb.ADBError: run_as_package org.mozilla.geckoview_example is not installed.

  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/mach_commands.py", line 727, in install
    ret = verify_android_device(self, install=InstallIntent.YES, **kwargs) == 0
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozrunner/mozrunner/devices/android_device.py", line 277, in verify_android_device
    device.run_as_package = app
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozdevice/mozdevice/adb.py", line 1211, in run_as_package
    raise ADBError('run_as_package %s is not installed.' % value)
Sentry is attempting to send 0 pending error messages
Waiting up to 2 seconds
Press Ctrl-C to quit

In addition, when running $./mach build faster, I also got an error, which might be related.

➜  mozilla-central ./mach build faster
 0:01.99 /usr/bin/make -C faster -j8 -s
 0:02.52 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin/gmp-fakeopenh264/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.53 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin/gmp-fake/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.58 Elapsed: 0.05s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin/localization: Kept 49 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.62 Elapsed: 0.10s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin/gmp-clearkey/0.1: Kept 0 existing; Added/updated 1; Removed 0 files and 0 directories.
 0:03.41 Elapsed: 0.68s; From /Users/alastor/mozilla-dev/mozilla-central/objdir-android/dist/bin: Kept 1791 existing; Added/updated 29; Removed 0 files and 0 directories.
 0:05.16  0:01.59 /Users/alastor/mozilla-dev/mozilla-central/gradlew geckoview:generateJNIWrappersForGeneratedWithGeckoBinariesDebug -x lint
 0:05.22 Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=utf-8
 0:09.15 > Task :geckoview:preBuild UP-TO-DATE
 0:09.15 > Task :geckoview:preWithGeckoBinariesDebugBuild UP-TO-DATE
 0:09.24 > Task :annotations:compileJava UP-TO-DATE
 0:09.24 > Task :annotations:processResources NO-SOURCE
 0:09.24 > Task :annotations:classes UP-TO-DATE
 0:09.24 > Task :annotations:jar UP-TO-DATE
 0:09.34 > Task :geckoview:compileWithGeckoBinariesDebugAidl UP-TO-DATE
 0:09.34 > Task :geckoview:compileWithGeckoBinariesDebugRenderscript NO-SOURCE
 0:09.34 > Task :geckoview:checkWithGeckoBinariesDebugManifest UP-TO-DATE
 0:09.34 > Task :geckoview:generateWithGeckoBinariesDebugBuildConfig UP-TO-DATE
 0:09.34 > Task :geckoview:generateWithGeckoBinariesDebugResValues UP-TO-DATE
 0:09.35 > Task :geckoview:generateWithGeckoBinariesDebugResources UP-TO-DATE
 0:09.35 > Task :geckoview:packageWithGeckoBinariesDebugResources UP-TO-DATE
 0:09.35 > Task :geckoview:processWithGeckoBinariesDebugManifest UP-TO-DATE
 0:09.44 > Task :geckoview:generateWithGeckoBinariesDebugRFile UP-TO-DATE
 0:09.54 > Task :geckoview:compileWithGeckoBinariesDebugKotlin UP-TO-DATE
 0:09.54 > Task :geckoview:prepareLintJar UP-TO-DATE
 0:09.54 > Task :geckoview:generateWithGeckoBinariesDebugSources UP-TO-DATE
 0:09.54 > Task :geckoview:javaPreCompileWithGeckoBinariesDebug UP-TO-DATE
 0:09.64 > Task :geckoview:compileWithGeckoBinariesDebugJavaWithJavac UP-TO-DATE
 0:09.64 > Task :geckoview:bundleLibRuntimeWithGeckoBinariesDebug UP-TO-DATE
 0:09.64 > Task :geckoview:generateJNIWrappersForGeneratedWithGeckoBinariesDebug UP-TO-DATE
 0:09.64 Deprecated Gradle features were used in this build, making it incompatible with Gradle 6.0.
 0:09.65 Use '--warning-mode all' to show the individual deprecation warnings.
 0:09.65 See https://docs.gradle.org/5.1.1/userguide/command_line_interface.html#sec:command_line_warnings
 0:09.65 BUILD SUCCESSFUL in 4s
 0:09.65 15 actionable tasks: 15 up-to-date
 0:10.07 462 compiler warnings present.
Error running mach:

    ['build', 'faster']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file build| 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:

AssertionError

  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1252, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 729, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 314, in stop
    assert self._running

Note. both commands are failing on assert self._running in resourcemonitor.py", line 314, in stop.

Component: General → Android Studio and Gradle Integration

My guess is that this is fallout from Bug 1666345, since psutil is what backs the resource monitor implementation.

alwu: is this reproducible with newer checkouts, etc? Does ./mach build faster succeed for you? I wonder if we have a re-entrancy issue.

Flags: needinfo?(alwu)

Bug 1666345 isn't closed, it wouldn't have any effect on this.

I found out this not related with Android build, now I encouter same issue when buillding desktop firefox.

I'm using MacOS 10.14.4 and my m-c is based on the changeset 555853:59aa8258be15, which is from Oct 12.

Yes, I can't even use ./mach build faster.

Component: Android Studio and Gradle Integration → General
Flags: needinfo?(alwu)
Summary: Fail on `$./mach install` (machBuildFaster FAILED) and `$./mach build faster` when building Firefox Android → Fail on `$./mach install` (machBuildFaster FAILED) and `$./mach build faster` when building Firefox

In addition, I've run ./mach bootstrap already, but it didn't help.

Note that if you're hitting this assertion, your build is finished.

Oh, but in the case of gradle, it may stop running other things. For desktop builds, it's less of a problem.

(In reply to Alastor Wu [:alwu] from comment #4)

I found out this not related with Android build, now I encouter same issue when buillding desktop firefox.

I'm using MacOS 10.14.4 and my m-c is based on the changeset 555853:59aa8258be15, which is from Oct 12.

Yes, I can't even use ./mach build faster.

Can you also post the logs from your desktop Firefox build? I can only assume that if you're encountering an issue it must be manifesting in an extremely different way, since the desktop build doesn't require any of the Android/gradle stuff that's been mentioned.

Flags: needinfo?(alwu)
Severity: -- → S3
Priority: -- → P3

Log are almost the same as what I posted in comment0, here is the result of running ./mach build faster

98:49.16 ./reserved-js-words.js.stub
98:49.16 ./spidermonkey_checks.stub
98:49.16 ./css_properties.js.stub
98:49.16 ./fake_remote_dafsa.bin.stub
98:49.17 ./collection_signing_root.pem.stub
98:49.17 ./collection_signing_int.pem.stub
98:49.17 ./collection_signing_ee.pem.stub
98:49.17 ./feature_definitions.json.stub
98:49.17 ./normandydriver-a-1.0.xpi.stub
98:49.17 ./normandydriver-b-1.0.xpi.stub
98:49.17 ./normandydriver-a-2.0.xpi.stub
98:49.17 ./ScalarArtifactDefinitions.json.stub
98:49.17 ./EventArtifactDefinitions.json.stub
98:49.17 ./glean_checks.stub
98:49.17 ./dependentlibs.list.stub
98:49.20 ./multilocale.txt.stub
98:49.20 ./built_in_addons.json.stub
98:49.20 ./browser_dragdrop1.xpi.stub
98:49.21 ./browser_dragdrop1.zip.stub
98:49.21 ./browser_dragdrop2.xpi.stub
98:49.21 ./browser_dragdrop2.zip.stub
98:49.21 ./browser_dragdrop_incompat.xpi.stub
98:49.21 ./browser_dragdrop_incompat.zip.stub
98:49.21 ./browser_installssl.xpi.stub
98:49.21 ./browser_installssl.zip.stub
98:49.21 ./browser_theme.xpi.stub
98:49.36 ./browser_theme.zip.stub
98:49.36 ./options_signed.xpi.stub
98:49.36 ./options_signed.zip.stub
98:49.36 TEST-PASS | check_spidermonkey_style.py | ok
98:49.36 Sorry, Glean found some glinter nits:
98:49.36 WARNING: USER_LIFETIME_EXPIRATION: geckoview.build_id: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.36 WARNING: USER_LIFETIME_EXPIRATION: geckoview.version: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.description: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.device_id: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.driver_date: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.driver_files: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.driver_vendor: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.driver_version: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.ram: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.40 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.subsystem_id: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.40 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.vendor_id: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.40 WARNING: USER_LIFETIME_EXPIRATION: gfx.display.count: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 WARNING: USER_LIFETIME_EXPIRATION: gfx.display.primary_height: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 WARNING: USER_LIFETIME_EXPIRATION: gfx.display.primary_width: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 WARNING: USER_LIFETIME_EXPIRATION: gfx.status.compositor: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 WARNING: USER_LIFETIME_EXPIRATION: gfx.status.headless: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 Please fix the above nits to continue.
98:49.41 To disable a check, add a `no_lint` parameter with a list of check names to disable.
98:49.41 This parameter can appear with each individual metric, or at the top-level to affect the entire file.
98:49.42 TEST-PASS | check_macroassembler_style.py | ok
98:49.42 browser/locales/updater.ini.stub
98:49.42 browser/locales/bookmarks.html.stub
98:49.42 TEST-PASS | check_js_opcode.py | ok
98:49.42 toolkit/locales/update.locale.stub
98:49.42 toolkit/locales/locale.ini.stub
98:50.69 Packaging specialpowers@mozilla.org.xpi...
98:50.97 Packaging quitter@mozilla.org.xpi...
98:54.21 Packaging mozscreenshots@mozilla.org.xpi...
98:54.44 591 compiler warnings present.
Error running mach:

    ['build']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file build| 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:

AssertionError

  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1252, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 729, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 314, in stop
    assert self._running
Flags: needinfo?(alwu)

(In reply to Alastor Wu [:alwu] from comment #9)

Log are almost the same as what I posted in comment0, here is the result of running ./mach build faster

98:49.16 ./reserved-js-words.js.stub
98:49.16 ./spidermonkey_checks.stub
98:49.16 ./css_properties.js.stub
98:49.16 ./fake_remote_dafsa.bin.stub
98:49.17 ./collection_signing_root.pem.stub
98:49.17 ./collection_signing_int.pem.stub
98:49.17 ./collection_signing_ee.pem.stub
98:49.17 ./feature_definitions.json.stub
98:49.17 ./normandydriver-a-1.0.xpi.stub
98:49.17 ./normandydriver-b-1.0.xpi.stub
98:49.17 ./normandydriver-a-2.0.xpi.stub
98:49.17 ./ScalarArtifactDefinitions.json.stub
98:49.17 ./EventArtifactDefinitions.json.stub
98:49.17 ./glean_checks.stub
98:49.17 ./dependentlibs.list.stub
98:49.20 ./multilocale.txt.stub
98:49.20 ./built_in_addons.json.stub
98:49.20 ./browser_dragdrop1.xpi.stub
98:49.21 ./browser_dragdrop1.zip.stub
98:49.21 ./browser_dragdrop2.xpi.stub
98:49.21 ./browser_dragdrop2.zip.stub
98:49.21 ./browser_dragdrop_incompat.xpi.stub
98:49.21 ./browser_dragdrop_incompat.zip.stub
98:49.21 ./browser_installssl.xpi.stub
98:49.21 ./browser_installssl.zip.stub
98:49.21 ./browser_theme.xpi.stub
98:49.36 ./browser_theme.zip.stub
98:49.36 ./options_signed.xpi.stub
98:49.36 ./options_signed.zip.stub
98:49.36 TEST-PASS | check_spidermonkey_style.py | ok
98:49.36 Sorry, Glean found some glinter nits:
98:49.36 WARNING: USER_LIFETIME_EXPIRATION: geckoview.build_id: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.36 WARNING: USER_LIFETIME_EXPIRATION: geckoview.version: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.description: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.device_id: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.driver_date: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.driver_files: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.driver_vendor: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.driver_version: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.37 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.ram: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.40 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.subsystem_id: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.40 WARNING: USER_LIFETIME_EXPIRATION: gfx.adapter.primary.vendor_id: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.40 WARNING: USER_LIFETIME_EXPIRATION: gfx.display.count: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 WARNING: USER_LIFETIME_EXPIRATION: gfx.display.primary_height: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 WARNING: USER_LIFETIME_EXPIRATION: gfx.display.primary_width: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 WARNING: USER_LIFETIME_EXPIRATION: gfx.status.compositor: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 WARNING: USER_LIFETIME_EXPIRATION: gfx.status.headless: Metrics with 'user' lifetime cannot have an expiration date. They live as long as the user profile does. Set expires to 'never'.
98:49.41 Please fix the above nits to continue.
98:49.41 To disable a check, add a `no_lint` parameter with a list of check names to disable.
98:49.41 This parameter can appear with each individual metric, or at the top-level to affect the entire file.
98:49.42 TEST-PASS | check_macroassembler_style.py | ok
98:49.42 browser/locales/updater.ini.stub
98:49.42 browser/locales/bookmarks.html.stub
98:49.42 TEST-PASS | check_js_opcode.py | ok
98:49.42 toolkit/locales/update.locale.stub
98:49.42 toolkit/locales/locale.ini.stub
98:50.69 Packaging specialpowers@mozilla.org.xpi...
98:50.97 Packaging quitter@mozilla.org.xpi...
98:54.21 Packaging mozscreenshots@mozilla.org.xpi...
98:54.44 591 compiler warnings present.
Error running mach:

    ['build']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file build| 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:

AssertionError

  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1252, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 729, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 314, in stop
    assert self._running

Can you paste the entire unabridged output? I have no way of knowing whether the logs contain other information that is relevant.

Flags: needinfo?(alwu)

The full log is actully very short, here is the log when I run ./mach build faster.

➜  mozilla-central ./mach build faster
 0:04.81 /usr/bin/make -C faster -j8 -s
 0:05.16 Elapsed: 0.01s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/features/webcompat-reporter@mozilla.org: Kept 1 existing; Added/updated 2; Removed 0 files and 0 directories.
 0:05.16 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-fake/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:05.16 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-fakeopenh264/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:05.18 Elapsed: 0.03s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/features/formautofill@mozilla.org: Kept 52 existing; Added/updated 2; Removed 0 files and 0 directories.
 0:05.19 Elapsed: 0.03s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/localization: Kept 76 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:05.22 Elapsed: 0.07s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-clearkey/0.1: Kept 0 existing; Added/updated 1; Removed 0 files and 0 directories.
 0:05.31 Elapsed: 0.02s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/localization: Kept 48 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:06.22 Elapsed: 0.55s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin: Kept 1709 existing; Added/updated 41; Removed 0 files and 0 directories.
 0:06.31 Elapsed: 1.16s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser: Kept 3851 existing; Added/updated 43; Removed 0 files and 0 directories.
 0:08.71 374 compiler warnings present.
Error running mach:

    ['build', 'faster']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file build| 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:

AssertionError

  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1252, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 729, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-d
Flags: needinfo?(alwu)

I'll update my codebase and run the bootstrap again, to see if it would help.

Still encountered the same issue.

I can't reproduce. What's in your mozconfig?

If you want, feel free to apply the following patch so we can see where and how often these functions are getting called to try to debug. Beware that this is printf debugging :)

diff --git a/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py b/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
index 17e01ba6fdfe..6f7b3b3acef1 100644
--- a/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
+++ b/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
@@ -8,6 +8,7 @@ from contextlib import contextmanager
 import multiprocessing
 import sys
 import time
+import traceback
 import warnings
 
 from collections import (
@@ -296,6 +297,7 @@ class SystemResourceMonitor(object):
         if not self._process:
             return
 
+        traceback.print_stack()
         self._running = True
         self._process.start()
 
@@ -311,6 +313,7 @@ class SystemResourceMonitor(object):
             self._stopped = True
             return
 
+        traceback.print_stack()
         assert self._running
         assert not self._stopped
Flags: needinfo?(alwu)

Here is my .mozconfig and the printed stack after applying diff from comment14, thank you so much.

mk_add_options AUTOCLOBBER=1

ac_add_options --with-ccache=/usr/local/bin/ccache
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-debug-@CONFIG_GUESS@

# debug build
ac_add_options --enable-debug-symbols
ac_add_options --enable-debug

➜  mozilla-central ./mach build faster
  File "./mach", line 267, in <module>
    main(sys.argv[1:])
  File "./mach", line 263, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1069, in build
    monitor.start_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 256, in start_resource_recording
    self.resources.start()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 300, in start
    traceback.print_stack()
 0:01.85 /usr/bin/make -C faster -j8 -s
 0:02.27 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-fakeopenh264/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.27 Elapsed: 0.01s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/features/webcompat-reporter@mozilla.org: Kept 1 existing; Added/updated 2; Removed 0 files and 0 directories.
 0:02.28 Elapsed: 0.01s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-fake/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.30 Elapsed: 0.03s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/features/formautofill@mozilla.org: Kept 52 existing; Added/updated 2; Removed 0 files and 0 directories.
 0:02.32 Elapsed: 0.04s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/localization: Kept 76 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.35 Elapsed: 0.08s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-clearkey/0.1: Kept 0 existing; Added/updated 1; Removed 0 files and 0 directories.
 0:02.40 Elapsed: 0.02s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/localization: Kept 48 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:03.44 Elapsed: 0.58s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin: Kept 1709 existing; Added/updated 41; Removed 1 files and 0 directories.
 0:03.56 Elapsed: 1.29s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser: Kept 3855 existing; Added/updated 42; Removed 1 files and 0 directories.
 0:06.20 374 compiler warnings present.
  File "./mach", line 267, in <module>
    main(sys.argv[1:])
  File "./mach", line 263, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1252, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 336, in finish
    self.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 316, in stop
    traceback.print_stack()
  File "./mach", line 267, in <module>
    main(sys.argv[1:])
  File "./mach", line 263, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1252, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 729, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 316, in stop
    traceback.print_stack()
Error running mach:

    ['build', 'faster']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file build| 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:

AssertionError

  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1252, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 729, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 317, in stop
    assert self._running
Sentry is attempting to send 0 pending error messages
Flags: needinfo?(alwu)

Hmm. Unfortunately this makes very little sense to me. :( The if self._resources_started: check in stop_resource_recording() is supposed to guard against this happening, and we're going through that function in both of the instances here. So I'm not sure what could be going wrong.

First of all, update to the latest central, because you're definitely at least one day behind. Hopefully that improves things. If not, try this patch and let me know what the output is. (Sorry, we're still in printf debugging mode.) I'm sanity-checking some invariants here.

diff --git a/python/mozbuild/mozbuild/controller/building.py b/python/mozbuild/mozbuild/controller/building.py
index fe807306db77..b9740fc7a011 100644
--- a/python/mozbuild/mozbuild/controller/building.py
+++ b/python/mozbuild/mozbuild/controller/building.py
@@ -324,10 +324,15 @@ class BuildMonitor(MozbuildObject):
         return BuildOutputResult(warning, False, message)
 
     def stop_resource_recording(self):
+        print('Before: self._resources_started = %s, self.resources._running = %s' % (
+            self._resources_started, self.resources._running))
         if self._resources_started:
             self.resources.stop()
 
         self._resources_started = False
+        print('After: self._resources_started = %s, self.resources._running = %s' % (
+            self._resources_started, self.resources._running))
+
 
     def finish(self, record_usage=True):
         """Record the end of the build."""
diff --git a/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py b/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
index 17e01ba6fdfe..6f7b3b3acef1 100644
--- a/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
+++ b/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
@@ -8,6 +8,7 @@ from contextlib import contextmanager
 import multiprocessing
 import sys
 import time
+import traceback
 import warnings
 
 from collections import (
@@ -296,6 +297,7 @@ class SystemResourceMonitor(object):
         if not self._process:
             return
 
+        traceback.print_stack()
         self._running = True
         self._process.start()
 
@@ -311,6 +313,7 @@ class SystemResourceMonitor(object):
             self._stopped = True
             return
 
+        traceback.print_stack()
         assert self._running
         assert not self._stopped

Here is my printed result, thank you. (BTW, I've updated to the latest m-c)

➜  mozilla-central ./mach build faster
  File "./mach", line 260, in <module>
    main(sys.argv[1:])
  File "./mach", line 256, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1072, in build
    monitor.start_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 254, in start_resource_recording
    self.resources.start()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 300, in start
    traceback.print_stack()
 0:01.88 /usr/bin/make -C faster -j8 -s
 0:02.38 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/features/webcompat-reporter@mozilla.org: Kept 1 existing; Added/updated 2; Removed 0 files and 0 directories.
 0:02.40 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-fake/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.42 Elapsed: 0.03s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/features/formautofill@mozilla.org: Kept 52 existing; Added/updated 2; Removed 0 files and 0 directories.
 0:02.43 Elapsed: 0.05s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/localization: Kept 76 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.46 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-fakeopenh264/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.47 Elapsed: 0.09s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-clearkey/0.1: Kept 0 existing; Added/updated 1; Removed 0 files and 0 directories.
 0:02.48 Elapsed: 0.03s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/localization: Kept 48 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:03.66 Elapsed: 0.68s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin: Kept 1707 existing; Added/updated 41; Removed 2 files and 0 directories.
 0:03.68 Elapsed: 1.38s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser: Kept 3857 existing; Added/updated 47; Removed 2 files and 0 directories.
 0:06.56 156 compiler warnings present.
Before: self._resources_started = True, self.resources._running = True
  File "./mach", line 260, in <module>
    main(sys.argv[1:])
  File "./mach", line 256, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1255, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 339, in finish
    self.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 316, in stop
    traceback.print_stack()
Before: self._resources_started = True, self.resources._running = False
  File "./mach", line 260, in <module>
    main(sys.argv[1:])
  File "./mach", line 256, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1255, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 732, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 316, in stop
    traceback.print_stack()
Error running mach:

    ['build', 'faster']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file build| 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:

AssertionError

  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1255, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 732, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 317, in stop
    assert self._running
Sentry is attempting to send 0 pending error messages
Waiting up to 2 seconds
Press Ctrl-C to quit
➜  mozilla-central

Okay. So you're not seeing the After: lines that I printed. So I think the code isn't getting to that point. I wonder if it's throwing an exception in stop() in resourcemonitor.py, and then encountering that error when it's trying to clean up.

Try this. It'll swallow that error and (hopefully, maybe) show the real, underlying error.

diff --git a/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py b/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
index 17e01ba6fdfe..934fd590813f 100644
--- a/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
+++ b/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
@@ -311,8 +311,8 @@ class SystemResourceMonitor(object):
             self._stopped = True
             return
 
-        assert self._running
-        assert not self._stopped
+        if not self._running:
+            return
 
         try:
             self._pipe.send(('terminate',))
Flags: needinfo?(alwu)

Still the same :( here is the log.

➜  mozilla-central ./mach build faster
  File "./mach", line 260, in <module>
    main(sys.argv[1:])
  File "./mach", line 256, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1072, in build
    monitor.start_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 254, in start_resource_recording
    self.resources.start()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 300, in start
    traceback.print_stack()
 0:01.77 /usr/bin/make -C faster -j8 -s
 0:02.25 Elapsed: 0.00s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-fake/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.25 Elapsed: 0.01s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/features/webcompat-reporter@mozilla.org: Kept 1 existing; Added/updated 2; Removed 0 files and 0 directories.
 0:02.26 Elapsed: 0.01s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-fakeopenh264/1.0: Kept 1 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.28 Elapsed: 0.04s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/features/formautofill@mozilla.org: Kept 52 existing; Added/updated 2; Removed 0 files and 0 directories.
 0:02.30 Elapsed: 0.05s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser/localization: Kept 76 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.30 Elapsed: 0.03s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/localization: Kept 48 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.34 Elapsed: 0.08s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/gmp-clearkey/0.1: Kept 0 existing; Added/updated 1; Removed 0 files and 0 directories.
 0:03.41 Elapsed: 0.55s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin: Kept 1707 existing; Added/updated 41; Removed 0 files and 0 directories.
 0:03.54 Elapsed: 1.30s; From /Users/alastor/mozilla-dev/mozilla-central/obj-debug-x86_64-apple-darwin18.5.0/dist/bin/browser: Kept 3862 existing; Added/updated 42; Removed 0 files and 0 directories.
 0:06.16 156 compiler warnings present.
Before: self._resources_started = True, self.resources._running = True
  File "./mach", line 260, in <module>
    main(sys.argv[1:])
  File "./mach", line 256, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1255, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 339, in finish
    self.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 316, in stop
    traceback.print_stack()
Before: self._resources_started = True, self.resources._running = False
  File "./mach", line 260, in <module>
    main(sys.argv[1:])
  File "./mach", line 256, in main
    sys.exit(mach.run(args))
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 363, in run
    return self._run(argv, sentry)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/main.py", line 462, in _run
    return Registrar._run_command_handler(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mach/mach/registrar.py", line 101, in _run_command_handler
    result = fn(**kwargs)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1255, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 732, in __exit__
    self.monitor.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 316, in stop
    traceback.print_stack()
After: self._resources_started = False, self.resources._running = False
Error running mach:

    ['build', 'faster']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file build| 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: __new__() takes 9 positional arguments but 10 were given

  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/build_commands.py", line 125, in build
    return driver.build(
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 1255, in build
    monitor.finish(record_usage=record_usage)
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 339, in finish
    self.stop_resource_recording()
  File "/Users/alastor/mozilla-dev/mozilla-central/python/mozbuild/mozbuild/controller/building.py", line 330, in stop_resource_recording
    self.resources.stop()
  File "/Users/alastor/mozilla-dev/mozilla-central/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py", line 348, in stop
    virt = self._virt_type(*virt_mem)
Sentry is attempting to send 0 pending error messages
Waiting up to 2 seconds
Press Ctrl-C to quit
➜  mozilla-central
Flags: needinfo?(alwu)

Oh. That's interesting. Do you have MACH_USE_SYSTEM_PYTHON set?

If not, can you do the following and copy-paste the results?

./mach python -c 'import psutil; virt = psutil.virtual_memory(); print(virt); print(len([v for v in virt]))'
./mach python -c 'import psutil; help(type(psutil.virtual_memory()))'
Flags: needinfo?(alwu)

It sounds like maybe I have a weird python enviroment...? When I type python, it shows the version is 3.8.6, which is equal to the version shown in pyenv.

In addition, I tried to add mk_add_options MACH_USE_SYSTEM_PYTHON=1 in my .mozconfig but it didn't work. Thank you so much.

➜  mozilla-central ./mach python -c 'import psutil; virt = psutil.virtual_memory(); print(virt); print(len([v for v in virt]))'
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/__init__.py", line 161, in <module>
    from . import _psosx as _psplatform
  File "/Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/_psosx.py", line 15, in <module>
    from . import _psutil_osx as cext
ImportError: dlopen(/Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/_psutil_osx.cpython-38-darwin.so, 2): Symbol not found: _kIOMasterPortDefault
  Referenced from: /Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/_psutil_osx.cpython-38-darwin.so
  Expected in: flat namespace
 in /Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/_psutil_osx.cpython-38-darwin.so

➜  mozilla-central ./mach python -c 'import psutil; help(type(psutil.virtual_memory()))'
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/__init__.py", line 161, in <module>
    from . import _psosx as _psplatform
  File "/Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/_psosx.py", line 15, in <module>
    from . import _psutil_osx as cext
ImportError: dlopen(/Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/_psutil_osx.cpython-38-darwin.so, 2): Symbol not found: _kIOMasterPortDefault
  Referenced from: /Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/_psutil_osx.cpython-38-darwin.so
  Expected in: flat namespace
 in /Users/alastor/mozilla-dev/mozilla-central/third_party/python/psutil/psutil/_psutil_osx.cpython-38-darwin.so
Flags: needinfo?(alwu)

Okay. That's the root cause. You had trouble compiling the native code in the psutil Python package and now it can't import the package without failing.

Can you try patching in https://phabricator.services.mozilla.com/D90914, then re-run mach bootstrap, and see if that fixes things? (This patch will eventually land in central, it's just blocked on some work other people are doing now.)

Okay, I'm building them now, will update the result later. Thank you.

Thank you, it works! hoping the fix can land on m-c soon :)

The Bugbug bot thinks this bug should belong to the 'Firefox Build System::Mach Core' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Component: General → Mach Core

Sounds like this is fixed, closing the ticket 👍

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.