Closed Bug 1658403 Opened 4 years ago Closed 4 years ago

Intermittent Assertion failure: Request::mDisconnected, at z:/build/workspace/obj-build/dist/include\mozilla/MozPromise.h:447 after TypeError: Telemetry.snapshotCapturedStacks is not a function(resource://gre/modules/TelemetrySession.jsm:743:44)

Categories

(Toolkit :: Telemetry, defect, P1)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

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

People

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

References

Details

(Keywords: assertion, intermittent-failure)

Attachments

(1 file)

Bug 1658403 - Remove the last of Telemetry's 'capturestacks' mentions r?janerik!
47 bytes, text/x-phabricator-request
Details | Review

Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=312594796&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UuKg5ipzRzKOsSOtA-lR5Q/runs/0/artifacts/public/logs/live_backing.log

[task 2020-08-10T14:30:16.862Z] 14:30:16 INFO - 1597069816856 Toolkit.Telemetry TRACE TelemetrySend::submitPing - ping id: 78dc72b3-2c4e-43dd-b42b-7a78e7ea7875, options: {"usePingSender":true}
[task 2020-08-10T14:30:16.862Z] 14:30:16 INFO - 1597069816856 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2020-08-10T14:30:16.864Z] 14:30:16 INFO - 1597069816857 Toolkit.Telemetry TRACE TelemetryPrioPing::Shutting down.
[task 2020-08-10T14:30:16.864Z] 14:30:16 INFO - 1597069816857 Toolkit.Telemetry TRACE TelemetryPrioPing::_submitPing
[task 2020-08-10T14:30:16.864Z] 14:30:16 INFO - 1597069816858 Toolkit.Telemetry TRACE TelemetryPrioPing::nothing to send
[task 2020-08-10T14:30:16.864Z] 14:30:16 INFO - 1597069816858 Toolkit.Telemetry TRACE TelemetryReportingPolicy::shutdown
[task 2020-08-10T14:30:16.865Z] 14:30:16 INFO - 1597069816858 Toolkit.Telemetry TRACE TelemetryEnvironment::shutdown
[task 2020-08-10T14:30:16.865Z] 14:30:16 INFO - 1597069816860 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::shutdown
[task 2020-08-10T14:30:16.865Z] 14:30:16 INFO - 1597069816860 Toolkit.Telemetry TRACE TelemetrySend::promisePendingPingActivity - Waiting for ping task
[task 2020-08-10T14:30:16.870Z] 14:30:16 INFO - 1597069816867 Toolkit.Telemetry TRACE TelemetryHealthPing::::shutdown()
[task 2020-08-10T14:30:16.871Z] 14:30:16 INFO - 1597069816868 Toolkit.Telemetry TRACE TelemetrySession::shutdownChromeProcess
[task 2020-08-10T14:30:16.871Z] 14:30:16 INFO - 1597069816868 Toolkit.Telemetry TRACE TelemetryEnvironment::unregisterChangeListener for TelemetrySession::onEnvironmentChange
[task 2020-08-10T14:30:16.871Z] 14:30:16 INFO - 1597069816868 Toolkit.Telemetry WARN TelemetryEnvironment::registerChangeListener - already shutdown
[task 2020-08-10T14:30:16.871Z] 14:30:16 INFO - 1597069816868 Toolkit.Telemetry TRACE TelemetryScheduler::shutdown
[task 2020-08-10T14:30:16.871Z] 14:30:16 INFO - 1597069816868 Toolkit.Telemetry TRACE TelemetrySession::saveShutdownPings
[task 2020-08-10T14:30:16.871Z] 14:30:16 INFO - 1597069816868 Toolkit.Telemetry TRACE TelemetrySession::getSessionPayload - reason: shutdown, clearSubsession: false
[task 2020-08-10T14:30:16.871Z] 14:30:16 INFO - 1597069816870 Toolkit.Telemetry TRACE TelemetrySession::assemblePayloadWithMeasurements - reason: shutdown, submitting subsession data: true
[task 2020-08-10T14:30:16.920Z] 14:30:16 INFO - 1597069816912 Toolkit.Telemetry ERROR TelemetrySession::assemblePayloadWithMeasurements - caught exception: TypeError: Telemetry.snapshotCapturedStacks is not a function(resource://gre/modules/TelemetrySession.jsm:743:44) JS Stack trace: assemblePayloadWithMeasurements/stacks<@TelemetrySession.jsm:743:44
[task 2020-08-10T14:30:16.920Z] 14:30:16 INFO - protect@TelemetrySession.jsm:619:16
[task 2020-08-10T14:30:16.920Z] 14:30:16 INFO - assemblePayloadWithMeasurements@TelemetrySession.jsm:743:27
[task 2020-08-10T14:30:16.920Z] 14:30:16 INFO - getSessionPayload@TelemetrySession.jsm:787:22
[task 2020-08-10T14:30:16.920Z] 14:30:16 INFO - saveShutdownPings@TelemetrySession.jsm:990:34
[task 2020-08-10T14:30:16.921Z] 14:30:16 INFO - shutdownChromeProcess/cleanup/<@TelemetrySession.jsm:1314:20
[task 2020-08-10T14:30:16.921Z] 14:30:16 INFO - cleanup@TelemetrySession.jsm:1321:9
[task 2020-08-10T14:30:16.921Z] 14:30:16 INFO - shutdownChromeProcess@TelemetrySession.jsm:1338:14
[task 2020-08-10T14:30:16.921Z] 14:30:16 INFO - shutdown@TelemetrySession.jsm:257:17
[task 2020-08-10T14:30:16.921Z] 14:30:16 INFO - _cleanupOnShutdown@TelemetryControllerParent.jsm:890:30
[task 2020-08-10T14:30:16.921Z] 14:30:16 INFO - observe@AsyncShutdown.jsm:554:16
[task 2020-08-10T14:30:16.921Z] 14:30:16 INFO - 1597069816914 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - type: main, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":false}
[task 2020-08-10T14:30:16.921Z] 14:30:16 INFO - 1597069816914 Toolkit.Telemetry TRACE TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":false}
[task 2020-08-10T14:30:16.940Z] 14:30:16 INFO - 1597069816936 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - ping assembled, id: 6eae75fa-003e-4add-a557-187bfbc1471a
[task 2020-08-10T14:30:16.940Z] 14:30:16 INFO - 1597069816937 Toolkit.Telemetry TRACE TelemetrySend::submitPing - ping id: 6eae75fa-003e-4add-a557-187bfbc1471a, options: {"usePingSender":false}
[task 2020-08-10T14:30:16.940Z] 14:30:16 INFO - 1597069816937 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2020-08-10T14:30:16.940Z] 14:30:16 INFO - 1597069816938 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2020-08-10T14:30:16.940Z] 14:30:16 INFO - 1597069816938 Toolkit.Telemetry TRACE TelemetrySend::submitPing - can't send ping now, persisting to disk - canSendNow: false
[task 2020-08-10T14:30:16.940Z] 14:30:16 INFO - 1597069816939 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - type: first-shutdown, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2020-08-10T14:30:16.941Z] 14:30:16 INFO - 1597069816939 Toolkit.Telemetry TRACE TelemetryController::assemblePing - Type first-shutdown, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2020-08-10T14:30:16.961Z] 14:30:16 INFO - 1597069816958 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - ping assembled, id: dd9e9c64-96f0-46d5-8d1e-103751597f8a
[task 2020-08-10T14:30:16.961Z] 14:30:16 INFO - 1597069816959 Toolkit.Telemetry TRACE TelemetrySend::submitPing - ping id: dd9e9c64-96f0-46d5-8d1e-103751597f8a, options: {"usePingSender":true}
[task 2020-08-10T14:30:16.961Z] 14:30:16 INFO - 1597069816959 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2020-08-10T14:30:16.966Z] 14:30:16 INFO - 1597069816961 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: Z:\task_1597069485\build\tmpk2hjjp.mozrunner\datareporting\archived\2020-08\1597069816854.78dc72b3-2c4e-43dd-b42b-7a78e7ea7875.event.jsonlz4
[task 2020-08-10T14:30:16.971Z] 14:30:16 INFO - 1597069816966 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: Z:\task_1597069485\build\tmpk2hjjp.mozrunner\saved-telemetry-pings\78dc72b3-2c4e-43dd-b42b-7a78e7ea7875
[task 2020-08-10T14:30:16.971Z] 14:30:16 INFO - 1597069816970 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: Z:\task_1597069485\build\tmpk2hjjp.mozrunner\datareporting\archived\2020-08\1597069816935.6eae75fa-003e-4add-a557-187bfbc1471a.main.jsonlz4
[task 2020-08-10T14:30:16.990Z] 14:30:16 INFO - 1597069816988 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: Z:\task_1597069485\build\tmpk2hjjp.mozrunner\saved-telemetry-pings\6eae75fa-003e-4add-a557-187bfbc1471a
[task 2020-08-10T14:30:17.008Z] 14:30:17 INFO - 1597069817006 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: Z:\task_1597069485\build\tmpk2hjjp.mozrunner\datareporting\archived\2020-08\1597069816957.dd9e9c64-96f0-46d5-8d1e-103751597f8a.first-shutdown.jsonlz4
[task 2020-08-10T14:30:17.027Z] 14:30:17 INFO - 1597069817024 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: Z:\task_1597069485\build\tmpk2hjjp.mozrunner\saved-telemetry-pings\dd9e9c64-96f0-46d5-8d1e-103751597f8a
[task 2020-08-10T14:30:17.057Z] 14:30:17 INFO - 1597069817052 Toolkit.Telemetry TRACE TelemetryStorage::savePendingPing - saved ping with id 78dc72b3-2c4e-43dd-b42b-7a78e7ea7875
[task 2020-08-10T14:30:17.057Z] 14:30:17 INFO - 1597069817052 Toolkit.Telemetry TRACE TelemetrySend::_sendWithPingSender - sending 78dc72b3-2c4e-43dd-b42b-7a78e7ea7875 to http://localhost:8000/pings/submit/telemetry/78dc72b3-2c4e-43dd-b42b-7a78e7ea7875/event/Firefox/82.0a1/default/20200810122447?v=4
[task 2020-08-10T14:30:17.057Z] 14:30:17 INFO - 1597069817052 Toolkit.Telemetry TRACE TelemetrySend::_sendWithPingSender - too late to send. Batching.
[task 2020-08-10T14:30:17.076Z] 14:30:17 INFO - 1597069817069 Toolkit.Telemetry TRACE TelemetryStorage::savePendingPing - saved ping with id 6eae75fa-003e-4add-a557-187bfbc1471a
[task 2020-08-10T14:30:17.085Z] 14:30:17 INFO - 1597069817079 Toolkit.Telemetry TRACE TelemetryStorage::savePendingPing - saved ping with id dd9e9c64-96f0-46d5-8d1e-103751597f8a
[task 2020-08-10T14:30:17.085Z] 14:30:17 INFO - 1597069817079 Toolkit.Telemetry TRACE TelemetrySend::_sendWithPingSender - sending dd9e9c64-96f0-46d5-8d1e-103751597f8a to http://localhost:8000/pings/submit/telemetry/dd9e9c64-96f0-46d5-8d1e-103751597f8a/first-shutdown/Firefox/82.0a1/default/20200810122447?v=4
[task 2020-08-10T14:30:17.085Z] 14:30:17 INFO - 1597069817079 Toolkit.Telemetry TRACE TelemetrySend::_sendWithPingSender - too late to send. Batching.
[task 2020-08-10T14:30:17.085Z] 14:30:17 INFO - 1597069817080 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2020-08-10T14:30:17.085Z] 14:30:17 INFO - 1597069817081 Toolkit.Telemetry TRACE TelemetryStorage::removeAbortedSessionPing - success
[task 2020-08-10T14:30:17.085Z] 14:30:17 INFO - 1597069817083 Toolkit.Telemetry TRACE TelemetrySend::flushPingSenderBatch - Sending 3 pings.
[task 2020-08-10T14:30:17.087Z] 14:30:17 INFO - 1597069817085 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2020-08-10T14:30:17.089Z] 14:30:17 INFO - 1597069817087 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2020-08-10T14:30:17.089Z] 14:30:17 INFO - 1597069817088 Marionette DEBUG Marionette stopped listening
[task 2020-08-10T14:30:17.372Z] 14:30:17 INFO - ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-08-10T14:30:18.254Z] 14:30:18 INFO - pingserver pings_handler received 'new-profile' ping
[task 2020-08-10T14:30:18.259Z] 14:30:18 INFO - pingserver pings_handler received 'event' ping
[task 2020-08-10T14:30:18.278Z] 14:30:18 INFO - pingserver pings_handler received 'first-shutdown' ping
[task 2020-08-10T14:30:18.513Z] 14:30:18 INFO - Assertion failure: Request::mDisconnected, at z:/build/workspace/obj-build/dist/include\mozilla/MozPromise.h:447
[task 2020-08-10T14:30:18.631Z] 14:30:18 INFO - #01: v8::internal::RegExpParser::zone[Z:\task_1597069485\build\application\firefox\xul.dll +0x350620]
[task 2020-08-10T14:30:18.631Z] 14:30:18 INFO - #02: v8::internal::RegExpParser::zone[Z:\task_1597069485\build\application\firefox\xul.dll +0x34119c]
[task 2020-08-10T14:30:18.631Z] 14:30:18 INFO - #03: v8::internal::RegExpParser::zone[Z:\task_1597069485\build\application\firefox\xul.dll +0x34872e]
[task 2020-08-10T14:30:18.631Z] 14:30:18 INFO - #04: v8::internal::RegExpParser::zone[Z:\task_1597069485\build\application\firefox\xul.dll +0x341d59]
[task 2020-08-10T14:30:18.631Z] 14:30:18 INFO - #05: v8::internal::RegExpParser::zone[Z:\task_1597069485\build\application\firefox\xul.dll +0x346272]
[task 2020-08-10T14:30:18.631Z] 14:30:18 INFO - #06: v8::internal::RegExpParser::zone[Z:\task_1597069485\build\application\firefox\xul.dll +0x334364]
[task 2020-08-10T14:30:18.631Z] 14:30:18 INFO - #07: v8::internal::RegExpParser::isolate[Z:\task_1597069485\build\application\firefox\xul.dll +0x409f6a]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #08: workerlz4_maxCompressedSize[Z:\task_1597069485\build\application\firefox\xul.dll +0xe242eac]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #09: workerlz4_maxCompressedSize[Z:\task_1597069485\build\application\firefox\xul.dll +0xe26ce7c]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #10: workerlz4_maxCompressedSize[Z:\task_1597069485\build\application\firefox\xul.dll +0xe262f7a]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #11: workerlz4_maxCompressedSize[Z:\task_1597069485\build\application\firefox\xul.dll +0xe264109]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #12: Ordinal0[Z:\task_1597069485\build\application\firefox\firefox.exe +0x2127]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #13: Ordinal0[Z:\task_1597069485\build\application\firefox\firefox.exe +0x1495]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #14: TargetNtUnmapViewOfSection[Z:\task_1597069485\build\application\firefox\firefox.exe +0x1066b8]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #15: BaseThreadInitThunk[C:\Windows\System32\KERNEL32.DLL +0x13034]
[task 2020-08-10T14:30:18.632Z] 14:30:18 INFO - #16: RtlUserThreadStart[C:\Windows\SYSTEM32\ntdll.dll +0x71461]

The exception is logged and ignored (see the use of protect at the call site, so I think this may be a red herring.

That being said, those lines should've been removed as part of bug 1655835, so I'll just go and do that now.

Assignee: nobody → chutten
Severity: normal → S4
Status: NEW → ASSIGNED
Priority: P5 → P1
Pushed by chutten@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e05bbc1d4de9
Remove the last of Telemetry's 'capturestacks' mentions r=janerik

https://hg.mozilla.org/mozilla-central/rev/e05bbc1d4de9

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox81: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 81 Branch
See Also: → 1660137
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: