Closed Bug 1457984 Opened 7 years ago Closed 3 years ago

Intermittent toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_sendCheckOverride - [test_sendCheckOverride : 528] Must receive a ping of the expected type - "health" == "test-sendCheckOverride"

Categories

(Toolkit :: Telemetry, defect, P2)

defect

Tracking

()

RESOLVED FIXED
Tracking Status
firefox-esr68 --- disabled

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell disabled])

Attachments

(2 files)

Filed by: archaeopteryx [at] coole-files.de https://treeherder.mozilla.org/logviewer.html#?job_id=176300079&repo=mozilla-beta https://queue.taskcluster.net/v1/task/OVEow6lSTSGmKIegnWFcug/runs/0/artifacts/public/logs/live_backing.log [task 2018-04-30T16:58:42.634Z] 16:58:42 INFO - TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_persistCurrentPingsOnShutdown - [test_persistCurrentPingsOnShutdown : 489] Should have the correct pending ping count - 5 == 5 [task 2018-04-30T16:58:42.635Z] 16:58:42 INFO - (xpcshell/head.js) | test run_next_test 9 pending (2) [task 2018-04-30T16:58:42.636Z] 16:58:42 INFO - (xpcshell/head.js) | test test_persistCurrentPingsOnShutdown finished (2) [task 2018-04-30T16:58:42.638Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520875 Toolkit.Telemetry TRACE TelemetrySend::reset" [task 2018-04-30T16:58:42.642Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520875 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::reset" [task 2018-04-30T16:58:42.644Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520875 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::shutdown" [task 2018-04-30T16:58:42.645Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520875 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::start" [task 2018-04-30T16:58:42.647Z] 16:58:42 INFO - toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | Starting test_sendCheckOverride [task 2018-04-30T16:58:42.648Z] 16:58:42 INFO - (xpcshell/head.js) | test test_sendCheckOverride pending (2) [task 2018-04-30T16:58:42.648Z] 16:58:42 INFO - (xpcshell/head.js) | test run_next_test 9 finished (2) [task 2018-04-30T16:58:42.649Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520877 Toolkit.Telemetry TRACE TelemetryController::shutdown" [task 2018-04-30T16:58:42.651Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520877 Toolkit.Telemetry TRACE TelemetryReportingPolicy::shutdown" [task 2018-04-30T16:58:42.653Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520877 Toolkit.Telemetry TRACE TelemetryEnvironment::shutdown" [task 2018-04-30T16:58:42.656Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1525107520878 Toolkit.Telemetry ERROR TelemetrySend::shutdown - failed to remove observer for idle-daily: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: shutdown :: line 758" data: no] Stack trace: shutdown()@resource://gre/modules/TelemetrySend.jsm:758 [task 2018-04-30T16:58:42.657Z] 16:58:42 INFO - shutdown()@resource://gre/modules/TelemetrySend.jsm:215 [task 2018-04-30T16:58:42.658Z] 16:58:42 INFO - _cleanupOnShutdown()@resource://gre/modules/TelemetryController.jsm:749 [task 2018-04-30T16:58:42.659Z] 16:58:42 INFO - shutdown()@resource://gre/modules/TelemetryController.jsm:792 [task 2018-04-30T16:58:42.660Z] 16:58:42 INFO - testShutdown()@resource://gre/modules/TelemetryController.jsm:146 [task 2018-04-30T16:58:42.662Z] 16:58:42 INFO - test_sendCheckOverride()@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:499 [task 2018-04-30T16:58:42.664Z] 16:58:42 INFO - run_next_test/_run_next_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:1425 [task 2018-04-30T16:58:42.665Z] 16:58:42 INFO - _run_next_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:1425 [task 2018-04-30T16:58:42.665Z] 16:58:42 INFO - run()@/builds/worker/workspace/build/tests/xpcshell/head.js:676 [task 2018-04-30T16:58:42.666Z] 16:58:42 INFO - _do_main()@/builds/worker/workspace/build/tests/xpcshell/head.js:215 [task 2018-04-30T16:58:42.667Z] 16:58:42 INFO - _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:521 [task 2018-04-30T16:58:42.668Z] 16:58:42 INFO - -e:1" {file: "resource://gre/modules/Log.jsm" line: 853}] [task 2018-04-30T16:58:42.668Z] 16:58:42 INFO - App_append@resource://gre/modules/Log.jsm:853:9 [task 2018-04-30T16:58:42.669Z] 16:58:42 INFO - log@resource://gre/modules/Log.jsm:467:7 [task 2018-04-30T16:58:42.670Z] 16:58:42 INFO - getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:590:14 [task 2018-04-30T16:58:42.671Z] 16:58:42 INFO - error@resource://gre/modules/Log.jsm:475:5 [task 2018-04-30T16:58:42.671Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetrySend.jsm:760:9 [task 2018-04-30T16:58:42.672Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetrySend.jsm:215:12 [task 2018-04-30T16:58:42.672Z] 16:58:42 INFO - _cleanupOnShutdown@resource://gre/modules/TelemetryController.jsm:749:13 [task 2018-04-30T16:58:42.673Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetryController.jsm:792:14 [task 2018-04-30T16:58:42.674Z] 16:58:42 INFO - testShutdown@resource://gre/modules/TelemetryController.jsm:146:12 [task 2018-04-30T16:58:42.674Z] 16:58:42 INFO - test_sendCheckOverride@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:499:9 [task 2018-04-30T16:58:42.675Z] 16:58:42 INFO - run_next_test/_run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1425:22 [task 2018-04-30T16:58:42.676Z] 16:58:42 INFO - _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1425:10 [task 2018-04-30T16:58:42.676Z] 16:58:42 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:676:9 [task 2018-04-30T16:58:42.677Z] 16:58:42 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:215:3 [task 2018-04-30T16:58:42.678Z] 16:58:42 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:521:5 [task 2018-04-30T16:58:42.678Z] 16:58:42 INFO - @-e:1:1 [task 2018-04-30T16:58:42.679Z] 16:58:42 INFO - " [task 2018-04-30T16:58:42.680Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1525107520879 Toolkit.Telemetry ERROR TelemetrySend::shutdown - failed to remove observer for quit-application-granted: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: shutdown :: line 758" data: no] Stack trace: shutdown()@resource://gre/modules/TelemetrySend.jsm:758 [task 2018-04-30T16:58:42.680Z] 16:58:42 INFO - shutdown()@resource://gre/modules/TelemetrySend.jsm:215 [task 2018-04-30T16:58:42.681Z] 16:58:42 INFO - _cleanupOnShutdown()@resource://gre/modules/TelemetryController.jsm:749 [task 2018-04-30T16:58:42.681Z] 16:58:42 INFO - shutdown()@resource://gre/modules/TelemetryController.jsm:792 [task 2018-04-30T16:58:42.682Z] 16:58:42 INFO - testShutdown()@resource://gre/modules/TelemetryController.jsm:146 [task 2018-04-30T16:58:42.683Z] 16:58:42 INFO - test_sendCheckOverride()@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:499 [task 2018-04-30T16:58:42.683Z] 16:58:42 INFO - run_next_test/_run_next_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:1425 [task 2018-04-30T16:58:42.684Z] 16:58:42 INFO - _run_next_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:1425 [task 2018-04-30T16:58:42.684Z] 16:58:42 INFO - run()@/builds/worker/workspace/build/tests/xpcshell/head.js:676 [task 2018-04-30T16:58:42.685Z] 16:58:42 INFO - _do_main()@/builds/worker/workspace/build/tests/xpcshell/head.js:215 [task 2018-04-30T16:58:42.686Z] 16:58:42 INFO - _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:521 [task 2018-04-30T16:58:42.686Z] 16:58:42 INFO - -e:1" {file: "resource://gre/modules/Log.jsm" line: 853}] [task 2018-04-30T16:58:42.687Z] 16:58:42 INFO - App_append@resource://gre/modules/Log.jsm:853:9 [task 2018-04-30T16:58:42.687Z] 16:58:42 INFO - log@resource://gre/modules/Log.jsm:467:7 [task 2018-04-30T16:58:42.688Z] 16:58:42 INFO - getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:590:14 [task 2018-04-30T16:58:42.688Z] 16:58:42 INFO - error@resource://gre/modules/Log.jsm:475:5 [task 2018-04-30T16:58:42.689Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetrySend.jsm:760:9 [task 2018-04-30T16:58:42.690Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetrySend.jsm:215:12 [task 2018-04-30T16:58:42.690Z] 16:58:42 INFO - _cleanupOnShutdown@resource://gre/modules/TelemetryController.jsm:749:13 [task 2018-04-30T16:58:42.691Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetryController.jsm:792:14 [task 2018-04-30T16:58:42.691Z] 16:58:42 INFO - testShutdown@resource://gre/modules/TelemetryController.jsm:146:12 [task 2018-04-30T16:58:42.692Z] 16:58:42 INFO - test_sendCheckOverride@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:499:9 [task 2018-04-30T16:58:42.693Z] 16:58:42 INFO - run_next_test/_run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1425:22 [task 2018-04-30T16:58:42.693Z] 16:58:42 INFO - _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1425:10 [task 2018-04-30T16:58:42.694Z] 16:58:42 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:676:9 [task 2018-04-30T16:58:42.694Z] 16:58:42 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:215:3 [task 2018-04-30T16:58:42.695Z] 16:58:42 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:521:5 [task 2018-04-30T16:58:42.696Z] 16:58:42 INFO - @-e:1:1 [task 2018-04-30T16:58:42.696Z] 16:58:42 INFO - " [task 2018-04-30T16:58:42.697Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1525107520880 Toolkit.Telemetry ERROR TelemetrySend::shutdown - failed to remove observer for quit-application-forced: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: shutdown :: line 758" data: no] Stack trace: shutdown()@resource://gre/modules/TelemetrySend.jsm:758 [task 2018-04-30T16:58:42.698Z] 16:58:42 INFO - shutdown()@resource://gre/modules/TelemetrySend.jsm:215 [task 2018-04-30T16:58:42.698Z] 16:58:42 INFO - _cleanupOnShutdown()@resource://gre/modules/TelemetryController.jsm:749 [task 2018-04-30T16:58:42.699Z] 16:58:42 INFO - shutdown()@resource://gre/modules/TelemetryController.jsm:792 [task 2018-04-30T16:58:42.699Z] 16:58:42 INFO - testShutdown()@resource://gre/modules/TelemetryController.jsm:146 [task 2018-04-30T16:58:42.699Z] 16:58:42 INFO - test_sendCheckOverride()@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:499 [task 2018-04-30T16:58:42.700Z] 16:58:42 INFO - run_next_test/_run_next_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:1425 [task 2018-04-30T16:58:42.701Z] 16:58:42 INFO - _run_next_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:1425 [task 2018-04-30T16:58:42.701Z] 16:58:42 INFO - run()@/builds/worker/workspace/build/tests/xpcshell/head.js:676 [task 2018-04-30T16:58:42.702Z] 16:58:42 INFO - _do_main()@/builds/worker/workspace/build/tests/xpcshell/head.js:215 [task 2018-04-30T16:58:42.703Z] 16:58:42 INFO - _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:521 [task 2018-04-30T16:58:42.703Z] 16:58:42 INFO - -e:1" {file: "resource://gre/modules/Log.jsm" line: 853}] [task 2018-04-30T16:58:42.704Z] 16:58:42 INFO - App_append@resource://gre/modules/Log.jsm:853:9 [task 2018-04-30T16:58:42.705Z] 16:58:42 INFO - log@resource://gre/modules/Log.jsm:467:7 [task 2018-04-30T16:58:42.706Z] 16:58:42 INFO - getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:590:14 [task 2018-04-30T16:58:42.706Z] 16:58:42 INFO - error@resource://gre/modules/Log.jsm:475:5 [task 2018-04-30T16:58:42.707Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetrySend.jsm:760:9 [task 2018-04-30T16:58:42.707Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetrySend.jsm:215:12 [task 2018-04-30T16:58:42.708Z] 16:58:42 INFO - _cleanupOnShutdown@resource://gre/modules/TelemetryController.jsm:749:13 [task 2018-04-30T16:58:42.708Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetryController.jsm:792:14 [task 2018-04-30T16:58:42.709Z] 16:58:42 INFO - testShutdown@resource://gre/modules/TelemetryController.jsm:146:12 [task 2018-04-30T16:58:42.710Z] 16:58:42 INFO - test_sendCheckOverride@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:499:9 [task 2018-04-30T16:58:42.710Z] 16:58:42 INFO - run_next_test/_run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1425:22 [task 2018-04-30T16:58:42.711Z] 16:58:42 INFO - _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1425:10 [task 2018-04-30T16:58:42.711Z] 16:58:42 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:676:9 [task 2018-04-30T16:58:42.712Z] 16:58:42 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:215:3 [task 2018-04-30T16:58:42.712Z] 16:58:42 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:521:5 [task 2018-04-30T16:58:42.713Z] 16:58:42 INFO - @-e:1:1 [task 2018-04-30T16:58:42.713Z] 16:58:42 INFO - " [task 2018-04-30T16:58:42.714Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1525107520880 Toolkit.Telemetry ERROR TelemetrySend::shutdown - failed to remove observer for profile-change-net-teardown: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: shutdown :: line 758" data: no] Stack trace: shutdown()@resource://gre/modules/TelemetrySend.jsm:758 [task 2018-04-30T16:58:42.715Z] 16:58:42 INFO - shutdown()@resource://gre/modules/TelemetrySend.jsm:215 [task 2018-04-30T16:58:42.715Z] 16:58:42 INFO - _cleanupOnShutdown()@resource://gre/modules/TelemetryController.jsm:749 [task 2018-04-30T16:58:42.716Z] 16:58:42 INFO - shutdown()@resource://gre/modules/TelemetryController.jsm:792 [task 2018-04-30T16:58:42.717Z] 16:58:42 INFO - testShutdown()@resource://gre/modules/TelemetryController.jsm:146 [task 2018-04-30T16:58:42.717Z] 16:58:42 INFO - test_sendCheckOverride()@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:499 [task 2018-04-30T16:58:42.718Z] 16:58:42 INFO - run_next_test/_run_next_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:1425 [task 2018-04-30T16:58:42.719Z] 16:58:42 INFO - _run_next_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:1425 [task 2018-04-30T16:58:42.719Z] 16:58:42 INFO - run()@/builds/worker/workspace/build/tests/xpcshell/head.js:676 [task 2018-04-30T16:58:42.720Z] 16:58:42 INFO - _do_main()@/builds/worker/workspace/build/tests/xpcshell/head.js:215 [task 2018-04-30T16:58:42.720Z] 16:58:42 INFO - _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:521 [task 2018-04-30T16:58:42.721Z] 16:58:42 INFO - -e:1" {file: "resource://gre/modules/Log.jsm" line: 853}] [task 2018-04-30T16:58:42.722Z] 16:58:42 INFO - App_append@resource://gre/modules/Log.jsm:853:9 [task 2018-04-30T16:58:42.722Z] 16:58:42 INFO - log@resource://gre/modules/Log.jsm:467:7 [task 2018-04-30T16:58:42.723Z] 16:58:42 INFO - getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:590:14 [task 2018-04-30T16:58:42.723Z] 16:58:42 INFO - error@resource://gre/modules/Log.jsm:475:5 [task 2018-04-30T16:58:42.724Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetrySend.jsm:760:9 [task 2018-04-30T16:58:42.725Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetrySend.jsm:215:12 [task 2018-04-30T16:58:42.725Z] 16:58:42 INFO - _cleanupOnShutdown@resource://gre/modules/TelemetryController.jsm:749:13 [task 2018-04-30T16:58:42.726Z] 16:58:42 INFO - shutdown@resource://gre/modules/TelemetryController.jsm:792:14 [task 2018-04-30T16:58:42.726Z] 16:58:42 INFO - testShutdown@resource://gre/modules/TelemetryController.jsm:146:12 [task 2018-04-30T16:58:42.727Z] 16:58:42 INFO - test_sendCheckOverride@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:499:9 [task 2018-04-30T16:58:42.728Z] 16:58:42 INFO - run_next_test/_run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1425:22 [task 2018-04-30T16:58:42.728Z] 16:58:42 INFO - _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1425:10 [task 2018-04-30T16:58:42.729Z] 16:58:42 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:676:9 [task 2018-04-30T16:58:42.730Z] 16:58:42 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:215:3 [task 2018-04-30T16:58:42.730Z] 16:58:42 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:521:5 [task 2018-04-30T16:58:42.731Z] 16:58:42 INFO - @-e:1:1 [task 2018-04-30T16:58:42.732Z] 16:58:42 INFO - " [task 2018-04-30T16:58:42.733Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520881 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::shutdown" [task 2018-04-30T16:58:42.733Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520881 Toolkit.Telemetry TRACE TelemetrySend::promisePendingPingActivity - Waiting for ping task" [task 2018-04-30T16:58:42.734Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520881 Toolkit.Telemetry TRACE TelemetryHealthPing::::shutdown()" [task 2018-04-30T16:58:42.734Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520881 Toolkit.Telemetry TRACE TelemetryHealthPing::::_submitPing(shutdown)" [task 2018-04-30T16:58:42.735Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520881 Toolkit.Telemetry TRACE TelemetryHealthPing::::_assemblePayload()" [task 2018-04-30T16:58:42.736Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520881 Toolkit.Telemetry TRACE TelemetryHealthPing::::_clearData()" [task 2018-04-30T16:58:42.737Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520883 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - type: health, aOptions: {"addClientId":true,"usePingSender":true,"addEnvironment":false}" [task 2018-04-30T16:58:42.737Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520883 Toolkit.Telemetry TRACE TelemetryController::assemblePing - Type health, aOptions {"addClientId":true,"usePingSender":true,"addEnvironment":false}" [task 2018-04-30T16:58:42.738Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520884 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - ping assembled, id: ac12f4aa-cbcb-466f-ab55-6964b0e74ed8" [task 2018-04-30T16:58:42.738Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520884 Toolkit.Telemetry TRACE TelemetrySend::submitPing - ping id: ac12f4aa-cbcb-466f-ab55-6964b0e74ed8, options: {"usePingSender":true}" [task 2018-04-30T16:58:42.739Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520884 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet." [task 2018-04-30T16:58:42.740Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520886 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: /tmp/xpc-profile-o9yv2O/datareporting/archived/2010-02/1265029740000.ac12f4aa-cbcb-466f-ab55-6964b0e74ed8.health.jsonlz4" [task 2018-04-30T16:58:42.741Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520887 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: /tmp/xpc-profile-o9yv2O/saved-telemetry-pings/ac12f4aa-cbcb-466f-ab55-6964b0e74ed8" [task 2018-04-30T16:58:42.741Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520888 Toolkit.Telemetry TRACE TelemetryStorage::savePendingPing - saved ping with id ac12f4aa-cbcb-466f-ab55-6964b0e74ed8" [task 2018-04-30T16:58:42.742Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520888 Toolkit.Telemetry TRACE TelemetrySend::_sendWithPingSender - sending ac12f4aa-cbcb-466f-ab55-6964b0e74ed8 to http://localhost:34746/submit/telemetry/ac12f4aa-cbcb-466f-ab55-6964b0e74ed8/health///beta/?v=4" [task 2018-04-30T16:58:42.743Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520893 Toolkit.Telemetry TRACE TelemetrySession::shutdownChromeProcess" [task 2018-04-30T16:58:42.743Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520893 Toolkit.Telemetry TRACE TelemetryEnvironment::unregisterChangeListener for TelemetrySession::onEnvironmentChange" [task 2018-04-30T16:58:42.744Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520893 Toolkit.Telemetry WARN TelemetryEnvironment::registerChangeListener - already shutdown" [task 2018-04-30T16:58:42.744Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520893 Toolkit.Telemetry TRACE TelemetryScheduler::shutdown" [task 2018-04-30T16:58:42.745Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520894 Toolkit.Telemetry TRACE TelemetrySession::saveShutdownPings" [task 2018-04-30T16:58:42.746Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520894 Toolkit.Telemetry TRACE TelemetrySession::getSessionPayload - reason: shutdown, clearSubsession: false" [task 2018-04-30T16:58:42.746Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520904 Toolkit.Telemetry TRACE TelemetrySession::assemblePayloadWithMeasurements - reason: shutdown, submitting subsession data: true" [task 2018-04-30T16:58:42.747Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520916 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - type: main, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":false}" [task 2018-04-30T16:58:42.748Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520916 Toolkit.Telemetry TRACE TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":false}" [task 2018-04-30T16:58:42.748Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520919 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - ping assembled, id: 443480d6-83d1-42a7-bc00-9b845c931a5f" [task 2018-04-30T16:58:42.749Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520920 Toolkit.Telemetry TRACE TelemetrySend::submitPing - ping id: 443480d6-83d1-42a7-bc00-9b845c931a5f, options: {"usePingSender":false}" [task 2018-04-30T16:58:42.750Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520920 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet." [task 2018-04-30T16:58:42.750Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520920 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet." [task 2018-04-30T16:58:42.751Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520920 Toolkit.Telemetry TRACE TelemetrySend::submitPing - can't send ping now, persisting to disk - canSendNow: false" [task 2018-04-30T16:58:42.752Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520924 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: /tmp/xpc-profile-o9yv2O/datareporting/archived/2010-02/1265029740000.443480d6-83d1-42a7-bc00-9b845c931a5f.main.jsonlz4" [task 2018-04-30T16:58:42.752Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520927 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: /tmp/xpc-profile-o9yv2O/saved-telemetry-pings/443480d6-83d1-42a7-bc00-9b845c931a5f" [task 2018-04-30T16:58:42.753Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520929 Toolkit.Telemetry TRACE TelemetryStorage::savePendingPing - saved ping with id 443480d6-83d1-42a7-bc00-9b845c931a5f" [task 2018-04-30T16:58:42.754Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520930 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation." [task 2018-04-30T16:58:42.754Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520932 Toolkit.Telemetry TRACE TelemetryStorage::removeAbortedSessionPing - no such file" [task 2018-04-30T16:58:42.755Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520933 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation." [task 2018-04-30T16:58:42.755Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520933 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation." [task 2018-04-30T16:58:42.756Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520933 Toolkit.Telemetry TRACE TelemetryStorage::removePendingPings - removing all pending pings" [task 2018-04-30T16:58:42.757Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520943 Toolkit.Telemetry TRACE TelemetryController::setupTelemetry" [task 2018-04-30T16:58:42.758Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520943 Toolkit.Telemetry TRACE TelemetryController::registerJsProbes - registering builtin JS probes" [task 2018-04-30T16:58:42.758Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520943 Toolkit.Telemetry TRACE TelemetryController::registerScalarProbes - registering scalar builtin JS probes" [task 2018-04-30T16:58:42.759Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520943 Toolkit.Telemetry TRACE TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json" [task 2018-04-30T16:58:42.759Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520943 Toolkit.Telemetry TRACE TelemetryReportingPolicy::setup" [task 2018-04-30T16:58:42.760Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520943 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true" [task 2018-04-30T16:58:42.761Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520943 Toolkit.Telemetry TRACE TelemetrySession::earlyInit" [task 2018-04-30T16:58:42.761Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520943 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet." [task 2018-04-30T16:58:42.762Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520944 Toolkit.Telemetry TRACE UpdatePing::init - enabled: true" [task 2018-04-30T16:58:42.763Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520944 Toolkit.Telemetry TRACE TelemetrySend::reset" [task 2018-04-30T16:58:42.763Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520944 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::reset" [task 2018-04-30T16:58:42.764Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520944 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::shutdown" [task 2018-04-30T16:58:42.764Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520944 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::start" [task 2018-04-30T16:58:42.765Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520944 Toolkit.Telemetry TRACE TelemetryController::registerEventProbes - registering builtin JS Event probes" [task 2018-04-30T16:58:42.765Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520944 Toolkit.Telemetry TRACE TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json" [task 2018-04-30T16:58:42.766Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520947 Toolkit.Telemetry TRACE TelemetrySend::setup" [task 2018-04-30T16:58:42.767Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520947 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet." [task 2018-04-30T16:58:42.768Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520947 Toolkit.Telemetry TRACE TelemetryStorage::_scanPendingPings" [task 2018-04-30T16:58:42.768Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520947 Toolkit.Telemetry TRACE TelemetryStorage::_migrateAppDataPings" [task 2018-04-30T16:58:42.769Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520948 Toolkit.Telemetry TRACE TelemetryStorage::_migrateAppDataPings - userApplicationDataDir is not defined. Is this a test?" [task 2018-04-30T16:58:42.770Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520951 Toolkit.Telemetry TRACE PingServer::defaultPingHandler() - POST http://localhost:34746/submit/telemetry/ac12f4aa-cbcb-466f-ab55-6964b0e74ed8/health///beta/" [task 2018-04-30T16:58:42.770Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520972 Toolkit.Telemetry INFO TelemetrySend::_checkPendingPings - pending ping count: 0" [task 2018-04-30T16:58:42.771Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520973 Toolkit.Telemetry TRACE TelemetrySend::_checkPendingPings - no pending pings" [task 2018-04-30T16:58:42.772Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520973 Toolkit.Telemetry TRACE TelemetryStorage::_enforcePendingPingsQuota" [task 2018-04-30T16:58:42.772Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520973 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true" [task 2018-04-30T16:58:42.773Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520973 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask iteration" [task 2018-04-30T16:58:42.774Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520973 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0" [task 2018-04-30T16:58:42.774Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520973 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0" [task 2018-04-30T16:58:42.775Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520973 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out" [task 2018-04-30T16:58:42.775Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520974 Toolkit.Telemetry TRACE TelemetrySession::delayedInit" [task 2018-04-30T16:58:42.776Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520974 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation." [task 2018-04-30T16:58:42.777Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520976 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation." [task 2018-04-30T16:58:42.778Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520984 Toolkit.Telemetry TRACE TelemetryStorage::loadPingfile - unreadable ping /tmp/xpc-profile-o9yv2O/datareporting/aborted-session-ping: {"operation":"open","path":"/tmp/xpc-profile-o9yv2O/datareporting/aborted-session-ping","unixErrno":2}" [task 2018-04-30T16:58:42.778Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520985 Toolkit.Telemetry TRACE TelemetryStorage::loadAbortedSessionPing - no such file" [task 2018-04-30T16:58:42.779Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520985 Toolkit.Telemetry TRACE TelemetryController::checkAbortedSessionPing - found aborted-session ping: false" [task 2018-04-30T16:58:42.779Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520985 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange" [task 2018-04-30T16:58:42.780Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520985 Toolkit.Telemetry TRACE TelemetryScheduler::init" [task 2018-04-30T16:58:42.781Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520985 Toolkit.Telemetry TRACE TelemetryScheduler::_rescheduleTimeout - isUserIdle: false" [task 2018-04-30T16:58:42.781Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520985 Toolkit.Telemetry TRACE TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Mon Feb 01 2010 13:14:00 GMT+0000 (UTC)" [task 2018-04-30T16:58:42.782Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520985 Toolkit.Telemetry TRACE TelemetryStorage::cleanArchiveTask" [task 2018-04-30T16:58:42.783Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520985 Toolkit.Telemetry TRACE TelemetryStorage::removeFHRDatabase" [task 2018-04-30T16:58:42.783Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520986 Toolkit.Telemetry TRACE TelemetrySend::reset" [task 2018-04-30T16:58:42.784Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520987 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::reset" [task 2018-04-30T16:58:42.784Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520987 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::shutdown" [task 2018-04-30T16:58:42.785Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520987 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::start" [task 2018-04-30T16:58:42.786Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520987 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - type: test-sendCheckOverride, aOptions: {"addClientId":false,"addEnvironment":false,"usePingSender":false}" [task 2018-04-30T16:58:42.787Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520987 Toolkit.Telemetry TRACE TelemetryController::assemblePing - Type test-sendCheckOverride, aOptions {"addClientId":false,"addEnvironment":false,"usePingSender":false}" [task 2018-04-30T16:58:42.787Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520987 Toolkit.Telemetry TRACE TelemetryController::submitExternalPing - ping assembled, id: 1be651ab-1f31-4e90-9bbe-fec56697ffa2" [task 2018-04-30T16:58:42.788Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520987 Toolkit.Telemetry TRACE TelemetrySend::submitPing - ping id: 1be651ab-1f31-4e90-9bbe-fec56697ffa2, options: {"usePingSender":false}" [task 2018-04-30T16:58:42.788Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520987 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet." [task 2018-04-30T16:58:42.789Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520988 Toolkit.Telemetry TRACE TelemetrySend::submitPing - can send pings, trying to send now" [task 2018-04-30T16:58:42.789Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520988 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true" [task 2018-04-30T16:58:42.790Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520988 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask iteration" [task 2018-04-30T16:58:42.791Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520988 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 1" [task 2018-04-30T16:58:42.791Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520988 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 1" [task 2018-04-30T16:58:42.792Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520988 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - triggering sending of 0 pings now, 0 pings waiting" [task 2018-04-30T16:58:42.793Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520988 Toolkit.Telemetry TRACE TelemetrySend::_doPing - server: http://localhost:42789, persisted: false, id: 1be651ab-1f31-4e90-9bbe-fec56697ffa2" [task 2018-04-30T16:58:42.793Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520991 Toolkit.Telemetry TRACE TelemetryStorage::_purgeOldPings" [task 2018-04-30T16:58:42.794Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107520998 Toolkit.Telemetry TRACE PingServer::defaultPingHandler() - POST http://localhost:42789/submit/telemetry/1be651ab-1f31-4e90-9bbe-fec56697ffa2/test-sendCheckOverride///beta/" [task 2018-04-30T16:58:42.795Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107521000 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: /tmp/xpc-profile-o9yv2O/datareporting/archived/2010-02/1265029740000.1be651ab-1f31-4e90-9bbe-fec56697ffa2.test-sendCheckOverride.jsonlz4" [task 2018-04-30T16:58:42.795Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107521001 Toolkit.Telemetry INFO TelemetrySend::_doPing - successfully loaded, status: 200" [task 2018-04-30T16:58:42.796Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107521001 Toolkit.Telemetry TRACE TelemetrySend::_onPingRequestFinished - success: true, persisted: false" [task 2018-04-30T16:58:42.796Z] 16:58:42 INFO - "CONSOLE_MESSAGE: (info) 1525107521002 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - bailing out after sending, shutdown: false, pendingPingCount: 0" [task 2018-04-30T16:58:42.797Z] 16:58:42 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_sendCheckOverride - [test_sendCheckOverride : 528] Must receive a ping of the expected type - "health" == "test-sendCheckOverride" [task 2018-04-30T16:58:42.798Z] 16:58:42 INFO - /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:test_sendCheckOverride:528 [task 2018-04-30T16:58:42.798Z] 16:58:42 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:215 [task 2018-04-30T16:58:42.799Z] 16:58:42 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:521 [task 2018-04-30T16:58:42.799Z] 16:58:42 INFO - -e:null:1 [task 2018-04-30T16:58:42.800Z] 16:58:42 INFO - exiting test [task 2018-04-30T16:58:42.800Z] 16:58:42 INFO - Unexpected exception NS_ERROR_ABORT: [task 2018-04-30T16:58:42.801Z] 16:58:42 INFO - _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:730:9 [task 2018-04-30T16:58:42.801Z] 16:58:42 INFO - do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:837:5 [task 2018-04-30T16:58:42.802Z] 16:58:42 INFO - Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:55:5 [task 2018-04-30T16:58:42.802Z] 16:58:42 INFO - proto.report@resource://testing-common/Assert.jsm:210:5 [task 2018-04-30T16:58:42.803Z] 16:58:42 INFO - equal@resource://testing-common/Assert.jsm:242:3 [task 2018-04-30T16:58:42.804Z] 16:58:42 INFO - test_sendCheckOverride@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:528:3 [task 2018-04-30T16:58:42.804Z] 16:58:42 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:215:3 [task 2018-04-30T16:58:42.805Z] 16:58:42 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:521:5 [task 2018-04-30T16:58:42.805Z] 16:58:42 INFO - @-e:1:1

