1697823 - Intermittent random test failure because of Toolkit.Telemetry ERROR ClientID::updateClientID - invalid client ID: null" {file: "resource://gre/modules/Log.jsm" line: 723}]

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=332861567&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FYGr7D-QT3GuDsIfbDAZgw/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/FYGr7D-QT3GuDsIfbDAZgw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2021-03-11T15:16:20.356Z] 15:16:20     INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_autocomplete_enter_race.js | Search provider extension should be running - "running" == "running" - 
[task 2021-03-11T15:16:20.356Z] 15:16:20     INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_autocomplete_enter_race.js | Extension ID of search provider should be set - "[e-mail]" == true - 
[task 2021-03-11T15:16:20.356Z] 15:16:20     INFO - wait for the page to load
[task 2021-03-11T15:16:20.356Z] 15:16:20     INFO - Buffered messages logged at 15:16:15
[task 2021-03-11T15:16:20.357Z] 15:16:20     INFO - Leaving test bound 
[task 2021-03-11T15:16:20.357Z] 15:16:20     INFO - Entering test bound 
[task 2021-03-11T15:16:20.357Z] 15:16:20     INFO - Buffered messages logged at 15:16:16
[task 2021-03-11T15:16:20.357Z] 15:16:20     INFO - Awaiting for the urlbar panel to open
[task 2021-03-11T15:16:20.358Z] 15:16:20     INFO - wait for the page to load
[task 2021-03-11T15:16:20.358Z] 15:16:20     INFO - Buffered messages logged at 15:16:17
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - Console message: [JavaScript Error: "1615475777405	Toolkit.Telemetry	ERROR	ClientID::updateClientID - invalid client ID: null" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - append@resource://gre/modules/Log.jsm:723:12
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - log@resource://gre/modules/Log.jsm:379:16
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:508:18
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - error@resource://gre/modules/Log.jsm:387:10
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - updateClientID@resource://gre/modules/ClientID.jsm:479:17
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - _doLoadClientIDs@resource://gre/modules/ClientID.jsm:250:33
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - 
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - Buffered messages finished
[task 2021-03-11T15:16:20.360Z] 15:16:20     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_autocomplete_enter_race.js | false == true - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_autocomplete_enter_race.js :: test_delay :: line 164```

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

This affects random tests which check if any error messages have been logged during their execution. Please prioritize fixing it (sheriffs have to manually check logs to identify the issue).

Comment 5

[Chris H-C :chutten]

Okay, so the culprit is _doLoadClientId setting the client id whether or not there's one present, not realizing that updateClientId prints an error about it and me not realizing that error prints cause other tests to fail.

Fix should be straightforward, I'll work on this now.

Comment 6

[Chris H-C :chutten]

Attachment: Bug 1697823 - Don't try to update the client_id to null r?janerik!

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e0b1b0b70a9e
Don't try to update the client_id to null r=janerik

Comment 8

[Sandor Molnar[:smolnar]]

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

Comment 9

[Intermittent Failures Robot]

5 failures in 4622 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5

Platform and build breakdown:

• macosx1014-64-qr: 4
  • debug: 2
  • opt: 2
• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1697823&startday=2021-03-08&endday=2021-03-14&tree=all