Closed Bug 1457984 Opened 6 years ago Closed 2 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: 2 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: