Closed Bug 1736179 Opened 3 years ago Closed 3 years 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)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
95 Branch
Tracking Flags:
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)

Bug 1736179 - Allow test pings to arrive in any order.
48 bytes, text/x-phabricator-request
Details | Review

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
Has Regression Range: --- → yes

Fails on tier 1 jobs now: https://treeherder.mozilla.org/logviewer?job_id=355034757&repo=autoland

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

Set release status flags based on info from the regressing bug 1734262

status-firefox93: --- → unaffected
status-firefox94: --- → unaffected
status-firefox95: --- → affected
status-firefox-esr78: --- → unaffected
status-firefox-esr91: --- → unaffected
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

https://hg.mozilla.org/mozilla-central/rev/0cdac6554c4b

Status: NEW → RESOLVED
Closed: 3 years ago
status-firefox95: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: