1746324 - Intermittent netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_NUM_OF_HINTS_PER_PAGE at index 0 - 1 == 0 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 302

Reporter

Description

•

3 years ago

treeherder

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

[task 2021-12-15T23:20:44.813Z] 23:20:44     INFO - TEST-START | netwerk/test/browser/browser_103_telemetry.js
[task 2021-12-15T23:20:45.152Z] 23:20:45     INFO - TEST-INFO | started process screentopng
[task 2021-12-15T23:20:45.691Z] 23:20:45     INFO - TEST-INFO | screentopng: exit 0
[task 2021-12-15T23:20:45.692Z] 23:20:45     INFO - Buffered messages logged at 23:20:44
[task 2021-12-15T23:20:45.693Z] 23:20:45     INFO - Entering test bound 
[task 2021-12-15T23:20:45.694Z] 23:20:45     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.com/browser/netwerk/test/browser/103_preload.html" line: 0}]
[task 2021-12-15T23:20:45.695Z] 23:20:45     INFO - Buffered messages finished
[task 2021-12-15T23:20:45.698Z] 23:20:45     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_NUM_OF_HINTS_PER_PAGE at index 0 - 1 == 0 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 302
[task 2021-12-15T23:20:45.699Z] 23:20:45     INFO - Stack trace:
[task 2021-12-15T23:20:45.700Z] 23:20:45     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertHistogram:302
[task 2021-12-15T23:20:45.700Z] 23:20:45     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:33
[task 2021-12-15T23:20:45.701Z] 23:20:45     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-15T23:20:45.702Z] 23:20:45     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | expected counts should match for EH_NUM_OF_HINTS_PER_PAGE at index 1 - 0 == 1 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 296
[task 2021-12-15T23:20:45.703Z] 23:20:45     INFO - Stack trace:
[task 2021-12-15T23:20:45.703Z] 23:20:45     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertHistogram:296
[task 2021-12-15T23:20:45.704Z] 23:20:45     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:33
[task 2021-12-15T23:20:45.704Z] 23:20:45     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | Should have found an entry for EH_NUM_OF_HINTS_PER_PAGE at index 1 - true == true - 
[task 2021-12-15T23:20:45.704Z] 23:20:45     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-15T23:20:45.705Z] 23:20:45     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | Should have found an entry for EH_FINAL_RESPONSE at index 0 - false == true - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 309
[task 2021-12-15T23:20:45.706Z] 23:20:45     INFO - Stack trace:
[task 2021-12-15T23:20:45.706Z] 23:20:45     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertHistogram:309
[task 2021-12-15T23:20:45.707Z] 23:20:45     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:34
[task 2021-12-15T23:20:45.707Z] 23:20:45     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-15T23:20:45.708Z] 23:20:45     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | false == true - JS frame :: chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js :: <TOP_LEVEL> :: line 42
[task 2021-12-15T23:20:45.708Z] 23:20:45     INFO - Stack trace:
[task 2021-12-15T23:20:45.709Z] 23:20:45     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:42
[task 2021-12-15T23:20:45.710Z] 23:20:45     INFO - Leaving test bound 
[task 2021-12-15T23:20:45.710Z] 23:20:45     INFO - Entering test bound 
[task 2021-12-15T23:20:45.711Z] 23:20:45     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.com/browser/netwerk/test/browser/no_103_preload.html" line: 0}]
[task 2021-12-15T23:20:45.711Z] 23:20:45     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | expected counts should match for EH_NUM_OF_HINTS_PER_PAGE at index 0 - 1 == 1 - 
[task 2021-12-15T23:20:45.712Z] 23:20:45     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_NUM_OF_HINTS_PER_PAGE at index 1 - 0 == 0 - 
[task 2021-12-15T23:20:45.713Z] 23:20:45     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | Should have found an entry for EH_NUM_OF_HINTS_PER_PAGE at index 0 - true == true - 
[task 2021-12-15T23:20:45.714Z] 23:20:45     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | 0 == 0 - 
[task 2021-12-15T23:20:45.715Z] 23:20:45     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | true == true - 
[task 2021-12-15T23:20:45.715Z] 23:20:45     INFO - Leaving test bound 
[task 2021-12-15T23:20:45.716Z] 23:20:45     INFO - Entering test bound 
[task 2021-12-15T23:20:45.870Z] 23:20:45     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.com/browser/netwerk/test/browser/103_preload_and_404.html" line: 0}]
[task 2021-12-15T23:20:46.019Z] 23:20:46     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | 0 == 0 - 
[task 2021-12-15T23:20:46.021Z] 23:20:46     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-15T23:20:46.022Z] 23:20:46     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | Should have found an entry for EH_FINAL_RESPONSE at index 2 - false == true - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 309
[task 2021-12-15T23:20:46.022Z] 23:20:46     INFO - Stack trace:
[task 2021-12-15T23:20:46.023Z] 23:20:46     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertHistogram:309
[task 2021-12-15T23:20:46.024Z] 23:20:46     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:92

