1920941 - Missing TLS Handshake Timing for Speculative Connections

Assignee

Description

•

10 months ago

•

Found a bug when investigating the test failure in bug 1898247 #comment 4.
When a speculative connection is created and a NullTransaction is used to drive TLS handshake, we didn't set secureConnectionStart correctly.

Kershaw Chang [:kershaw]

Assignee

Comment 1

•

10 months ago

Attached file Bug 1920941 - Store secureConnectionStart in mBootstrappedTimings for NullTransaction, r=#necko — Details

Phabricator Automation

Updated

•

10 months ago

Assignee: nobody → kershaw

Status: NEW → ASSIGNED

Pulsebot

Comment 2

•

10 months ago

Pushed by kjang@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/3b9114742881 Store secureConnectionStartin mBootstrappedTimings for NullTransaction, r=necko-reviewers,valentin

Iulian Moraru

Comment 3

•

10 months ago

Backed out for causing xpcshell failures on test_tls_handshake_timing.js.

[task 2024-09-26T15:56:38.257Z] 15:56:38     INFO -  TEST-START | netwerk/test/unit/test_tls_handshake_timing.js
[task 2024-09-26T16:01:38.263Z] 16:01:38  WARNING -  TEST-UNEXPECTED-TIMEOUT | netwerk/test/unit/test_tls_handshake_timing.js | Test timed out
[task 2024-09-26T16:01:38.263Z] 16:01:38     INFO -  TEST-INFO took 300006ms
[task 2024-09-26T16:01:38.264Z] 16:01:38     INFO -  >>>>>>>
[task 2024-09-26T16:01:38.264Z] 16:01:38     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2024-09-26T16:01:38.265Z] 16:01:38     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2024-09-26T16:01:38.265Z] 16:01:38     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2024-09-26T16:01:38.265Z] 16:01:38     INFO -  running event loop
[task 2024-09-26T16:01:38.265Z] 16:01:38     INFO -  netwerk/test/unit/test_tls_handshake_timing.js | Starting setup test_setup
[task 2024-09-26T16:01:38.266Z] 16:01:38     INFO -  (xpcshell/head.js) | test test_setup pending (2)
[task 2024-09-26T16:01:38.266Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_setup - [test_setup : 21] "50282" != null
[task 2024-09-26T16:01:38.266Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_setup - [test_setup : 22] "50282" != ""
[task 2024-09-26T16:01:38.266Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_setup - [test_setup : 24] "60675" != null
[task 2024-09-26T16:01:38.267Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_setup - [test_setup : 25] "60675" != ""
[task 2024-09-26T16:01:38.267Z] 16:01:38     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2024-09-26T16:01:38.267Z] 16:01:38     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2024-09-26T16:01:38.267Z] 16:01:38     INFO -  (xpcshell/head.js) | test test_setup finished (2)
[task 2024-09-26T16:01:38.268Z] 16:01:38     INFO -  netwerk/test/unit/test_tls_handshake_timing.js | Starting test_http2
[task 2024-09-26T16:01:38.268Z] 16:01:38     INFO -  (xpcshell/head.js) | test test_http2 pending (2)
[task 2024-09-26T16:01:38.269Z] 16:01:38     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2024-09-26T16:01:38.269Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http2 - [test_http2 : 1] 12 == 12
[task 2024-09-26T16:01:38.269Z] 16:01:38     INFO -  "secureConnectionStartTime=1727366199632178"
[task 2024-09-26T16:01:38.269Z] 16:01:38     INFO -  "connectEndTime=1727366199645935"
[task 2024-09-26T16:01:38.270Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http2 - [test_http2 : 74] true == true
[task 2024-09-26T16:01:38.270Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http2 - [test_http2 : 75] true == true
[task 2024-09-26T16:01:38.270Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http2 - [test_http2 : 78] true == true
[task 2024-09-26T16:01:38.271Z] 16:01:38     INFO -  "handshakeTime=13757"
[task 2024-09-26T16:01:38.271Z] 16:01:38     INFO -  "perfMetrics"
[task 2024-09-26T16:01:38.271Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http2 - [test_http2 : 1] 12 == 12
[task 2024-09-26T16:01:38.271Z] 16:01:38     INFO -  "secureConnectionStartTime=1727366200657870"
[task 2024-09-26T16:01:38.272Z] 16:01:38     INFO -  "connectEndTime=1727366200669358"
[task 2024-09-26T16:01:38.272Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http2 - [test_http2 : 74] true == true
[task 2024-09-26T16:01:38.272Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http2 - [test_http2 : 75] true == true
[task 2024-09-26T16:01:38.273Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http2 - [test_http2 : 78] true == true
[task 2024-09-26T16:01:38.273Z] 16:01:38     INFO -  "handshakeTime=11488"
[task 2024-09-26T16:01:38.273Z] 16:01:38     INFO -  "perfMetrics"
[task 2024-09-26T16:01:38.273Z] 16:01:38     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2024-09-26T16:01:38.273Z] 16:01:38     INFO -  (xpcshell/head.js) | test test_http2 finished (2)
[task 2024-09-26T16:01:38.274Z] 16:01:38     INFO -  netwerk/test/unit/test_tls_handshake_timing.js | Starting test_http1
[task 2024-09-26T16:01:38.274Z] 16:01:38     INFO -  (xpcshell/head.js) | test test_http1 pending (2)
[task 2024-09-26T16:01:38.274Z] 16:01:38     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2024-09-26T16:01:38.274Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http1 - [test_http1 : 1] 4 == 4
[task 2024-09-26T16:01:38.275Z] 16:01:38     INFO -  "secureConnectionStartTime=1727366201832593"
[task 2024-09-26T16:01:38.275Z] 16:01:38     INFO -  "connectEndTime=1727366201849843"
[task 2024-09-26T16:01:38.275Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http1 - [test_http1 : 74] true == true
[task 2024-09-26T16:01:38.276Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http1 - [test_http1 : 75] true == true
[task 2024-09-26T16:01:38.276Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http1 - [test_http1 : 78] true == true
[task 2024-09-26T16:01:38.276Z] 16:01:38     INFO -  "handshakeTime=17250"
[task 2024-09-26T16:01:38.276Z] 16:01:38     INFO -  "perfMetrics"
[task 2024-09-26T16:01:38.277Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http1 - [test_http1 : 1] 4 == 4
[task 2024-09-26T16:01:38.277Z] 16:01:38     INFO -  "secureConnectionStartTime=1727366202864821"
[task 2024-09-26T16:01:38.277Z] 16:01:38     INFO -  "connectEndTime=1727366202876527"
[task 2024-09-26T16:01:38.278Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http1 - [test_http1 : 74] true == true
[task 2024-09-26T16:01:38.278Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http1 - [test_http1 : 75] true == true
[task 2024-09-26T16:01:38.278Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http1 - [test_http1 : 78] true == true
[task 2024-09-26T16:01:38.279Z] 16:01:38     INFO -  "handshakeTime=11706"
[task 2024-09-26T16:01:38.279Z] 16:01:38     INFO -  "perfMetrics"
[task 2024-09-26T16:01:38.279Z] 16:01:38     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2024-09-26T16:01:38.279Z] 16:01:38     INFO -  (xpcshell/head.js) | test test_http1 finished (2)
[task 2024-09-26T16:01:38.280Z] 16:01:38     INFO -  netwerk/test/unit/test_tls_handshake_timing.js | Starting test_http3
[task 2024-09-26T16:01:38.280Z] 16:01:38     INFO -  (xpcshell/head.js) | test test_http3 pending (2)
[task 2024-09-26T16:01:38.280Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http3 - [test_http3 : 113] "60675" != null
[task 2024-09-26T16:01:38.281Z] 16:01:38     INFO -  TEST-PASS | netwerk/test/unit/test_tls_handshake_timing.js | test_http3 - [test_http3 : 113] "60675" != ""
[task 2024-09-26T16:01:38.281Z] 16:01:38     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
[task 2024-09-26T16:01:38.281Z] 16:01:38     INFO -  PID 7644 | routed is 0
[task 2024-09-26T16:01:38.281Z] 16:01:38     INFO -  PID 7644 | try again to get alt svc mapping
[task 2024-09-26T16:01:38.282Z] 16:01:38     INFO -  PID 7644 | results=falserouted is NA
[task 2024-09-26T16:01:38.282Z] 16:01:38     INFO -  PID 7644 | try again to get alt svc mapping
[task 2024-09-26T16:01:38.282Z] 16:01:38     INFO -  PID 7644 | results=falserouted is NA
[task 2024-09-26T16:01:38.282Z] 16:01:38     INFO -  PID 7644 | try again to get alt svc mapping
[task 2024-09-26T16:01:38.282Z] 16:01:38     INFO -  PID 7644 | results=falserouted is NA
<...>
[task 2024-09-26T16:01:38.342Z] 16:01:38     INFO -  PID 7644 | results=falserouted is NA
[task 2024-09-26T16:01:38.342Z] 16:01:38     INFO -  PID 7644 | try again to get alt svc mapping
[task 2024-09-26T16:01:38.342Z] 16:01:38     INFO -  <<<<<<<
[task 2024-09-26T16:01:38.454Z] 16:01:38     INFO -  xpcshell return code: None
[task 2024-09-26T16:01:38.478Z] 16:01:38     INFO -  TEST-START | netwerk/test/unit/test_webtransport_simple.js
[task 2024-09-26T16:06:38.492Z] 16:06:38  WARNING -  TEST-UNEXPECTED-TIMEOUT | netwerk/test/unit/test_webtransport_simple.js | Test timed out
[task 2024-09-26T16:06:38.494Z] 16:06:38     INFO -  TEST-INFO took 300014ms
[task 2024-09-26T16:06:38.494Z] 16:06:38     INFO -  >>>>>>>
[task 2024-09-26T16:06:38.495Z] 16:06:38     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2024-09-26T16:06:38.495Z] 16:06:38     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2024-09-26T16:06:38.495Z] 16:06:38     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2024-09-26T16:06:38.495Z] 16:06:38     INFO -  running event loop
<...>

Flags: needinfo?(kershaw)

Kershaw Chang [:kershaw]

Assignee

Comment 4

•

10 months ago

https://treeherder.mozilla.org/jobs?repo=try&revision=9ea0e3d0cd5a858b80097ccbb72638665819b065

Flags: needinfo?(kershaw)

Phabricator Automation

Updated

•

10 months ago

Attachment #9427160 - Attachment description: Bug 1920941 - Store secureConnectionStartin mBootstrappedTimings for NullTransaction, r=#necko → Bug 1920941 - Store secureConnectionStart in mBootstrappedTimings for NullTransaction, r=#necko

Pulsebot

Comment 5

•

10 months ago

Pushed by kjang@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/42d11b726217 Store secureConnectionStart in mBootstrappedTimings for NullTransaction, r=necko-reviewers,valentin

Sandor Molnar[:smolnar]

Comment 6

•

10 months ago

Backed out for causing bc failures @ browser_test_marker_network_redirect.js

Backout link: https://hg.mozilla.org/integration/autoland/rev/3f1aa9f8cba706813e574c5e69f7b74ccf73f8c1

Push with failures

Failure log -> TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_marker_network_redirect.js | These properties are present, but shouldn't: "secureConnectionStart".

Flags: needinfo?(kershaw)

Kershaw Chang [:kershaw]

Assignee

Updated

•

10 months ago

Flags: needinfo?(kershaw)

Pulsebot

Comment 7

•

9 months ago

Pushed by kjang@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f177dd989d3c Store secureConnectionStart in mBootstrappedTimings for NullTransaction, r=necko-reviewers,valentin,profiler-reviewers,canaltinova

Serban Stanca [:SerbanS]

Comment 8

•

9 months ago

Backed out for causing xpcshell failures in test_tls_handshake_timing.js.

Backout link
Push with failures
Failure Log
Failure line: TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_tls_handshake_timing.js | xpcshell return code: 0

Flags: needinfo?(kershaw)

Pulsebot

Comment 9

•

9 months ago

Pushed by kjang@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/b3f73fdd7999 Store secureConnectionStart in mBootstrappedTimings for NullTransaction, r=necko-reviewers,valentin,profiler-reviewers,canaltinova

Kershaw Chang [:kershaw]

Assignee

Updated

•

9 months ago

Flags: needinfo?(kershaw)

agoloman

Comment 10

•

9 months ago

bugherder

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

Status: ASSIGNED → RESOLVED

Closed: 9 months ago

status-firefox133: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 133 Branch

Bugzilla

Missing TLS Handshake Timing for Speculative Connections

Categories

(Core :: Networking: HTTP, defect, P2)

Tracking

()

People

(Reporter: kershaw, Assigned: kershaw)

References

Details

(Whiteboard: [necko-triaged] [necko-priority-queue])

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Comment 1

Updated

Comment 2

Comment 3

Comment 4

Updated

Comment 5

Comment 6

Updated

Comment 7

Comment 8

Comment 9

Updated

Comment 10

Attachment

General

Description

File Name

Content Type