Failure reappeared on this merge https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=0e9e744accd3ed7b7b0ff2436904ed78a92bf9e2

Bryce is this from bug 1532391?

There are 18 total failures in the last 3 days on linux64-shippable opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=245516267&repo=autoland&lineNumber=2203

[task 2019-05-09T11:36:45.090Z] 11:36:45 INFO - TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js
[task 2019-05-09T11:38:17.635Z] 11:38:17 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | xpcshell return code: 0
[task 2019-05-09T11:38:17.636Z] 11:38:17 INFO - TEST-INFO took 92537ms
[task 2019-05-09T11:38:17.636Z] 11:38:17 INFO - >>>>>>>
[task 2019-05-09T11:38:17.640Z] 11:38:17 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-05-09T11:38:17.640Z] 11:38:17 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2019-05-09T11:38:17.642Z] 11:38:17 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2019-05-09T11:38:17.642Z] 11:38:17 INFO - running event loop
[task 2019-05-09T11:38:17.643Z] 11:38:17 INFO - toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | Starting test_setup

[task 2019-05-09T11:38:19.433Z] 11:38:19 INFO - TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_sendCheckOverride - [test_sendCheckOverride : 1] Known clientId should never appear in a ping on the server - "c0ffeec0-ffee-c0ff-eec0-ffeec0ffeec0" != "38178b0d-0302-409a-96e2-4241bfeb478c"
[task 2019-05-09T11:38:19.434Z] 11:38:19 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_sendCheckOverride - [test_sendCheckOverride : 552] Must receive a ping of the expected type - "health" == "test-sendCheckOverride"
[task 2019-05-09T11:38:19.434Z] 11:38:19 INFO - /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:test_sendCheckOverride:552
[task 2019-05-09T11:38:19.435Z] 11:38:19 INFO - exiting test
[task 2019-05-09T11:38:19.435Z] 11:38:19 INFO - Unexpected exception NS_ERROR_ABORT:
[task 2019-05-09T11:38:19.435Z] 11:38:19 INFO - _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:742:20
[task 2019-05-09T11:38:19.435Z] 11:38:19 INFO - do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:849:5
[task 2019-05-09T11:38:19.436Z] 11:38:19 INFO - Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:57:5
[task 2019-05-09T11:38:19.436Z] 11:38:19 INFO - proto.report@resource://testing-common/Assert.jsm:213:10
[task 2019-05-09T11:38:19.436Z] 11:38:19 INFO - equal@resource://testing-common/Assert.jsm:249:8
[task 2019-05-09T11:38:19.437Z] 11:38:19 INFO - test_sendCheckOverride@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:552:10
[task 2019-05-09T11:38:19.437Z] 11:38:19 INFO - async*run_next_test/_run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1437:22
[task 2019-05-09T11:38:19.437Z] 11:38:19 INFO - _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1437:38
[task 2019-05-09T11:38:19.438Z] 11:38:19 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:688:9
[task 2019-05-09T11:38:19.438Z] 11:38:19 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:227:6
[task 2019-05-09T11:38:19.438Z] 11:38:19 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:529:5
[task 2019-05-09T11:38:19.439Z] 11:38:19 INFO - @-e:1:1
[task 2019-05-09T11:38:19.439Z] 11:38:19 INFO - exiting test

