Closed Bug 1797279 Opened 2 years ago Closed 1 year ago

Intermittent netwerk/test/unit/test_retry_0rtt.js | single tracking bug

Tracking

()

Status:

RESOLVED FIXED

Milestone:

109 Branch

Tracking Flags:

Tracking

Status

firefox-esr102

---

unaffected

firefox106

---

unaffected

firefox107

---

unaffected

firefox108

---

wontfix

firefox109

---

fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [necko-triaged])

Attachments

(2 files, 1 obsolete file)

Bug 1797279 - ClearSSLExternalAndInternalSessionCache should wait for socketprocess before continuing r=kershaw 2 years ago Valentin Gosu [:valentin] (he/him) 48 bytes, text/x-phabricator-request		Details \| Review
Bug 1797279 - Make PSocketProcess.ClearSessionCache return async when done r=kershaw 2 years ago Valentin Gosu [:valentin] (he/him) 48 bytes, text/x-phabricator-request		Details \| Review
Bug 1797279 - Add nsINSSComponent.asyncClearSSLExternalAndInternalSessionCache that waits for socket process to clear the cache r=keeler 2 years ago Valentin Gosu [:valentin] (he/him) 48 bytes, text/x-phabricator-request		Details \| Review

Treeherder Bug Filer

Reporter

Description

•

2 years ago

treeherder

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

