Closed Bug 1736179 Opened 2 months ago Closed 2 months ago

Intermittent toolkit/components/telemetry/tests/unit/test_PingSender.js | test_pingSender_multiple_pings - [test_pingSender_multiple_pings : 229] Should have received the correct ping id. - "083bc7d1-ab39-4fd2-8562-fc11626683df" == "093ac192-f

Categories

(Toolkit :: Telemetry, defect, P5)

defect

Tracking

()

RESOLVED FIXED
95 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox-esr91 --- unaffected
firefox93 --- unaffected
firefox94 --- unaffected
firefox95 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=355025097&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/IYfzfc08R9aKF62skcUPsA/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/IYfzfc08R9aKF62skcUPsA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2021-10-16T17:06:03.450Z] 17:06:03  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_PingSender.js | test_pingSender_multiple_pings - [test_pingSender_multiple_pings : 229] Should have received the correct ping id. - "083bc7d1-ab39-4fd2-8562-fc11626683df" == "093ac192-f572-4c4e-ae6d-e5ca6808328a"
[task 2021-10-16T17:06:03.451Z] 17:06:03     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_PingSender.js:test_pingSender_multiple_pings:229
[task 2021-10-16T17:06:03.452Z] 17:06:03     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:240
[task 2021-10-16T17:06:03.454Z] 17:06:03     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:597
[task 2021-10-16T17:06:03.455Z] 17:06:03     INFO -  -e:null:1
[task 2021-10-16T17:06:03.456Z] 17:06:03     INFO -  exiting test
[task 2021-10-16T17:06:03.457Z] 17:06:03     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2021-10-16T17:06:03.458Z] 17:06:03     INFO -  _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:868:20
[task 2021-10-16T17:06:03.459Z] 17:06:03     INFO -  do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:969:5
[task 2021-10-16T17:06:03.460Z] 17:06:03     INFO -  Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:75:21
[task 2021-10-16T17:06:03.461Z] 17:06:03     INFO -  proto.report@resource://testing-common/Assert.jsm:228:10
[task 2021-10-16T17:06:03.463Z] 17:06:03     INFO -  equal@resource://testing-common/Assert.jsm:270:8
[task 2021-10-16T17:06:03.464Z] 17:06:03     INFO -  test_pingSender_multiple_pings@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_PingSender.js:229:12
[task 2021-10-16T17:06:03.465Z] 17:06:03     INFO -  _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:240:6
[task 2021-10-16T17:06:03.466Z] 17:06:03     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:597:5
[task 2021-10-16T17:06:03.467Z] 17:06:03     INFO -  @-e:1:1
[task 2021-10-16T17:06:03.468Z] 17:06:03     INFO -  exiting test
[task 2021-10-16T17:06:03.469Z] 17:06:03     INFO -  "CONSOLE_MESSAGE: (info) 1634403963105	Toolkit.Telemetry	TRACE	PingServer::defaultPingHandler() - POST http://localhost:34523/submit/telemetry/"
[task 2021-10-16T17:06:03.475Z] 17:06:03     INFO -  "CONSOLE_MESSAGE: (info) 1634403963115	Toolkit.Telemetry	TRACE	PingServer::defaultPingHandler() - POST http://localhost:34523/submit/telemetry/"
[task 2021-10-16T17:06:03.478Z] 17:06:03     INFO -  PID 6553 | [Parent 6841, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:197
[task 2021-10-16T17:06:03.479Z] 17:06:03     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1634403963137	Toolkit.Telemetry	ERROR	TelemetrySend::shutdown - failed to remove observer for idle-daily: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: shutdown :: line 902"  data: no] Stack trace: shutdown()@resource://gre/modules/TelemetrySend.jsm:902
[task 2021-10-16T17:06:03.480Z] 17:06:03     INFO -  shutdown()@resource://gre/modules/TelemetrySend.jsm:266
[task 2021-10-16T17:06:03.481Z] 17:06:03     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:541
[task 2021-10-16T17:06:03.482Z] 17:06:03     INFO -  _execute_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:661
[task 2021-10-16T17:06:03.482Z] 17:06:03     INFO -  _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:670
[task 2021-10-16T17:06:03.483Z] 17:06:03     INFO -  -e:1" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2021-10-16T17:06:03.483Z] 17:06:03     INFO -  append@resource://gre/modules/Log.jsm:723:12
[task 2021-10-16T17:06:03.484Z] 17:06:03     INFO -  log@resource://gre/modules/Log.jsm:379:16
[task 2021-10-16T17:06:03.484Z] 17:06:03     INFO -  getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:508:18
[task 2021-10-16T17:06:03.485Z] 17:06:03     INFO -  error@resource://gre/modules/Log.jsm:387:10
[task 2021-10-16T17:06:03.486Z] 17:06:03     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:904:19
[task 2021-10-16T17:06:03.486Z] 17:06:03     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:266:30
[task 2021-10-16T17:06:03.487Z] 17:06:03     INFO -  @/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:541:47
[task 2021-10-16T17:06:03.488Z] 17:06:03     INFO -  _execute_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:661:28
[task 2021-10-16T17:06:03.488Z] 17:06:03     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:670:5
[task 2021-10-16T17:06:03.489Z] 17:06:03     INFO -  @-e:1:1
[task 2021-10-16T17:06:03.490Z] 17:06:03     INFO -  "
[task 2021-10-16T17:06:03.491Z] 17:06:03     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1634403963139	Toolkit.Telemetry	ERROR	TelemetrySend::shutdown - failed to remove observer for quit-application-granted: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: shutdown :: line 902"  data: no] Stack trace: shutdown()@resource://gre/modules/TelemetrySend.jsm:902
[task 2021-10-16T17:06:03.491Z] 17:06:03     INFO -  shutdown()@resource://gre/modules/TelemetrySend.jsm:266
[task 2021-10-16T17:06:03.492Z] 17:06:03     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:541
[task 2021-10-16T17:06:03.492Z] 17:06:03     INFO -  _execute_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:661
[task 2021-10-16T17:06:03.493Z] 17:06:03     INFO -  _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:670
[task 2021-10-16T17:06:03.493Z] 17:06:03     INFO -  -e:1" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2021-10-16T17:06:03.494Z] 17:06:03     INFO -  append@resource://gre/modules/Log.jsm:723:12
[task 2021-10-16T17:06:03.495Z] 17:06:03     INFO -  log@resource://gre/modules/Log.jsm:379:16
[task 2021-10-16T17:06:03.495Z] 17:06:03     INFO -  getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:508:18
[task 2021-10-16T17:06:03.495Z] 17:06:03     INFO -  error@resource://gre/modules/Log.jsm:387:10
[task 2021-10-16T17:06:03.496Z] 17:06:03     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:904:19
[task 2021-10-16T17:06:03.496Z] 17:06:03     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:266:30
[task 2021-10-16T17:06:03.496Z] 17:06:03     INFO -  @/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:541:47
[task 2021-10-16T17:06:03.497Z] 17:06:03     INFO -  _execute_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:661:28
[task 2021-10-16T17:06:03.498Z] 17:06:03     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:670:5
[task 2021-10-16T17:06:03.498Z] 17:06:03     INFO -  @-e:1:1
[task 2021-10-16T17:06:03.499Z] 17:06:03     INFO -  "
[task 2021-10-16T17:06:03.499Z] 17:06:03     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1634403963141	Toolkit.Telemetry	ERROR	TelemetrySend::shutdown - failed to remove observer for quit-application-forced: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: shutdown :: line 902"  data: no] Stack trace: shutdown()@resource://gre/modules/TelemetrySend.jsm:902
[task 2021-10-16T17:06:03.500Z] 17:06:03     INFO -  shutdown()@resource://gre/modules/TelemetrySend.jsm:266
[task 2021-10-16T17:06:03.501Z] 17:06:03     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:541
[task 2021-10-16T17:06:03.501Z] 17:06:03     INFO -  _execute_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:661
[task 2021-10-16T17:06:03.503Z] 17:06:03     INFO -  _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:670
[task 2021-10-16T17:06:03.503Z] 17:06:03     INFO -  -e:1" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2021-10-16T17:06:03.504Z] 17:06:03     INFO -  append@resource://gre/modules/Log.jsm:723:12
[task 2021-10-16T17:06:03.504Z] 17:06:03     INFO -  log@resource://gre/modules/Log.jsm:379:16
[task 2021-10-16T17:06:03.504Z] 17:06:03     INFO -  getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:508:18
[task 2021-10-16T17:06:03.505Z] 17:06:03     INFO -  error@resource://gre/modules/Log.jsm:387:10
[task 2021-10-16T17:06:03.505Z] 17:06:03     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:904:19
[task 2021-10-16T17:06:03.505Z] 17:06:03     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:266:30
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  @/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:541:47
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  _execute_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:661:28
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:670:5
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  @-e:1:1
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  "
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1634403963143	Toolkit.Telemetry	ERROR	TelemetrySend::shutdown - failed to remove observer for profile-change-net-teardown: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: shutdown :: line 902"  data: no] Stack trace: shutdown()@resource://gre/modules/TelemetrySend.jsm:902
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  shutdown()@resource://gre/modules/TelemetrySend.jsm:266
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:541
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  _execute_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:661
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:670
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  -e:1" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  append@resource://gre/modules/Log.jsm:723:12
[task 2021-10-16T17:06:03.506Z] 17:06:03     INFO -  log@resource://gre/modules/Log.jsm:379:16
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:508:18
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  error@resource://gre/modules/Log.jsm:387:10
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:904:19
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:266:30
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  @/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:541:47
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  _execute_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:661:28
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:670:5
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  @-e:1:1
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  "
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  "CONSOLE_MESSAGE: (info) 1634403963145	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::shutdown"
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  "CONSOLE_MESSAGE: (info) 1634403963146	Toolkit.Telemetry	TRACE	TelemetrySend::promisePendingPingActivity - Waiting for ping task"
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  PID 6553 | !!! error running onStopped callback: TypeError: callback is not a function
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  PID 6553 | [Parent 6841, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3353
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  PID 6553 | [Parent 6841, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3420
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  PID 6553 | [Parent 6841, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4439
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  PID 6553 | [Parent 6553, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3353
[task 2021-10-16T17:06:03.507Z] 17:06:03     INFO -  PID 6553 | [Parent 6553, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3420
[task 2021-10-16T17:06:03.508Z] 17:06:03     INFO -  PID 6553 | [Parent 6553, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4439
[task 2021-10-16T17:06:03.508Z] 17:06:03     INFO -  PID 6553 | [Parent 6553, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:204
[task 2021-10-16T17:06:03.508Z] 17:06:03     INFO -  PID 6553 | [Parent 6553, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:204
[task 2021-10-16T17:06:03.508Z] 17:06:03     INFO -  <<<<<<<
[task 2021-10-16T17:06:03.508Z] 17:06:03     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_PingSender.js
Regressed by: 1734262
Summary: Intermittent TV toolkit/components/telemetry/tests/unit/test_PingSender.js | test_pingSender_multiple_pings - [test_pingSender_multiple_pings : 229] Should have received the correct ping id. - "083bc7d1-ab39-4fd2-8562-fc11626683df" == "093ac192-f → Intermittent toolkit/components/telemetry/tests/unit/test_PingSender.js | test_pingSender_multiple_pings - [test_pingSender_multiple_pings : 229] Should have received the correct ping id. - "083bc7d1-ab39-4fd2-8562-fc11626683df" == "093ac192-f
Flags: needinfo?(bholley)

I'm working on getting a pernosco trace.

(In reply to Bobby Holley (:bholley) from comment #4)

I'm working on getting a pernosco trace.

Oh I see, it's actually straightforward to see the issue by inspection. The test assumes that queued background pings are received by the server in the order they're passed to pingsender. This occurred reliably with pingsender 1.0, because it fully processed each request in sequence (because it would be hard to do anything else in manual C++). But pingsender 2.0 executes the request in parallel (because it's easy to do that with promises), and so sometimes the test server receives the second ping before the first one.

I'll relax the test.

Assignee: nobody → bholley
Flags: needinfo?(bholley)
Pushed by bholley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/0cdac6554c4b
Allow test pings to arrive in any order. r=chutten
Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch
You need to log in before you can comment on or make changes to this bug.