Flags: needinfo?(bvandyk)
Whiteboard: [stockwell needswork:owner]

I suppose it could be given the timing. Bug 1548959 also landed in that range.

I'm not particularly familiar with this test, but we'd previously had the media recorder probes in place seemingly without issue. As bug 1532391 restored them after they lapsed, I'd be surprised if it introduced new bustages, but I could use some help from those more familiar with telem and this test. I'm going to hold the NI to remind me to come back to this and try and reach out for aid in understanding what this failure means.

Keywords: regression

(In reply to Cristina Coroiu [:ccoroiu] from comment #43)

Mark, can you please take a look at this?

All bug 1548639/bug 1541416 did was change some unrelated test code and add some new tests. So directly they wouldn't have caused this.

I've just scanned the logs and it looks like test_TelemetrySend.js is now being run around the same time as the tests in bug 1548639 affected. Those tests are very processor intensive at the moment (I'm working on making them a bit better).

It looks like test_TelemetrySend.js is now failing/timing out when run in parallel, and then gets re-run sequentially as a result which is then failing.

I just ran it locally on my Mac (opt, artifact) as a single test, and out of four times it failed twice.

My suspicion is that there's something timing related here. Generally it gets away with it if run in parallel alongside tests that aren't very processor intensive, but run it on its own, or under heavy load, and there's something triggering the failure.