[task 2022-10-25T10:06:02.728Z] 10:06:02     INFO -  TEST-START | netwerk/test/unit/test_retry_0rtt.js
[task 2022-10-25T10:06:06.455Z] 10:06:06  WARNING -  TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_retry_0rtt.js | xpcshell return code: 0
[task 2022-10-25T10:06:06.470Z] 10:06:06     INFO -  TEST-INFO took 3727ms
[task 2022-10-25T10:06:06.470Z] 10:06:06     INFO -  >>>>>>>
[task 2022-10-25T10:06:06.470Z] 10:06:06     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-10-25T10:06:06.470Z] 10:06:06     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-10-25T10:06:06.471Z] 10:06:06     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-10-25T10:06:06.471Z] 10:06:06     INFO -  running event loop
[task 2022-10-25T10:06:06.471Z] 10:06:06     INFO -  netwerk/test/unit/test_retry_0rtt.js | Starting
[task 2022-10-25T10:06:06.471Z] 10:06:06     INFO -  (xpcshell/head.js) | test pending (2)
[task 2022-10-25T10:06:06.471Z] 10:06:06     INFO -  TEST-PASS | netwerk/test/unit/test_retry_0rtt.js |  - Binary util FaultyServer should exist - true == true
[task 2022-10-25T10:06:06.472Z] 10:06:06     INFO -  TEST-PASS | netwerk/test/unit/test_retry_0rtt.js |  - certificate folder (../../../security/manager/ssl/tests/unit/test_faulty_server) should exist - true == true
[task 2022-10-25T10:06:06.472Z] 10:06:06     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2022-10-25T10:06:06.472Z] 10:06:06     INFO -  PID 3892 | sending 'GET / HTTP/1.0
[task 2022-10-25T10:06:06.472Z] 10:06:06     INFO -  PID 3892 | '
[task 2022-10-25T10:06:06.472Z] 10:06:06     INFO -  (xpcshell/head.js) | test pending (2)
[task 2022-10-25T10:06:06.473Z] 10:06:06     INFO -  (xpcshell/head.js) | test finished (2)
[task 2022-10-25T10:06:06.473Z] 10:06:06     INFO -  PID 3892 | HTTP/1.0 200 OK
[task 2022-10-25T10:06:06.473Z] 10:06:06     INFO -  PID 3892 | content-type: text/plain
[task 2022-10-25T10:06:06.473Z] 10:06:06     INFO -  PID 3892 | connection: close
[task 2022-10-25T10:06:06.473Z] 10:06:06     INFO -  PID 3892 | server: httpd.js
[task 2022-10-25T10:06:06.474Z] 10:06:06     INFO -  PID 3892 | date: Tue, 25 Oct 2022 10:06:04 GMT
[task 2022-10-25T10:06:06.474Z] 10:06:06     INFO -  PID 3892 | content-length: 3
[task 2022-10-25T10:06:06.474Z] 10:06:06     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2022-10-25T10:06:06.474Z] 10:06:06     INFO -  (xpcshell/head.js) | test finished (2)
[task 2022-10-25T10:06:06.474Z] 10:06:06     INFO -  netwerk/test/unit/test_retry_0rtt.js | Starting testRetry0Rtt
[task 2022-10-25T10:06:06.474Z] 10:06:06     INFO -  (xpcshell/head.js) | test testRetry0Rtt pending (2)
[task 2022-10-25T10:06:06.475Z] 10:06:06     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2022-10-25T10:06:06.475Z] 10:06:06     INFO -  PID 3892 | found pre-defined host '0rtt-alert-bad-mac.example.com'
[task 2022-10-25T10:06:06.475Z] 10:06:06     INFO -  PID 3892 | found pre-defined host '0rtt-alert-bad-mac.example.com'
[task 2022-10-25T10:06:06.475Z] 10:06:06     INFO -  PID 3892 | 0RTT handler epoch=2 dir=1
[task 2022-10-25T10:06:06.475Z] 10:06:06     INFO -  PID 3892 | 0RTT handler epoch=2 dir=2
[task 2022-10-25T10:06:06.476Z] 10:06:06     INFO -  PID 3892 | 0RTT handler epoch=3 dir=1
[task 2022-10-25T10:06:06.476Z] 10:06:06     INFO -  PID 3892 | 0RTT handler epoch=3 dir=2
[task 2022-10-25T10:06:06.476Z] 10:06:06     INFO -  PID 3892 | read '0x47'
[task 2022-10-25T10:06:06.477Z] 10:06:06     INFO -  PID 3892 | sending 'G'
[task 2022-10-25T10:06:06.477Z] 10:06:06     INFO -  TEST-PASS | netwerk/test/unit/test_retry_0rtt.js | testRetry0Rtt - [testRetry0Rtt : 86] "G" == true
[task 2022-10-25T10:06:06.477Z] 10:06:06     INFO -  TEST-PASS | netwerk/test/unit/test_retry_0rtt.js | testRetry0Rtt - [testRetry0Rtt : 87] no early data sent - 0 == 0
[task 2022-10-25T10:06:06.477Z] 10:06:06     INFO -  PID 3892 | found pre-defined host '0rtt-alert-bad-mac.example.com'
[task 2022-10-25T10:06:06.477Z] 10:06:06     INFO -  PID 3892 | found pre-defined host '0rtt-alert-bad-mac.example.com'
[task 2022-10-25T10:06:06.478Z] 10:06:06     INFO -  PID 3892 | 0RTT handler epoch=2 dir=1
[task 2022-10-25T10:06:06.478Z] 10:06:06     INFO -  PID 3892 | 0RTT handler epoch=2 dir=2
[task 2022-10-25T10:06:06.478Z] 10:06:06     INFO -  PID 3892 | 0RTT handler epoch=3 dir=1
[task 2022-10-25T10:06:06.478Z] 10:06:06     INFO -  PID 3892 | 0RTT handler epoch=3 dir=2
[task 2022-10-25T10:06:06.478Z] 10:06:06     INFO -  PID 3892 | read '0x47'
[task 2022-10-25T10:06:06.478Z] 10:06:06     INFO -  PID 3892 | sending 'G'
[task 2022-10-25T10:06:06.479Z] 10:06:06     INFO -  TEST-PASS | netwerk/test/unit/test_retry_0rtt.js | testRetry0Rtt - [testRetry0Rtt : 102] "G" == true
[task 2022-10-25T10:06:06.479Z] 10:06:06  WARNING -  TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_retry_0rtt.js | testRetry0Rtt - [testRetry0Rtt : 103] got early data - 0 == 1
[task 2022-10-25T10:06:06.479Z] 10:06:06     INFO -  Z:/task_166668261336352/build/tests/xpcshell/tests/netwerk/test/unit/test_retry_0rtt.js:testRetry0Rtt:103
[task 2022-10-25T10:06:06.479Z] 10:06:06     INFO -  Z:\task_166668261336352\build\tests\xpcshell\head.js:_do_main:240
[task 2022-10-25T10:06:06.480Z] 10:06:06     INFO -  Z:\task_166668261336352\build\tests\xpcshell\head.js:_execute_test:597
[task 2022-10-25T10:06:06.480Z] 10:06:06     INFO -  -e:null:1
[task 2022-10-25T10:06:06.480Z] 10:06:06     INFO -  exiting test
[task 2022-10-25T10:06:06.480Z] 10:06:06     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2022-10-25T10:06:06.480Z] 10:06:06     INFO -  _abort_failed_test@Z:\task_166668261336352\build\tests\xpcshell\head.js:875:20
[task 2022-10-25T10:06:06.480Z] 10:06:06     INFO -  do_report_result@Z:\task_166668261336352\build\tests\xpcshell\head.js:976:5
[task 2022-10-25T10:06:06.481Z] 10:06:06     INFO -  Assert<@Z:\task_166668261336352\build\tests\xpcshell\head.js:73:21
[task 2022-10-25T10:06:06.481Z] 10:06:06     INFO -  proto.report@resource://testing-common/Assert.jsm:228:10
[task 2022-10-25T10:06:06.481Z] 10:06:06     INFO -  equal@resource://testing-common/Assert.jsm:270:8
[task 2022-10-25T10:06:06.481Z] 10:06:06     INFO -  testRetry0Rtt@Z:/task_166668261336352/build/tests/xpcshell/tests/netwerk/test/unit/test_retry_0rtt.js:103:12
[task 2022-10-25T10:06:06.482Z] 10:06:06     INFO -  _do_main@Z:\task_166668261336352\build\tests\xpcshell\head.js:240:6
[task 2022-10-25T10:06:06.482Z] 10:06:06     INFO -  _execute_test@Z:\task_166668261336352\build\tests\xpcshell\head.js:597:5
[task 2022-10-25T10:06:06.482Z] 10:06:06     INFO -  @-e:1:1
[task 2022-10-25T10:06:06.483Z] 10:06:06     INFO -  exiting test
[task 2022-10-25T10:06:06.483Z] 10:06:06     INFO -  "Force a GC"
[task 2022-10-25T10:06:06.483Z] 10:06:06     INFO -  <<<<<<<
[task 2022-10-25T10:06:06.487Z] 10:06:06     INFO -  TEST-START | netwerk/test/unit/test_retry_0rtt.js

Cristian Tuns

Updated

•

2 years ago

Regressed by: 1754746

Summary: Intermittent TV netwerk/test/unit/test_retry_0rtt.js | single tracking bug → Intermittent netwerk/test/unit/test_retry_0rtt.js | single tracking bug

BugBot [:suhaib / :marco/ :calixte]

Comment 1

•

2 years ago

:valentin, since you are the author of the regressor, bug 1754746, could you take a look?

For more information, please visit auto_nag documentation.

Flags: needinfo?(valentin.gosu)

Keywords: regression

BugBot [:suhaib / :marco/ :calixte]

Comment 2

•

2 years ago

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

status-firefox106: --- → unaffected

status-firefox107: --- → unaffected

status-firefox108: --- → affected

status-firefox-esr102: --- → unaffected

Valentin Gosu [:valentin] (he/him)

Assignee

Updated

•

2 years ago

Assignee: nobody → valentin.gosu

Flags: needinfo?(valentin.gosu)

Whiteboard: [necko-triaged]

Comment hidden (Intermittent Failures Robot)

Valentin Gosu [:valentin] (he/him)

Assignee

Comment 6

•

2 years ago

All of the failures are spi (socket-process).
I think it's caused by the fact that we call clearSSLExternalAndInternalSessionCache in the setup, but with socket process that might be executed a bit later, messing with the timings of the test.
I'll post a patch that waits until the socketprocess callback is completed.