Atila Butkovits

Updated

•

3 years ago

Summary: Intermittent [TV] netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_NUM_OF_HINTS_PER_PAGE at index 0 - 1 == 0 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 302 → Intermittent netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_NUM_OF_HINTS_PER_PAGE at index 0 - 1 == 0 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 302

Sandor Molnar

Updated

•

3 years ago

Regressed by: 1743630

See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1744028

BMO Automation

Updated

•

3 years ago

Has Regression Range: --- → yes

Comment hidden (Intermittent Failures Robot)

BugBot [:suhaib / :marco/ :calixte]

Comment 3

•

3 years ago

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

status-firefox95: --- → unaffected

status-firefox96: --- → unaffected

status-firefox97: --- → affected

status-firefox-esr91: --- → unaffected

Andreea Pavel [:apavel]

Updated

•

3 years ago

Whiteboard: [stockwell needswork:owner] → [retriggered][stockwell needswork:owner]

BugBot [:suhaib / :marco/ :calixte]

Updated

•

3 years ago

Keywords: regression

Andreea Pavel [:apavel]

Comment 4

•

3 years ago

There are 36 total failures in the last 7 days on

linux1804-64-qr opt
linux1804-64-shippable-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=361607427&repo=autoland&lineNumber=6170

[task 2021-12-17T07:02:08.049Z] 07:02:08     INFO - TEST-START | netwerk/test/browser/browser_103_telemetry.js
[task 2021-12-17T07:02:08.370Z] 07:02:08     INFO - TEST-INFO | started process screentopng
[task 2021-12-17T07:02:08.752Z] 07:02:08     INFO - TEST-INFO | screentopng: exit 0
[task 2021-12-17T07:02:08.753Z] 07:02:08     INFO - Buffered messages logged at 07:02:08
[task 2021-12-17T07:02:08.754Z] 07:02:08     INFO - Entering test bound 
[task 2021-12-17T07:02:08.755Z] 07:02:08     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.com/browser/netwerk/test/browser/103_preload.html" line: 0}]
[task 2021-12-17T07:02:08.756Z] 07:02:08     INFO - Console message: [JavaScript Error: "Unknown Collection "main/partitioning-exempt-urls"" {file: "resource://services-settings/RemoteSettingsClient.jsm" line: 158}]
[task 2021-12-17T07:02:08.756Z] 07:02:08     INFO - UnknownCollectionError@resource://services-settings/RemoteSettingsClient.jsm:158:5
[task 2021-12-17T07:02:08.757Z] 07:02:08     INFO - sync@resource://services-settings/RemoteSettingsClient.jsm:501:13
[task 2021-12-17T07:02:08.757Z] 07:02:08     INFO - 
[task 2021-12-17T07:02:08.758Z] 07:02:08     INFO - Buffered messages finished
[task 2021-12-17T07:02:08.759Z] 07:02:08     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_NUM_OF_HINTS_PER_PAGE at index 0 - 1 == 0 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 302
[task 2021-12-17T07:02:08.759Z] 07:02:08     INFO - Stack trace:
[task 2021-12-17T07:02:08.759Z] 07:02:08     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertHistogram:302
[task 2021-12-17T07:02:08.759Z] 07:02:08     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:33
[task 2021-12-17T07:02:08.765Z] 07:02:08     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-17T07:02:08.777Z] 07:02:08     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | expected counts should match for EH_NUM_OF_HINTS_PER_PAGE at index 1 - 0 == 1 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 296
[task 2021-12-17T07:02:08.779Z] 07:02:08     INFO - Stack trace:
[task 2021-12-17T07:02:08.779Z] 07:02:08     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertHistogram:296
[task 2021-12-17T07:02:08.779Z] 07:02:08     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:33
[task 2021-12-17T07:02:08.779Z] 07:02:08     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | Should have found an entry for EH_NUM_OF_HINTS_PER_PAGE at index 1 - true == true - 
[task 2021-12-17T07:02:08.780Z] 07:02:08     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-17T07:02:08.780Z] 07:02:08     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | Should have found an entry for EH_FINAL_RESPONSE at index 0 - false == true - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertHistogram :: line 309
[task 2021-12-17T07:02:08.780Z] 07:02:08     INFO - Stack trace:
[task 2021-12-17T07:02:08.780Z] 07:02:08     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertHistogram:309
[task 2021-12-17T07:02:08.780Z] 07:02:08     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:34
[task 2021-12-17T07:02:08.780Z] 07:02:08     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-17T07:02:08.785Z] 07:02:08     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_telemetry.js | false == true - JS frame :: chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js :: <TOP_LEVEL> :: line 42
[task 2021-12-17T07:02:08.785Z] 07:02:08     INFO - Stack trace:
[task 2021-12-17T07:02:08.786Z] 07:02:08     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_telemetry.js:null:42
[task 2021-12-17T07:02:08.786Z] 07:02:08     INFO - Leaving test bound 
[task 2021-12-17T07:02:08.786Z] 07:02:08     INFO - Entering test bound 
[task 2021-12-17T07:02:08.787Z] 07:02:08     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.com/browser/netwerk/test/browser/no_103_preload.html" line: 0}]
[task 2021-12-17T07:02:08.788Z] 07:02:08     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | expected counts should match for EH_NUM_OF_HINTS_PER_PAGE at index 0 - 1 == 1 - 
[task 2021-12-17T07:02:08.789Z] 07:02:08     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_NUM_OF_HINTS_PER_PAGE at index 1 - 0 == 0 - 
[task 2021-12-17T07:02:08.789Z] 07:02:08     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | Should have found an entry for EH_NUM_OF_HINTS_PER_PAGE at index 0 - true == true - 
[task 2021-12-17T07:02:08.789Z] 07:02:08     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | 0 == 0 - 
[task 2021-12-17T07:02:08.791Z] 07:02:08     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | true == true - 
[task 2021-12-17T07:02:08.792Z] 07:02:08     INFO - Leaving test bound 
[task 2021-12-17T07:02:08.792Z] 07:02:08     INFO - Entering test bound 
[task 2021-12-17T07:02:08.845Z] 07:02:08     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.com/browser/netwerk/test/browser/103_preload_and_404.html" line: 0}]
[task 2021-12-17T07:02:09.107Z] 07:02:09     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | 0 == 0 - 
[task 2021-12-17T07:02:09.107Z] 07:02:09     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_FINAL_RESPONSE at index 1 - 0 == 0 - 
[task 2021-12-17T07:02:09.107Z] 07:02:09     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | expected counts should match for EH_FINAL_RESPONSE at index 2 - 1 == 1 - 
[task 2021-12-17T07:02:09.107Z] 07:02:09     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | unexpected counts should be zero for EH_FINAL_RESPONSE at index 3 - 0 == 0 - 
[task 2021-12-17T07:02:09.107Z] 07:02:09     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | Should have found an entry for EH_FINAL_RESPONSE at index 2 - true == true - 
[task 2021-12-17T07:02:09.107Z] 07:02:09     INFO - TEST-PASS | netwerk/test/browser/browser_103_telemetry.js | true == true - 
[task 2021-12-17T07:02:09.112Z] 07:02:09     INFO - Leaving test bound 
[task 2021-12-17T07:02:09.126Z] 07:02:09     INFO - GECKO(9399) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2021-12-17T07:02:09.127Z] 07:02:09     INFO - GECKO(9399) | MEMORY STAT | vsize 11154MB | residentFast 319MB | heapAllocated 185MB
[task 2021-12-17T07:02:09.128Z] 07:02:09     INFO - TEST-OK | netwerk/test/browser/browser_103_telemetry.js | took 1079ms
[task 2021-12-17T07:02:09.152Z] 07:02:09     INFO - checking window state

