Closed Bug 1650282 Opened 7 months ago Closed 5 months ago

Intermittent telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | application crashed [@ mozilla::ShutdownXPCOM(nsIServiceManager*)]

Categories

(Toolkit :: Telemetry, defect, P5)

defect

Tracking

()

RESOLVED FIXED
81 Branch
Tracking Status
firefox-esr68 --- unaffected
firefox-esr78 --- unaffected
firefox79 --- unaffected
firefox80 --- fixed
firefox81 --- fixed

People

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

References

Details

(Keywords: crash, intermittent-failure)

Crash Data

Attachments

(2 files)

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=308396878&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Fhrt_U0mTduXI5YOheW-rQ/runs/0/artifacts/public/logs/live_backing.log


[task 2020-07-02T22:28:12.081Z] 22:28:12 INFO - TEST-START | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping
[task 2020-07-02T22:28:12.081Z] 22:28:12 INFO - Application command: Z:\task_1593727886\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_1593727886\build\tmpp1cfjc.mozrunner
[task 2020-07-02T22:28:12.286Z] 22:28:12 INFO - [9192, StreamTrans #2] WARNING: (debug) mSafeStream->Finish() failed within nsBufferedOutputStream::Flush()! Possible dataloss.: file /builds/worker/checkouts/gecko/netwerk/base/nsBufferedStreams.cpp, line 1006
[task 2020-07-02T22:28:12.286Z] 22:28:12 INFO - [9192, StreamTrans #2] WARNING: failed to save prefs file! possible data loss: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 3036
[task 2020-07-02T22:28:13.043Z] 22:28:13 INFO - 1593728893039 Toolkit.Telemetry TRACE TelemetryController::observe - profile-after-change notified.
[task 2020-07-02T22:28:13.043Z] 22:28:13 INFO - 1593728893039 Toolkit.Telemetry TRACE TelemetryController::setupTelemetry
[task 2020-07-02T22:28:13.047Z] 22:28:13 INFO - 1593728893042 Toolkit.Telemetry TRACE TelemetryReportingPolicy::setup
[task 2020-07-02T22:28:13.047Z] 22:28:13 INFO - 1593728893043 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2020-07-02T22:28:13.047Z] 22:28:13 INFO - 1593728893043 Toolkit.Telemetry TRACE TelemetrySession::earlyInit
[task 2020-07-02T22:28:13.057Z] 22:28:13 INFO - 1593728893054 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2020-07-02T22:28:13.057Z] 22:28:13 INFO - 1593728893055 Toolkit.Telemetry TRACE UpdatePing::init - enabled: true
[task 2020-07-02T22:28:13.076Z] 22:28:13 INFO - 1593728893065 Toolkit.Telemetry TRACE TelemetryEnvironment::constructor
[task 2020-07-02T22:28:13.076Z] 22:28:13 INFO - 1593728893073 Toolkit.Telemetry TRACE TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2020-07-02T22:28:13.081Z] 22:28:13 INFO - 1593728893077 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2020-07-02T22:28:13.081Z] 22:28:13 INFO - 1593728893077 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
[task 2020-07-02T22:28:13.086Z] 22:28:13 INFO - 1593728893083 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2020-07-02T22:28:13.108Z] 22:28:13 INFO - 1593728893105 Marionette TRACE Marionette enabled
[task 2020-07-02T22:28:13.227Z] 22:28:13 INFO - 1593728893216 Marionette TRACE Received observer notification toplevel-window-ready
[task 2020-07-02T22:28:13.249Z] 22:28:13 INFO - 1593728893243 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons: addons differ
[task 2020-07-02T22:28:13.259Z] 22:28:13 INFO - [9192, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4283
[task 2020-07-02T22:28:13.263Z] 22:28:13 INFO - [9192, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4283
[task 2020-07-02T22:28:13.408Z] 22:28:13 INFO - [9192, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp, line 1131
[task 2020-07-02T22:28:13.692Z] 22:28:13 INFO - 1593728893690 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: auto-update-config-change, aData: false
[task 2020-07-02T22:28:13.813Z] 22:28:13 INFO - [9192, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4281
[task 2020-07-02T22:28:13.852Z] 22:28:13 INFO - [Parent 9192, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp, line 1562
[task 2020-07-02T22:28:13.856Z] 22:28:13 INFO - 1593728893852 Toolkit.Telemetry TRACE TelemetrySession::observe - xul-window-visible notified.
[task 2020-07-02T22:28:13.945Z] 22:28:13 INFO - 1593728893939 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2020-07-02T22:28:13.945Z] 22:28:13 INFO - 1593728893940 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2020-07-02T22:28:14.166Z] 22:28:14 INFO - 1593728894158 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.[task 2020-07-02T22:28:14.166Z] 22:28:14 INFO - 1593728894160 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2020-07-02T22:28:14.196Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: Need BrowserChild to get the nativeWindow from!: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp, line 1086
[task 2020-07-02T22:28:14.200Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: Need BrowserChild to get the nativeWindow from!: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp, line 1086
[task 2020-07-02T22:28:14.205Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: Need BrowserChild to get the nativeWindow from!: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp, line 1086
[task 2020-07-02T22:28:14.205Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: Need BrowserChild to get the nativeWindow from!: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp, line 1086
[task 2020-07-02T22:28:14.210Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: Need BrowserChild to get the nativeWindow from!: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp, line 1086
[task 2020-07-02T22:28:14.239Z] 22:28:14 INFO - 1593728894234 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: compositor:created, aData: null
[task 2020-07-02T22:28:14.300Z] 22:28:14 INFO - 1593728894297 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2020-07-02T22:28:14.302Z] 22:28:14 INFO - 1593728894299 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2020-07-02T22:28:14.343Z] 22:28:14 INFO - 1593728894339 Toolkit.Telemetry TRACE TelemetrySession::observe - user-interaction-active notified.
[task 2020-07-02T22:28:14.348Z] 22:28:14 INFO - [Child 2732, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp, line 2633
[task 2020-07-02T22:28:14.366Z] 22:28:14 INFO - [Child 2732, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp, line 2633
[task 2020-07-02T22:28:14.366Z] 22:28:14 INFO - [Child 2732, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp, line 2633
[task 2020-07-02T22:28:14.376Z] 22:28:14 INFO - [Child 2732, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp, line 2633
[task 2020-07-02T22:28:14.381Z] 22:28:14 INFO - [Child 2732, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp, line 2633
[task 2020-07-02T22:28:14.444Z] 22:28:14 INFO - [Child 7372, Main Thread] WARNING: NS_ENSURE_SUCCESS_VOID(rv) failed with result 0x80004001 (NS_ERROR_NOT_IMPLEMENTED): file /builds/worker/checkouts/gecko/caps/OriginAttributes.cpp, line 111
[task 2020-07-02T22:28:14.552Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file /builds/worker/checkouts/gecko/xpcom/io/nsLocalFileWin.cpp, line 3149
[task 2020-07-02T22:28:14.552Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file /builds/worker/checkouts/gecko/xpcom/io/nsLocalFileWin.cpp, line 3149
[task 2020-07-02T22:28:14.552Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: This method is lossy. Use GetCanonicalPath !: file /builds/worker/checkouts/gecko/xpcom/io/nsLocalFileWin.cpp, line 3149
[task 2020-07-02T22:28:14.552Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: '!mProxySettingTarget', file /builds/worker/checkouts/gecko/netwerk/base/nsProtocolProxyService.cpp, line 874
[task 2020-07-02T22:28:14.622Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp, line 1610
[task 2020-07-02T22:28:14.680Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4283
[task 2020-07-02T22:28:14.685Z] 22:28:14 INFO - console.error: SearchCache: "_readCacheFile: Error reading cache file:" (new Error("", "(unknown module)"))
[task 2020-07-02T22:28:14.685Z] 22:28:14 INFO - 1593728894682 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: ensure-known-region-done
[task 2020-07-02T22:28:14.723Z] 22:28:14 INFO - [Parent 9192, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp, line 1131
[task 2020-07-02T22:28:14.752Z] 22:28:14 INFO - 1593728894747 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: sessionstore-windows-restored, aData: null
[task 2020-07-02T22:28:14.752Z] 22:28:14 INFO - 1593728894750 Toolkit.Telemetry TRACE TelemetrySession::observe - sessionstore-windows-restored notified.
[task 2020-07-02T22:28:14.752Z] 22:28:14 INFO - 1593728894750 Toolkit.Telemetry TRACE TelemetrySession::gatherStartup[task 2020-07-02T22:28:18.788Z] 22:28:18 INFO - ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-07-02T22:28:18.806Z] 22:28:18 INFO - [GPU 10372, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4383
[task 2020-07-02T22:28:18.836Z] 22:28:18 INFO - [Parent 9192, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp, line 227
[task 2020-07-02T22:28:18.836Z] 22:28:18 INFO - [Parent 9192, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp, line 254
[task 2020-07-02T22:28:19.688Z] 22:28:19 INFO - [Parent 9192, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-02T22:28:19.746Z] 22:28:19 INFO - Hit MOZ_CRASH(NSS_Shutdown failed) at /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:763
[task 2020-07-02T22:28:19.751Z] 22:28:19 INFO - pingserver pings_handler received 'new-profile' ping
[task 2020-07-02T22:28:19.756Z] 22:28:19 INFO - pingserver pings_handler received 'event' ping
[task 2020-07-02T22:28:19.761Z] 22:28:19 INFO - pingserver pings_handler received 'first-shutdown' ping
[task 2020-07-02T22:28:19.841Z] 22:28:19 INFO - #01: workerlz4_maxCompressedSize[Z:\task_1593727886\build\application\firefox\xul.dll +0x61b303f]
[task 2020-07-02T22:28:19.841Z] 22:28:19 INFO - #02: workerlz4_maxCompressedSize[Z:\task_1593727886\build\application\firefox\xul.dll +0x61b397a]
[task 2020-07-02T22:28:19.841Z] 22:28:19 INFO - #03: Ordinal0[Z:\task_1593727886\build\application\firefox\firefox.exe +0x158f]
[task 2020-07-02T22:28:19.841Z] 22:28:19 INFO - #04: Ordinal0[Z:\task_1593727886\build\application\firefox\firefox.exe +0x120e]
[task 2020-07-02T22:28:19.841Z] 22:28:19 INFO - #05: TargetNtUnmapViewOfSection[Z:\task_1593727886\build\application\firefox\firefox.exe +0x92cb8]
[task 2020-07-02T22:28:19.841Z] 22:28:19 INFO - #06: BaseThreadInitThunk[C:\Windows\System32\KERNEL32.DLL +0x13034]
[task 2020-07-02T22:28:19.841Z] 22:28:19 INFO - #07: RtlUserThreadStart[C:\Windows\SYSTEM32\ntdll.dll +0x71461]
[task 2020-07-02T22:29:28.427Z] 22:29:28 INFO - mozcrash Copy/paste: Z:/task_1593727886/fetches\minidump_stackwalk\minidump_stackwalk.exe Z:\task_1593727886\build\tmpp1cfjc.mozrunner\minidumps\9956f3f0-165a-4dba-aa4a-e30d1416cf6b.dmp c:\users\task_1593727886\appdata\local\temp\tmpjdyiqg
[task 2020-07-02T22:30:10.876Z] 22:30:10 INFO - mozcrash Saved minidump as Z:\task_1593727886\build\blobber_upload_dir\9956f3f0-165a-4dba-aa4a-e30d1416cf6b.dmp
[task 2020-07-02T22:30:10.876Z] 22:30:10 INFO - mozcrash Saved app info as Z:\task_1593727886\build\blobber_upload_dir\9956f3f0-165a-4dba-aa4a-e30d1416cf6b.extra
[task 2020-07-02T22:30:10.880Z] 22:30:10 INFO - PROCESS-CRASH | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | application crashed [@ mozilla::ShutdownXPCOM(nsIServiceManager*)]
[task 2020-07-02T22:30:10.880Z] 22:30:10 INFO - Mozilla crash reason: MOZ_CRASH(NSS_Shutdown failed)[task 2020-07-02T22:30:10.880Z] 22:30:10 INFO - Crash dump filename: Z:\task_1593727886\build\tmpp1cfjc.mozrunner\minidumps\9956f3f0-165a-4dba-aa4a-e30d1416cf6b.dmp
[task 2020-07-02T22:30:10.880Z] 22:30:10 INFO - Operating system: Windows NT
[task 2020-07-02T22:30:10.880Z] 22:30:10 INFO - 10.0.17134
[task 2020-07-02T22:30:10.880Z] 22:30:10 INFO - CPU: amd64
[task 2020-07-02T22:30:10.880Z] 22:30:10 INFO - family 6 model 85 stepping 7
[task 2020-07-02T22:30:10.880Z] 22:30:10 INFO - 8 CPUs
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO -
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - GPU: UNKNOWN
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO -
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - Crash reason: EXCEPTION_BREAKPOINT
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - Crash address: 0x5da92579
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - Process uptime: 7 seconds
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO -
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - Thread 0 (crashed)
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - 0 xul.dll!mozilla::ShutdownXPCOM(nsIServiceManager*) [XPCOMInit.cpp:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 763 + 0x0]
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - rax = 0x00007ffc664c8b28 rdx = 0x00007ffca4a1a640
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - rcx = 0x00007ffc90292028 rbx = 0x00007ff7b1d964f3
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - rsi = 0x00000265a926b248 rdi = 0x00000091583ff588
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - rbp = 0x00000091583ff660 rsp = 0x00000091583ff540
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - r8 = 0x00000091583f9588 r9 = 0x00007ffc664c71b0
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - r10 = 0x0000000000000000 r11 = 0x00000091583fabd0
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - r12 = 0x0000000000780001 r13 = 0x00000265a92094c0
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - r14 = 0x00000091583ff950 r15 = 0xaaaaaaaaaaaaaaaa
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - rip = 0x00007ffc5da92579
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - Found by: given as instruction pointer in context
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - 1 xul.dll!ScopedXPCOMStartup::~ScopedXPCOMStartup() [nsAppRunner.cpp:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 1286 + 0x8]
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - rbx = 0x00007ff7b1d964f3 rbp = 0x00000091583ff660
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - rsp = 0x00000091583ff5b0 r12 = 0x0000000000780001
[task 2020-07-02T22:30:10.881Z] 22:30:10 INFO - r13 = 0x00000265a92094c0 r14 = 0x00000091583ff950
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - r15 = 0xaaaaaaaaaaaaaaaa rip = 0x00007ffc63a46062
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - Found by: call frame info
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - 2 xul.dll!XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 4883 + 0x19]
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - rbx = 0x00007ff7b1d964f3 rbp = 0x00000091583ff660
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - rsp = 0x00000091583ff610 r12 = 0x0000000000780001
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - r13 = 0x00000265a92094c0 r14 = 0x00000091583ff950
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - r15 = 0xaaaaaaaaaaaaaaaa rip = 0x00007ffc63a5303f
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - Found by: call frame info
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - 3 xul.dll!XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 4920 + 0x10]
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - rbx = 0x00007ff7b1d964f3 rbp = 0x00000091583ff660
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - rsp = 0x00000091583ff740 r12 = 0x0000000000780001
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - r13 = 0x00000265a92094c0 r14 = 0x00000091583ff950
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - r15 = 0xaaaaaaaaaaaaaaaa rip = 0x00007ffc63a5397a
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - Found by: call frame info[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - 4 firefox.exe!fprintf(_iobuf* const, char const* const, <NoType>) [stdio.h:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 835 + 0x1f]
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - rbx = 0x00007ff7b1d964f3 rbp = 0x00000091583ff660
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - rsp = 0x00000091583ff8b0 r12 = 0x0000000000780001
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - r13 = 0x00000265a92094c0 r14 = 0x00000091583ff950
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - r15 = 0xaaaaaaaaaaaaaaaa rip = 0x00007ff7b1d0158f
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - Found by: call frame info
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - 5 0x265a92103c0
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - rbx = 0x00007ff7b1d964f3 rbp = 0x00000091583ff660
[task 2020-07-02T22:30:10.882Z] 22:30:10 INFO - rsp = 0x00000091583ff910 r12 = 0x0000000000780001
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - r13 = 0x00000265a92094c0 r14 = 0x00000091583ff950
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - r15 = 0xaaaaaaaaaaaaaaaa rip = 0x00000265a92103c0
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - Found by: call frame info
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - 6 firefox.exe!mozilla::MemoryTelemetry::TotalMemoryGatherer::MaybeFinish() [MemoryTelemetry.cpp:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 421 + 0x5]
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - rsp = 0x00000091583ff948 rip = 0x00007ff7b1d96525
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - Found by: stack scanning
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - 7 0x265a8f382d2
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - rsp = 0x00000091583ff9c8 rip = 0x00000265a8f382d2
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - Found by: call frame info
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - 8 kernel32.dll!mp_exptmod_i(mp_int const*, mp_int const*, mp_int const*, mp_int*, mp_mont_modulus*, int, unsigned int, unsigned int, unsigned int) [mpmontg.c:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 485 + 0x14]
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - rsp = 0x00000091583ff9e8 rip = 0x00007ffca70f3fc0
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - Found by: stack scanning
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO -
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - Thread 1
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - 0 ntdll.dll!nsConsoleService::MaybeForwardScriptError(nsIConsoleMessage*, bool*) [nsConsoleService.cpp:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 232 + 0x30]
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - rax = 0x0000000000000009 rdx = 0x0000009158bff8d0
[task 2020-07-02T22:30:10.883Z] 22:30:10 INFO - rcx = 0x000000000000026c rbx = 0x0000009158bff8c8
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - rsi = 0x00007ff7b1d5b428 rdi = 0x0000009158bff8dc
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - rbp = 0x0000009158bff8dc rsp = 0x0000009158bff818
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - r8 = 0x0000000000002001 r9 = 0xe5e5e5e5e5e5e5e5
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - r10 = 0x0000000000000000 r11 = 0x00000265babd7000
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - r12 = 0x0000000000000000 r13 = 0x00000265a9214320
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - r14 = 0x0000009158bff8e0 r15 = 0x0000000000000000
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - rip = 0x00007ffca787a014
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - Found by: given as instruction pointer in context
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO -
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - Thread 2
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - 0 ntdll.dll!static nsXPCOMCycleCollectionParticipant::CheckForRightISupports(nsISupports*) [nsCycleCollectionParticipant.cpp:f0ac79e1ed53bbdc5f0b470f6889ebfcc05fa550 : 31 + 0xd]
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - rax = 0x00000000000000eb rdx = 0x00000091593fdad0
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - rcx = 0x0000000000000594 rbx = 0x00000000000004d0
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - rsi = 0x00000265aad72798 rdi = 0x00000265aad72800
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - rbp = 0xffffffffffffffff rsp = 0x00000091593fda58
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - r8 = 0x0000000000000718 r9 = 0x0000000000000000
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - r10 = 0x0000000000000000 r11 = 0x0000000000000246
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - r12 = 0x00000265aad72800 r13 = 0x00000265aad72798
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - r14 = 0x00000265aad727a8 r15 = 0x0000000000000594
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - rip = 0x00007ffca787bc44
[task 2020-07-02T22:30:10.884Z] 22:30:10 INFO - Found by: given as instruction pointer in context

Severity: normal → S4
Depends on: 1594515
Priority: -- → P5

Oops. This one's actually partially symbolicated.

No longer depends on: 1594515

Hm. We could set MOZ_IGNORE_NSS_SHUTDOWN_LEAKS to avoid this crash. Raphael, this will mean another slight modification to the test environment, but I think it's valid. What do you think?

Flags: needinfo?(rpierzina)

Can we chat about this on Zoom? I have a few questions about symbols.

Flags: needinfo?(rpierzina)
Duplicate of this bug: 1651656
Duplicate of this bug: 1651890
Crash Signature: [@ mozilla::ShutdownXPCOM(nsIServiceManager*)] → [@ mozilla::ShutdownXPCOM(nsIServiceManager*)] [@ xul.dll + 0x1f567c]
Duplicate of this bug: 1653754
Assignee: nobody → chutten
Status: NEW → ASSIGNED
Pushed by chutten@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e5c07bc5c338
Ignore NSS Shutdown leaks in telemety marionette tests r=raphael
Status: ASSIGNED → RESOLVED
Closed: 6 months ago
Resolution: --- → FIXED
Target Milestone: --- → 81 Branch
Crash Signature: [@ mozilla::ShutdownXPCOM(nsIServiceManager*)] [@ xul.dll + 0x1f567c] → [@ mozilla::ShutdownXPCOM(nsIServiceManager*)] [@ xul.dll + 0x1f567c]

The patch landed in nightly and beta is affected.
:chutten, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(chutten)
Flags: needinfo?(chutten)
Whiteboard: [checkin-needed-beta]

Hi Chris, this still occurs: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=312405847&repo=mozilla-central&lineNumber=1802, can you take a look?

[task 2020-08-07T16:07:25.412Z] 16:07:25 INFO - [Parent 4124, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-08-07T16:07:25.467Z] 16:07:25 INFO - Hit MOZ_CRASH(NSS_Shutdown failed) at /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:763
[task 2020-08-07T16:07:25.594Z] 16:07:25 INFO - #01: workerlz4_maxCompressedSize[Z:\task_1596816054\build\application\firefox\xul.dll +0x537bc82]
[task 2020-08-07T16:07:25.594Z] 16:07:25 INFO - #02: workerlz4_maxCompressedSize[Z:\task_1596816054\build\application\firefox\xul.dll +0x5386ef6]
[task 2020-08-07T16:07:25.594Z] 16:07:25 INFO - #03: workerlz4_maxCompressedSize[Z:\task_1596816054\build\application\firefox\xul.dll +0x53875b7]
[task 2020-08-07T16:07:25.594Z] 16:07:25 INFO - #04: XRE_GetBootstrap[Z:\task_1596816054\build\application\firefox\xul.dll +0x539cfb1]
[task 2020-08-07T16:07:25.594Z] 16:07:25 INFO - #05: Ordinal0[Z:\task_1596816054\build\application\firefox\firefox.exe +0x14da]
[task 2020-08-07T16:07:25.594Z] 16:07:25 INFO - #06: Ordinal0[Z:\task_1596816054\build\application\firefox\firefox.exe +0x11cf]
[task 2020-08-07T16:07:25.594Z] 16:07:25 INFO - #07: TargetNtUnmapViewOfSection[Z:\task_1596816054\build\application\firefox\firefox.exe +0x854b9]
[task 2020-08-07T16:07:25.595Z] 16:07:25 INFO - #08: BaseThreadInitThunk[C:\windows\system32\kernel32.dll +0x4ef3c]
[task 2020-08-07T16:07:25.595Z] 16:07:25 INFO - #09: RtlInitializeExceptionChain[C:\windows\SYSTEM32\ntdll.dll +0x63618]
[task 2020-08-07T16:07:25.595Z] 16:07:25 INFO - #10: RtlInitializeExceptionChain[C:\windows\SYSTEM32\ntdll.dll +0x635eb]
[task 2020-08-07T16:08:33.662Z] 16:08:33 INFO - mozcrash Copy/paste: Z:/task_1596816054/fetches\minidump_stackwalk\minidump_stackwalk.exe Z:\task_1596816054\build\tmpkiqu21.mozrunner\minidumps\18098eea-dcea-47d2-b3a9-7f0ed19a70ab.dmp c:\users\task_1596816054\appdata\local\temp\tmphuhhxz
[task 2020-08-07T16:08:58.022Z] 16:08:58 INFO - mozcrash Saved minidump as Z:\task_1596816054\build\blobber_upload_dir\18098eea-dcea-47d2-b3a9-7f0ed19a70ab.dmp
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - mozcrash Saved app info as Z:\task_1596816054\build\blobber_upload_dir\18098eea-dcea-47d2-b3a9-7f0ed19a70ab.extra
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - PROCESS-CRASH | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | application crashed [None]
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - Mozilla crash reason: MOZ_CRASH(NSS_Shutdown failed)
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - Crash dump filename: Z:\task_1596816054\build\tmpkiqu21.mozrunner\minidumps\18098eea-dcea-47d2-b3a9-7f0ed19a70ab.dmp
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - stderr from minidump_stackwalk:
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - 2020-08-07 16:08:34: simple_symbol_supplier.cc:196: INFO: No symbol file at c:\users\task_1596816054\appdata\local\temp\tmphuhhxz/xul.pdb/33A6D765303D612B4C4C44205044422E1/xul.sym
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - 2020-08-07 16:08:34: http_symbol_supplier.cc:507: INFO: HTTPSymbolSupplier: querying http://s3-us-west-2.amazonaws.com/org.mozilla.crash-stats.symbols-public/v1/xul.pdb/33A6D765303D612B4C4C44205044422E1/xul.sym
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - 2020-08-07 16:08:34: http_symbol_supplier.cc:302: INFO: HTTPSymbolSupplier: need to manually un-gzip
[task 2020-08-07T16:08:58.023Z] 16:08:58 INFO - 2020-08-07 16:08:34: http_symbol_supplier.cc:311: INFO: HTTPSymbolSupplier: symbol exists, saving to C:\Users\task_1596816054\AppData\Local\Temp\sym1.tmp
[task 2020-08-07T16:08:58.024Z] 16:08:58 INFO - 2020-08-07 16:08:51: simple_symbol_supplier.cc:196: INFO: No symbol file at c:\users\task_1596816054\appdata\local\temp\tmphuhhxz/firefox.pdb/8D0BE3393EEE322A4C4C44205044422E1/firefox.sym
[task 2020-08-07T16:08:58.024Z] 16:08:58 INFO - 2020-08-07 16:08:51: http_symbol_supplier.cc:507: INFO: HTTPSymbolSupplier: querying http://s3-us-west-2.amazonaws.com/org.mozilla.crash-stats.symbols-public/v1/firefox.pdb/8D0BE3393EEE322A4C4C44205044422E1/firefox.sym
[task 2020-08-07T16:08:58.024Z] 16:08:58 INFO - 2020-08-07 16:08:52: http_symbol_supplier.cc:302: INFO: HTTPSymbolSupplier: need to manually un-gzip
[task 2020-08-07T16:08:58.024Z] 16:08:58 INFO - 2020-08-07 16:08:52: http_symbol_supplier.cc:311: INFO: HTTPSymbolSupplier: symbol exists, saving to C:\Users\task_1596816054\AppData\Local\Temp\sym1.tmp
[task 2020-08-07T16:08:58.024Z] 16:08:58 INFO - terminating with uncaught exception of type std::bad_alloc: std::bad_alloc
[task 2020-08-07T16:08:59.819Z] 16:08:59 WARNING - Failed to gather test failure debug: Process has been unexpectedly closed (Exit code: 1) (Reason: [Errno 10053] An established connection was aborted by the software in your host machine)
[task 2020-08-07T16:08:59.819Z] 16:08:59 INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | IOError: Process crashed (Exit code: 1)
[task 2020-08-07T16:08:59.819Z] 16:08:59 INFO - Traceback (most recent call last):
[task 2020-08-07T16:08:59.819Z] 16:08:59 INFO - File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 196, in run
[task 2020-08-07T16:08:59.819Z] 16:08:59 INFO - testMethod()
[task 2020-08-07T16:08:59.819Z] 16:08:59 INFO - File "Z:\task_1596816054\build\tests\telemetry\marionette\tests\client\test_event_ping.py", line 51, in test_event_ping
[task 2020-08-07T16:08:59.819Z] 16:08:59 INFO - payload = self.wait_for_ping(self.restart_browser, EVENT_PING)["payload"]
[task 2020-08-07T16:08:59.819Z] 16:08:59 INFO - File "Z:\task_1596816054\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 153, in wait_for_ping
[task 2020-08-07T16:08:59.819Z] 16:08:59 INFO - [ping] = self.wait_for_pings(action_func, ping_filter, 1, ping_server=ping_server)
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - File "Z:\task_1596816054\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 140, in wait_for_pings
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - action_func()
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - File "Z:\task_1596816054\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 158, in restart_browser
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - return self.marionette.restart(clean=False, in_app=True)
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - return func(*args, **kwargs)
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1029, in restart
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - check_process_status=False)
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_driver\marionette.py", line 570, in raise_for_port
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - raise IOError('Process crashed (Exit code: {})'.format(runner.wait(0)))
[task 2020-08-07T16:08:59.820Z] 16:08:59 INFO - TEST-INFO took 103157ms
[task 2020-08-07T16:08:59.820Z] 16:08:59 ERROR - test_end for telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_event_ping.TestEventPing", "method_name": "test_event_ping"}, "expected": "PASS", "test": "telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping", "message": "InvalidSessionIdException: Please start a session", "stack": "Traceback (most recent call last):\n File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 227, in run\n self.tearDown()\n File "Z:\task_1596816054\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 224, in tearDown\n super(TelemetryTestCase, self).tearDown()\n File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_harness\runner\mixins\window_manager.py", line 25, in tearDown\n if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1261, in chrome_window_handles\n return self._send_message("WebDriver:GetChromeWindowHandles")\n File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _\n return func(*args, **kwargs)\n File "Z:\task_1596816054\build\venv\lib\site-packages\marionette_driver\marionette.py", line 591, in _send_message\n raise errors.InvalidSessionIdException("Please start a session")\n"}

Status: RESOLVED → REOPENED
Flags: needinfo?(chutten)
Resolution: FIXED → ---
Target Milestone: 81 Branch → ---

I tested it locally and it worked fine, maybe os.environ works differently on Windows (the two failures here are win7x32, all the failures in bug 1646285 are windows (mostly win7x32))? Maybe I need to plumb the envvar down to the runner after all : (

Flags: needinfo?(chutten)
See Also: → 1646285

My original patch just ignored it for locally-run tests.
This one makes a similar change for when it's run on try.

Pushed by chutten@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b129fc9655ff
Ignore NSS Shutdown leaks on telemetry integration tests r=raphael DONTBUILD
Status: REOPENED → RESOLVED
Closed: 6 months ago5 months ago
Resolution: --- → FIXED
Target Milestone: --- → 81 Branch
You need to log in before you can comment on or make changes to this bug.