Closed Bug 1630429 Opened 5 years ago Closed 4 years ago

Mozharness in generate profile tasks does not set the MINIDUMP_STACKWALK environment variable

Categories

(Testing :: General, defect, P5)

defect

Tracking

(firefox78 fixed)

RESOLVED FIXED
mozilla78
Tracking Status
firefox78 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: gbrown)

Details

(Whiteboard: dev-prod-2020)

Attachments

(1 file)

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


[task 2020-04-15T20:21:02.568Z] 20:21:02 INFO - Native pidof support: False
[task 2020-04-15T20:21:02.980Z] 20:21:02 INFO - New mozdevice with adb=/builds/worker/workspace/build/android-sdk-linux/platform-tools/adb, device=emulator-5554
[task 2020-04-15T20:21:03.402Z] 20:21:03 INFO - Found Android bogomips: 599
[task 2020-04-15T20:21:03.402Z] 20:21:03 INFO - /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb -s emulator-5554 logcat -v threadtime Trace:S StrictMode:S ExchangeService:S
[task 2020-04-15T20:21:03.918Z] 20:21:03 INFO - verify_device complete
[task 2020-04-15T20:21:03.919Z] 20:21:03 INFO - Running post-action listener: resource_record_post_action
[task 2020-04-15T20:21:03.919Z] 20:21:03 INFO - [mozharness: 2020-04-15 20:21:03.919803Z] Finished verify-device step (success)
[task 2020-04-15T20:21:03.920Z] 20:21:03 INFO - [mozharness: 2020-04-15 20:21:03.919976Z] Running install step.
[task 2020-04-15T20:21:03.920Z] 20:21:03 INFO - Running pre-action listener: resource_record_pre_action
[task 2020-04-15T20:21:03.920Z] 20:21:03 INFO - Running main action method: install
[task 2020-04-15T20:22:35.422Z] 20:22:35 INFO - Finished installing apps for emulator-5554
[task 2020-04-15T20:22:35.422Z] 20:22:35 INFO - Running post-action listener: resource_record_post_action
[task 2020-04-15T20:22:35.423Z] 20:22:35 INFO - [mozharness: 2020-04-15 20:22:35.422707Z] Finished install step (success)
[task 2020-04-15T20:22:35.423Z] 20:22:35 INFO - [mozharness: 2020-04-15 20:22:35.422785Z] Running run-tests step.
[task 2020-04-15T20:22:35.423Z] 20:22:35 INFO - Running pre-action listener: resource_record_pre_action
[task 2020-04-15T20:22:35.423Z] 20:22:35 INFO - Running pre-action listener: timed_screenshots
[task 2020-04-15T20:22:35.423Z] 20:22:35 INFO - Running main action method: run_tests
[task 2020-04-15T20:22:35.589Z] 20:22:35 INFO - Using adb 1.0.40
[task 2020-04-15T20:22:35.899Z] 20:22:35 INFO - adbd running as root
[task 2020-04-15T20:22:36.003Z] 20:22:36 INFO - su -c setenforce 0 exitcode 0, stdout: None
[task 2020-04-15T20:22:36.210Z] 20:22:36 INFO - su -c supported
[task 2020-04-15T20:22:36.417Z] 20:22:36 INFO - detect ls -1A: args: /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb wait-for-device shell /system/bin/ls -1A /sdcard; echo adb_returncode=$?, exitcode: 1, stdout: ls: Unknown option '-1'. Aborting.
[task 2020-04-15T20:22:36.417Z] 20:22:36 INFO - /system/bin/ls -a supported
[task 2020-04-15T20:22:36.521Z] 20:22:36 INFO - Native cp support: True
[task 2020-04-15T20:22:36.625Z] 20:22:36 INFO - Native chmod -R support: True
[task 2020-04-15T20:22:36.729Z] 20:22:36 INFO - Native chown -R support: False
[task 2020-04-15T20:22:36.832Z] 20:22:36 INFO - Unable to turn off logcat chatty
[task 2020-04-15T20:22:36.833Z] 20:22:36 INFO - Setting SELinux Permissive
[task 2020-04-15T20:22:36.936Z] 20:22:36 WARNING - Unable to set SELinux Permissive due to args: /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb wait-for-device shell setenforce Permissive; echo adb_returncode=$?, exitcode: 1, stdout: setenforce: SELinux is disabled.
[task 2020-04-15T20:22:36.936Z] 20:22:36 INFO - Native pidof support: False
[task 2020-04-15T20:22:37.770Z] 20:22:37 INFO - Using adb 1.0.40
[task 2020-04-15T20:22:38.188Z] 20:22:38 INFO - adbd running as root
[task 2020-04-15T20:22:38.292Z] 20:22:38 INFO - su -c setenforce 0 exitcode 0, stdout: None
[task 2020-04-15T20:22:38.499Z] 20:22:38 INFO - su -c supported
[task 2020-04-15T20:22:38.706Z] 20:22:38 INFO - detect ls -1A: args: /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb wait-for-device shell /system/bin/ls -1A /sdcard; echo adb_returncode=$?, exitcode: 1, stdout: ls: Unknown option '-1'. Aborting.
[task 2020-04-15T20:22:38.706Z] 20:22:38 INFO - /system/bin/ls -a supported
[task 2020-04-15T20:22:38.809Z] 20:22:38 INFO - Native cp support: True
[task 2020-04-15T20:22:38.913Z] 20:22:38 INFO - Native chmod -R support: True
[task 2020-04-15T20:22:39.017Z] 20:22:39 INFO - Native chown -R support: False
[task 2020-04-15T20:22:39.120Z] 20:22:39 INFO - Unable to turn off logcat chatty
[task 2020-04-15T20:22:39.120Z] 20:22:39 INFO - Setting SELinux Permissive
[task 2020-04-15T20:22:39.224Z] 20:22:39 WARNING - Unable to set SELinux Permissive due to args: /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb wait-for-device shell setenforce Permissive; echo adb_returncode=$?, exitcode: 1, stdout: setenforce: SELinux is disabled.
[task 2020-04-15T20:22:39.224Z] 20:22:39 INFO - Native pidof support: False
[task 2020-04-15T20:22:46.507Z] timed out waiting for profiles.ini
[task 2020-04-15T20:22:47.025Z] 20:22:47 INFO - launch_application: am start -W -n org.mozilla.geckoview.test/org.mozilla.geckoview.test.TestRunnerActivity -a android.intent.action.MAIN --es env9 LLVM_PROFILE_FILE=/sdcard/pgo_profile/default
%p_random
%m.profraw --es env8 R_LOG_DESTINATION=stderr --es args "-no-remote -profile /sdcard/tests/profile -marionette" --es env3 R_LOG_VERBOSE=1 --es env2 XPCOM_DEBUG_BREAK=warn --es env1 MOZ_WEBRENDER=0 --es env0 MOZ_CRASHREPORTER=1 --es env7 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env6 MOZ_IN_AUTOMATION=1 --es env5 MOZ_LOG=signaling:3,mtransport:4,DataChannel:4,jsep:4 --es env4 MOZ_HIDE_RESULTS_TABLE=1 --ez use_multiprocess True --es env13 R_LOG_LEVEL=6 --es env12 MOZ_PROCESS_LOG=/tmp/tmpTEpS7Wpidlog --es env11 MOZ_CRASHREPORTER_NO_REPORT=1 --es env10 MOZ_JAR_LOG_FILE=/sdcard/pgo_profile/en-US.log
[task 2020-04-15T20:30:03.072Z] mozcrash checking /tmp/tmpq54v1
for minidumps...
[task 2020-04-15T20:30:03.073Z] PROCESS-CRASH | marionette.py | application crashed [unknown top frame]
[task 2020-04-15T20:30:03.073Z] Crash dump filename: /tmp/tmpq54v1
/105b64d1-31a2-d2f1-8bb0-8300d604be46.dmp
[task 2020-04-15T20:30:03.073Z] MINIDUMP_STACKWALK not set, can't process dump.
[task 2020-04-15T20:30:03.074Z] 20:30:03 INFO - Running post-action listener: _resource_record_post_action
[task 2020-04-15T20:30:03.074Z] 20:30:03 INFO - Running post-action listener: stop_device
[task 2020-04-15T20:30:04.624Z] 20:30:04 INFO - Killing logcat pid 709.
[task 2020-04-15T20:30:04.624Z] 20:30:04 INFO - Killing every process called emulator64-arm
[task 2020-04-15T20:30:04.630Z] 20:30:04 INFO - Killing pid 202.
[task 2020-04-15T20:30:04.630Z] 20:30:04 INFO - [mozharness: 2020-04-15 20:30:04.630420Z] Finished run-tests step (failed)
[task 2020-04-15T20:30:04.631Z] 20:30:04 FATAL - Uncaught exception: Traceback (most recent call last):
[task 2020-04-15T20:30:04.632Z] 20:30:04 FATAL - File "/builds/worker/checkouts/gecko/testing/mozharness/mozharness/base/script.py", line 2132, in run
[task 2020-04-15T20:30:04.632Z] 20:30:04 FATAL - self.run_action(action)
[task 2020-04-15T20:30:04.632Z] 20:30:04 FATAL - File "/builds/worker/checkouts/gecko/testing/mozharness/mozharness/base/script.py", line 2071, in run_action
[task 2020-04-15T20:30:04.632Z] 20:30:04 FATAL - self._possibly_run_method(method_name, error_if_missing=True)
[task 2020-04-15T20:30:04.632Z] 20:30:04 FATAL - File "/builds/worker/checkouts/gecko/testing/mozharness/mozharness/base/script.py", line 2026, in _possibly_run_method
[task 2020-04-15T20:30:04.632Z] 20:30:04 FATAL - return getattr(self, method_name)()
[task 2020-04-15T20:30:04.632Z] 20:30:04 FATAL - File "/builds/worker/checkouts/gecko/testing/mozharness/scripts/android_emulator_pgo.py", line 230, in run_tests
[task 2020-04-15T20:30:04.632Z] 20:30:04 FATAL - driver.navigate("http://%s:%d/%s" % (IP, PORT, page))
[task 2020-04-15T20:30:04.636Z] 20:30:04 FATAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1467, in navigate
[task 2020-04-15T20:30:04.636Z] 20:30:04 FATAL - {"url": url})
[task 2020-04-15T20:30:04.636Z] 20:30:04 FATAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
[task 2020-04-15T20:30:04.636Z] 20:30:04 FATAL - m._handle_socket_failure()
[task 2020-04-15T20:30:04.636Z] 20:30:04 FATAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 677, in _handle_socket_failure
[task 2020-04-15T20:30:04.637Z] 20:30:04 FATAL - reraise(IOError, IOError(message.format(returncode=returncode, reason=exc)), tb)
[task 2020-04-15T20:30:04.637Z] 20:30:04 FATAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2020-04-15T20:30:04.637Z] 20:30:04 FATAL - return func(*args, **kwargs)
[task 2020-04-15T20:30:04.637Z] 20:30:04 FATAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 589, in _send_message
[task 2020-04-15T20:30:04.637Z] 20:30:04 FATAL - msg = self.client.request(name, params)
[task 2020-04-15T20:30:04.637Z] 20:30:04 FATAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 272, in request
[task 2020-04-15T20:30:04.637Z] 20:30:04 FATAL - return self.receive()
[task 2020-04-15T20:30:04.638Z] 20:30:04 FATAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 159, in receive
[task 2020-04-15T20:30:04.638Z] 20:30:04 FATAL - raise socket.error("No data received over socket")
[task 2020-04-15T20:30:04.638Z] 20:30:04 FATAL - IOError: Content process crashed (Reason: No data received over socket)
[task 2020-04-15T20:30:04.638Z] 20:30:04 FATAL - Running post_fatal callback...
[task 2020-04-15T20:30:04.639Z] 20:30:04 FATAL - Exiting -1
[task 2020-04-15T20:30:04.639Z] 20:30:04 INFO - Running post-run listener: _resource_record_post_run
[task 2020-04-15T20:30:04.742Z] 20:30:04 INFO - Total resource usage - Wall time: 567s; CPU: 17.0%; Read bytes: 0; Write bytes: 1135132672; Read time: 0; Write time: 92484
[task 2020-04-15T20:30:04.742Z] 20:30:04 INFO - TinderboxPrint: CPU usage<br/>16.9%
[task 2020-04-15T20:30:04.742Z] 20:30:04 INFO - TinderboxPrint: I/O read bytes / time<br/>0 / 0
[task 2020-04-15T20:30:04.742Z] 20:30:04 INFO - TinderboxPrint: I/O write bytes / time<br/>1,135,132,672 / 92,484
[task 2020-04-15T20:30:04.743Z] 20:30:04 INFO - TinderboxPrint: CPU idle<br/>1,867.4 (83.0%)
[task 2020-04-15T20:30:04.743Z] 20:30:04 INFO - TinderboxPrint: CPU user<br/>372.9 (16.6%)
[task 2020-04-15T20:30:04.743Z] 20:30:04 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2020-04-15T20:30:04.744Z] 20:30:04 INFO - verify-device - Wall time: 26s; CPU: 3.0%; Read bytes: 0; Write bytes: 2772992; Read time: 0; Write time: 56
[task 2020-04-15T20:30:04.746Z] 20:30:04 INFO - install - Wall time: 92s; CPU: 25.0%; Read bytes: 0; Write bytes: 803270656; Read time: 0; Write time: 77208
[task 2020-04-15T20:30:04.750Z] 20:30:04 INFO - run-tests - Wall time: 448s; CPU: 16.0%; Read bytes: 0; Write bytes: 320847872; Read time: 0; Write time: 14588
[task 2020-04-15T20:30:05.382Z] cleanup