Dragana, please take a look. Thank you.

Flags: needinfo?(dd.mozilla)

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Updated

•

3 years ago

Whiteboard: [retriggered][stockwell needswork:owner][stockwell needswork:owner] → [retriggered][stockwell needswork:owner]

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Updated

•

3 years ago

Whiteboard: [retriggered][stockwell needswork:owner][stockwell needswork:owner] → [retriggered][stockwell needswork:owner]

Dragana Damjanovic [:dragana]

Updated

•

3 years ago

Blocks: earlyhints

Flags: needinfo?(dd.mozilla)

Comment hidden (Intermittent Failures Robot)

Kershaw Chang [:kershaw]

Updated

•

2 years ago

Priority: -- → P5

Whiteboard: [retriggered][stockwell unknown] → [retriggered][stockwell unknown][necko-triaged]

Comment hidden (Intermittent Failures Robot)

Atila Butkovits

Comment 13

•

2 years ago

There have been 46 failures in the last 7 days.

Happens on: linux1804-64-qr debug.

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=378432001&repo=autoland&lineNumber=9669

Comment hidden (Intermittent Failures Robot)

Kershaw Chang [:kershaw]

Updated

•

2 years ago

Priority: -- → P2

Comment hidden (Intermittent Failures Robot)

Manuel Bucher [:manuel]