It is probably better for this to be looked at by the Telemetry team as they will know more about this test and the possible timing issues.

Flags: needinfo?(standard8)
Flags: needinfo?(gfritzsche)
Flags: needinfo?(bvandyk)
Priority: P5 → --
Priority: -- → P2

There have been 66 failures within the last 7 days as it follows:

  • 2 failures on linux x64 opt
  • 1 failure on linux x64 quantumrender opt
  • 17 failures on linux x64 shippable opt
  • 28 failures on linux x64 quantumrender shippable opt
  • 2 failures on os x 10.14 shippable opt
  • 1 failure on windows 7 opt
  • 15 failures on windows 7 shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=260966673&repo=autoland&lineNumber=6272

[task 2019-08-10T20:22:30.924Z] 20:22:30 INFO - TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js
[task 2019-08-10T20:22:55.642Z] 20:22:55 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | xpcshell return code: 0
[task 2019-08-10T20:22:55.642Z] 20:22:55 INFO - TEST-INFO took 24719ms
[task 2019-08-10T20:22:55.642Z] 20:22:55 INFO - >>>>>>>

Whiteboard: [retriggered][stockwell unknown] → [retriggered][stockwell needswork]
Pushed by csabou@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/91afb0796137 Disable test_TelemetrySend.js on !debug for frequent failures. r=chutten
Keywords: leave-open
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]

Since the patch the only oranges are from beta, esr, inbound, and try. Looks like disabling on !debug did the trick.

I looked into a quick fix for this, but simply disabling the "health" ping for the test didn't help. I think maybe there's carry-over from an earlier test that's causing the problem and a proper level of clean-up would take care of things, but I haven't looked too deeply.

Flags: needinfo?(gfritzsche)
Pushed by chutten@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/42807ce93df8 Fix intermittent test_TelemetrySend and re-enable on debug r=TravisLong
Regressions: 1701874
Has Regression Range: --- → yes
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Assignee: nobody → chutten
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: