New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.
Starred by 6 users

Issue metadata

Status: WontFix
Owner: ----
Closed: Jun 27
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: All
Pri: 2
Type: Bug

Blocking:
issue 404501
issue 305039



Sign in to add a comment

[Resource Timing] secureConnectionStart does not report start of HTTPS handshake

Project Member Reported by igrigo...@chromium.org, Jan 15 2015

Issue description

Version: 42.0.2276.0 canary, 39.0.2171.95 (64-bit)
OS: OSX 10.9.5

What steps will reproduce the problem?
1. Open: http://jsbin.com/jijesi/3/quiet
2. secureConnectionStart reports 0, but image is fetched from remote HTTPS origin (with TAO opt-in)

What is the expected output? What do you see instead?
"if the scheme [URL] of the resource is "HTTPS" [RFC2817], this attribute must return the time immediately before the user agent starts the handshake process to secure the current connection."

From: https://w3c.github.io/resource-timing/#widl-PerformanceResourceTiming-secureConnectionStart

- If a connection is reused: we should report a timestamp that's equal to connectStart
- If a connection is new: we should report the starting timestamp of TLS handshake

Last but not least... if I flush all the socket pools (via net-internals), etc, I *do* sometimes see a non-zero value for secureConnectionStart, but I haven't been able to figure out what triggers that. On the other hand, I do see lots of cases where a new TLS socket is being opened (via net-internal events) but secureConnectionStart still reports 0.. so there is a bug in there somewhere.

Without reliable secureConnectionStart we can't use RUM data to diagnose TLS performance.
 

Comment 1 by mmenke@chromium.org, Jan 15 2015

When we report 0, is connectStart also 0?

With preconnect, the start events will often be finished before the request reaches the network stack, and we don't report negative times, for obvious reasons.

Also, you aren't using Google sites for testing, right?  No idea what happens in the QUIC case.  SPDY should report correct values.
Try this and refresh it a few times: http://jsbin.com/jijesi/3/quiet - secureConnectionStart = 0 even when connectStart != 0.

Re, preconnect: I suspected this might be the case, which is why I was looking at the events tab in net-internals.. If I flush all the sockets and refresh the tab, I still see 0's for secureConnectionStart.. and I don't think the connection is initiated due to preconnect (although not 100% sure how to prove that).

Last but not least: no, not google sites. The image resource I'm using in above test case is served via nginx on my own server.

Comment 3 by mmenke@chromium.org, Jan 15 2015

Think the bug may actually that the connect times aren't 0.  At least when I reload it multiple times in a row (No socket pool flush), I see a zero secureConnectionStart, and non-zero connectStart times.  Diving into the network stack, I see that we are in fact reusing the SPDY connection.  Values become non-zero sometime between there and the renderer process.

Remember that we preconnect when a navigation starts, so when we see you start navigating to  http://jsbin.com/jijesi/3/quiet, before we start downloading, we may already establishing an HTTPS connection.
I think this is based on whether the socket was reused or not, yeah. The cases you see where a new socket is opened but secureConnectionStart reports 0 is likely, as Matt mentions, a preconnect. If you're not sure how to verify that, could you attach one of the net-internals dumps in question?

The bug appears to be in Blink. //net seems to never fill in any connect information for reused sockets for any properties. Instead, Blink patches in the zero values when it was a reuse. Although this does mean we have to plumb down a bit into Performance{,Resource}Timing to know whether secureConnectionStart is expected to be zero (because this is HTTPS) or whether it should use connectStart as placeholder.

https://code.google.com/p/chromium/codesearch#chromium/src/third_party/WebKit/Source/core/timing/PerformanceTiming.cpp&q=connectEnd%20case:yes&sq=package:chromium&type=cs&l=137
https://code.google.com/p/chromium/codesearch#chromium/src/third_party/WebKit/Source/core/timing/PerformanceResourceTiming.cpp&q=secureConnectionStart%20case:yes&sq=package:chromium&type=cs&l=151

Incidentally, I think there's a need to clarify the spec here slightly. For most of the other fields, the spec explicitly contains language like:

"If a persistent connection [RFC7230] is used or the resource is retrieved from relevant application caches or local resources, this attribute [connectEnd] must return the value of domainLookupEnd."

"If a persistent connection [RFC7230] is used or the resource is retrieved from relevant application caches or local resources, this attribute [connectStart] must return value of domainLookupEnd."

"If a persistent connection [RFC7230] is used or the resource is retrieved from relevant application caches or local resources, this attribute [domainLookupEnd] must return the same value as fetchStart."

"If a persistent connection [RFC7230] is used or the resource is retrieved from relevant application caches or local resources, this attribute [domainLookupStart] must return the same value as fetchStart."

But secureConnectionStart lacks such text (and logic in Blink). It should probably spec a fallback to connectStart. But I don't think it matters exactly which you use here.

In the meantime, assuming I haven't missed some other bug, I think you can just assume any zero secureConnectionStarts are equal to connectStart.

It may also be worth double-checking that we fill it in for QUIC, but, yeah, this test case isn't using QUIC.
Labels: Cr-Blink-Loader

Comment 6 by mmenke@chromium.org, Jan 15 2015

Labels: -Cr-Internals-Network
secureConnectionStart should presumably not have that logic for non-secure connections.  Sounds like we're actually adhering to the spec here.

I have noticed sometimes I get the image successfully loaded but "undefined" is displayed instead of the load times, which seems weird.  Maybe that happens when blink uses its in-memory cache?

Anyhow, the network stack seems to be behaving exactly as expected here (connect times are all 0, including SSL times), so this isn't actually a network stack issue.
Right, we need to plumb a bit into those two objects in Blink so it can only kick in the secureConnectionStart fallback only for secure URLs. The spec needs the same condition.
Cc: pmeenan@chromium.org
Ah, interesting.. it does look like it's subresource preconnects after all: 

- I've cleared all of my history (clean profile)
- First navigation to http://jsbin.com/jijesi/3/quiet shows non zero secureConnectionStart
- Close all sockets + flush socket pools + reload the page... secureConnectionStart = 0
-- Checking chrome://dns shows that a subresource preconnect was used (see attached)

Re, blink loader: I think we had a similar issue earlier with resources coming from a memory cache and reporting 0's.. I believe either Pat or Simon resolved it.

Last but not least, agreed.. we should clarify this behavior in the spec -- I'll kick off a thread on that. 
subresource-preconnect.png
40.9 KB View Download
Labels: -Cr-Blink-Loader Cr-Blink-PerformanceAPIs
Status: Available
Pat, did we resolve this? Anything actionable here?
Is it still reproducible?  I'm getting 0 for both regularly now.  There was an issue at one point with some of those fields not being initialized correctly in Blink which was the cache issue and it's possible that fixed it.
The spec was updated: http://w3c.github.io/resource-timing/#dom-performanceresourcetiming-secureconnectionstart

Re, preconnect interaction: https://github.com/w3c/resource-timing/issues/58 - I think we should continue the discussion there.

Re, cache issue: this one I'm not sure. If it's not yet resolved I propose that we open a new bug for it and close this one.

The HPBN image you're loading in http://jsbin.com/jijesi/3/quiet is missing Timing-Allow-Origin headers. Not sure if that was the case when you originally posted the link, but that explains why most of the ResourceTiming entries (including secureconnectionstart) are 0'd now.
Blocking: 305039
Blocking: 404501
Any thoughts on who a good owner for this would be?
Cc: sunjian@chromium.org panicker@chromium.org
sunjian@ worked on NT2 recently, perhaps he could take a look? :)
Summary: [Resource Timing] secureConnectionStart does not report start of HTTPS handshake (was: secureConnectionStart does not report start of HTTPS handshake)
Components: Blink>PerformanceAPIs>ResourceTiming
Components: -Blink>PerformanceAPIs
Status: Fixed (was: Available)
Actually, based on the conversation above, it sound like this has been fixed.

Please reopen if I'm mistaken.
Status: Available (was: Fixed)
To the extent of my knowledge, it hasn't been changed, at least in terms of the times net/ reports.  The spec was updated, but Chrome's behavior was not.
Thanks.

Both connectStart and secureConnectionStart are reporting 0. What's the desired behavior?
Returning fetch start, I think?  It's in the spec - it's not just reporting 0.
Status: WontFix (was: Available)
The example currently is not passing the TAO check hence why many attributes, including secureConnectionStart, are 0. Since the example in the bug report is now obsolete, I'm closing this issue. Feel free to reopen if there is anything different in here from what's already being looked at in issue 404501.

Sign in to add a comment