Comment 17

•

2 years ago

Diagnosis of what the error message means:

103 early hint with one image followed by 200 status code
- /netwerk/test/browser/browser_103_telemetry.js#33:
  - Expected one 200 response with one hint recorded there
  - found one response with zero hints recorded instead /netwerk/protocol/http/EarlyHintsService.cpp#82-85
- /netwerk/test/browser/browser_103_telemetry.js#34:
  - Because no early hint response was sent??/propagated to EarlyHintsServie, EH_NUM_OF_HINTS_PER_PAGE (/netwerk/protocol/http/EarlyHintsService.cpp#86-88) never gets increased
103 early hint with one image followed by 404 page, which doesn't include that image.
- /netwerk/test/browser/browser_103_telemetry.js#92
  - No early hints (with a follow up 200 status code) recorded as expected (one line earlier)
  - No early hint with final response of main page with status 4xx recorded, but also no early hint at all recorded

Manuel Bucher [:manuel]

Updated

•

2 years ago

Assignee: nobody → mbucher

Status: NEW → ASSIGNED

Manuel Bucher [:manuel]

Comment 18

•

2 years ago

Possible scenarios why it is happening:

/netwerk/ipc/DocumentLoadListener.cpp#2477: GetLoadingBrowsingContext() returns nullptr (and therefore . Is that the correct browsing context to use? It seems to be the parent one https://firefox-source-docs.mozilla.org/dom/navigation/BrowsingContext.html Do we need to use the TopBrowsingContext or rather just mBrowsingContext, because EarlyHints only happen in the TopBrowsing context?
EarlyHintsService::EarlyHint doesn't get called and therefore mEarlyHintsCount doesn't get incresed even though an early hint was sent by the server (for whatever reason)
The test server sometimes doesn't return an early hint (I find this one unlikely, but possible, if there is an internal error and only a 500 is returned)

As soon as I have a rr replay or a pernosco session, I can start to distiguish between these scenarios and check if one of those is correct or if it something completely different.

Andreea Pavel [:apavel]

Updated

•

2 years ago

Whiteboard: [retriggered][stockwell unknown][necko-triaged][stockwell needswork:owner] → [retriggered][necko-triaged][stockwell needswork:owner]

Comment hidden (Intermittent Failures Robot)

Joel Maher ( :jmaher ) (UTC -8)

Updated

•

2 years ago

Blocks: 1775763

Kershaw Chang [:kershaw]

Updated

•

2 years ago

Blocks: 1802501

Manuel Bucher [:manuel]

Updated

•

2 years ago

Assignee: manuel → nobody

No longer blocks: earlyhints

Status: ASSIGNED → NEW

Manuel Bucher [:manuel]

Updated

•

2 years ago

Status: NEW → RESOLVED

Closed: 2 years ago

Duplicate of bug: 1803884

Resolution: --- → DUPLICATE