Valentin Gosu [:valentin] (he/him)

Assignee

Comment 7

•

2 years ago

Attached file Bug 1797279 - ClearSSLExternalAndInternalSessionCache should wait for socketprocess before continuing r=kershaw (obsolete) — Details

This is a test only method, and the fact that the operation is not sync
with socket process can possibly cause racy tests.
This patch spins the event loop until the callback is received.

BugBot [:suhaib / :marco/ :calixte]

Comment 8

•

2 years ago

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

status-firefox109: --- → affected

Valentin Gosu [:valentin] (he/him)

Assignee

Comment 9

•

2 years ago

Attached file Bug 1797279 - Make PSocketProcess.ClearSessionCache return async when done r=kershaw — Details

Originally these changes were part of D162103.

Valentin Gosu [:valentin] (he/him)

Assignee

Comment 10

•

2 years ago

Attached file Bug 1797279 - Add nsINSSComponent.asyncClearSSLExternalAndInternalSessionCache that waits for socket process to clear the cache r=keeler — Details

This is a test only method, and the fact that the operation is not sync
with socket process can possibly cause racy tests.
This patch adds an async version of clearSSLExternalAndInternalSessionCache
that returns a promise.

Depends on D162152

Phabricator Automation

Updated

•

2 years ago

Attachment #9303479 - Attachment is obsolete: true

Comment hidden (Intermittent Failures Robot)

Pulsebot

Comment 13

•

1 year ago

Pushed by valentin.gosu@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/daf5d55079db
Make PSocketProcess.ClearSessionCache return async when done r=kershaw,necko-reviewers
https://hg.mozilla.org/integration/autoland/rev/8de777d3d624
Add nsINSSComponent.asyncClearSSLExternalAndInternalSessionCache that waits for socket process to clear the cache r=keeler,necko-reviewers,kershaw

Marian-Vasile Laza

Comment 14

•

1 year ago

Backed out 3 changesets (Bug 1797279, Bug 1800758) for causing xpcshell failures on test_httpssvc_retry_with_ech.js.
Backout link
Push with failures <--> X1
Failure Log

Flags: needinfo?(valentin.gosu)

Valentin Gosu [:valentin] (he/him)

Assignee

Updated

•

1 year ago

Flags: needinfo?(valentin.gosu)

Pulsebot

Comment 15

•

1 year ago

Pushed by valentin.gosu@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/85adb1c429e9
Make PSocketProcess.ClearSessionCache return async when done r=kershaw,necko-reviewers
https://hg.mozilla.org/integration/autoland/rev/2b9756d00604
Add nsINSSComponent.asyncClearSSLExternalAndInternalSessionCache that waits for socket process to clear the cache r=keeler,necko-reviewers,kershaw

Cristian Tuns

Comment 16

•

1 year ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/85adb1c429e9
https://hg.mozilla.org/mozilla-central/rev/2b9756d00604

Status: NEW → RESOLVED

Closed: 1 year ago

status-firefox109: affected → fixed

Resolution: --- → FIXED

Target Milestone: --- → 109 Branch

BugBot [:suhaib / :marco/ :calixte]

Comment 17

•

1 year ago

The patch landed in nightly and beta is affected.
:valentin, is this bug important enough to require an uplift?

If yes, please nominate the patch for beta approval.
If no, please set status-firefox108 to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(valentin.gosu)

Valentin Gosu [:valentin] (he/him)

Assignee

Comment 18

•

1 year ago

The socket process is disabled by default. This fix mostly affects automated testing. It is safe to ride the trains.

status-firefox108: affected → wontfix

Flags: needinfo?(valentin.gosu)

Treeherder Bug Filer

Reporter

Updated

•

1 year ago