As it looks like the Profile-guided optimization builds do not set the MINIDUMP_STACKWALK environment variable and as such we cannot symbolicate those crashes.

Component: Marionette → Task Configuration
Product: Testing → Firefox Build System
Version: Version 3 → unspecified
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE

Hey Tom, is there anything we should do here? See my comment 1.

Flags: needinfo?(mozilla)
Flags: needinfo?(mozilla) → needinfo?(mh+mozilla)

The generate profile tasks all have a dependency on the minidump-stackwalk toolchain and install it. The problem here is that for some reason mozharness doesn't set MINIDUMP_STACKWALK. Someone with better knowledge than I have about the mozharness scripts should look into this.

There's another potential problem that I'm not even sure the script for non-android builds would even try to use minidump-stackwalk.

Status: RESOLVED → REOPENED
Component: Task Configuration → General
Flags: needinfo?(mh+mozilla)
Product: Firefox Build System → Testing
Resolution: INCOMPLETE → ---
Flags: needinfo?(gbrown)

Morphing the bug's summary to something more actionable.

Summary: Intermittent marionette.py | application crashed [unknown top frame] → Generate profile tasks do not set the MINIDUMP_STACKWALK environment variable
Summary: Generate profile tasks do not set the MINIDUMP_STACKWALK environment variable → Mozharness in generate profile tasks does not set the MINIDUMP_STACKWALK environment variable

Most mozharness scripts define MINIDUMP_STACKWALK:

https://searchfox.org/mozilla-central/rev/4166c15e2a99a23a9b38ad62c9fdfe8e5448b354/testing/mozharness/scripts/desktop_unittest.py#873

but that's missing for android_emulator_pgo.py.

Assignee: nobody → gbrown
Flags: needinfo?(gbrown)

Minidumps saved as artifacts and crash report generated, but still missing symbols...
https://treeherder.mozilla.org/#/jobs?repo=try&revision=6d3f168bc825beab232a8291a69a4706c7f77070

Pushed by gbrown@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/29d33c4135da Support crash reporting in android_emulator_pgo.py; r=nalexander
Whiteboard: dev-prod-2020
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla78
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: