NEL report elapsed_time values are days long
Reported by
scott.he...@gmail.com,
Dec 20
|
|||||
Issue description
UserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36
Steps to reproduce the problem:
1. Deploy a NEL policy with reporting enabled.
2. Observe reports and elapsed_time value.
What is the expected behavior?
It seems really unusual that the browser is reporting elapsed_time values of between 5 and 16 *days*!! I will includ a few sample JSON payloads of the kind of thing I mean:
What went wrong?
{
"elapsed_time": 364896995,
"method": "GET",
"phase": "application",
"protocol": "h2",
"sampling_fraction": 1,
"server_ip": "104.24.96.190",
"status_code": 200,
"type": "unknown",
"url": "https://scotthelme.co.uk/content/images/2017/03/whoami.jpg"
}
{
"elapsed_time": 364897456,
"method": "GET",
"phase": "application",
"protocol": "h2",
"sampling_fraction": 1,
"server_ip": "104.24.96.190",
"status_code": 200,
"type": "unknown",
"url": "https://scotthelme.co.uk/content/images/2017/03/business-server-2.JPG"
}
{
"elapsed_time": 364897464,
"method": "GET",
"phase": "application",
"protocol": "h2",
"sampling_fraction": 1,
"server_ip": "104.24.96.190",
"status_code": 200,
"type": "unknown",
"url": "https://scotthelme.co.uk/content/images/2017/03/business-server-2.JPG"
}
The phase is application yet the error type always seems to be unknown.
Did this work before? N/A
Chrome version: 71.0.3578.98 Channel: stable
OS Version: 10.0
Flash Version:
,
Dec 20
Hey Matt, I hear that you're the right person to triage NEL bugs. Mind taking a look at this one? The behavior seems unexpected, and the relevant code seems to be correctly converting to milliseconds (https://cs.chromium.org/chromium/src/net/network_error_logging/network_error_logging_service.cc?sq=package:chromium&g=0&l=543). It seems odd that we'd end up with errors delivered several days later.
,
Dec 20
[+chlily] Not sure where you heard that, but I'm not familiar with this code. Handing off bug to chlily.
,
Dec 20
,
Dec 20
Looking into this. We're not actually delivering days-old error reports, but rather we're incorrectly recording the elapsed time.
,
Dec 20
,
Dec 20
@chlily it's a bit of a guess for me because we don't record the 'age' property delivered as part of the payload, we just store the 'body'.
,
Dec 20
I ran a bisect and found this range: https://chromium.googlesource.com/chromium/src/+log/fd1e1a9f7b904ac3e22aef3872da9f7af1272d97..992c44541df673bc4f0a8061ad5bf47af905a0c4 So this almost certainly broke when NEL report generation was moved from URLRequest to HTTPNetworkTransaction. It looks like |timing.request_start| is 0 when we calculate the elapsed time here: https://cs.chromium.org/chromium/src/net/http/http_network_transaction.cc?l=1425
,
Dec 20
Request start is logged by the top of the stack, so the bottom doesn't know when the request started. It's unfortunate that time is difficult to test, but there are ways to at least sanity check values, even without hooking into the time mocking infrastructure.
,
Jan 11
|
|||||
►
Sign in to add a comment |
|||||
Comment 1 by scott.he...@gmail.com
, Dec 2010+ days for favicon: { "elapsed_time": 865471850, "method": "GET", "phase": "application", "protocol": "h2", "sampling_fraction": 1, "server_ip": "104.24.97.190", "status_code": 200, "type": "unknown", "url": "https://scotthelme.co.uk/favicon.ico" }