https cache misses timeout at proxy.config.http.transaction_no_activity_timeout_in

[mlibbey]

In ATS 7, with https requests, we are able to consistently reproduce clients getting disconnected at proxy.config.http.transaction_no_activity_timeout_in
for cache misses. eg when set to 20 we see:

$ curl --limit-rate 10M -D- https://example.com/mybigfile
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0HTTP/1.1 200 OK
Date: Fri, 30 Jun 2017 21:29:12 GMT
Last-Modified: Wed, 26 Oct 2016 22:24:18 GMT
Accept-Ranges: bytes
Content-Type: binary/octet-stream
Content-Length: 1125156837
Server: ATS/7.0.0
Cache-Control: max-age=600, public
Access-Control-Allow-Origin: *
Etag: "11c8b7ebe78d6a7bbacd4582820939f4"
Age: 0
Connection: close

 18 1073M   18  203M    0     0   9.9M      0  0:01:47  0:00:20  0:01:27 10.0M
curl: (18) transfer closed with 904329920 bytes remaining to read

(note the 0:00:20 in the curl progress note)

or when set to 60

$curl --limit-rate 10M -D- https://example.com/mybigfile
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0HTTP/1.1 200 OK
Date: Fri, 30 Jun 2017 21:18:25 GMT
Last-Modified: Wed, 26 Oct 2016 22:24:18 GMT
ETag: "11c8b7ebe78d6a7bbacd4582820939f4"
Accept-Ranges: bytes
Content-Type: binary/octet-stream
Content-Length: 1125156837
Server: ATS/7.0.0
Cache-Control: max-age=600, public
Access-Control-Allow-Origin: *
Age: 2
Connection: close

 59 1073M   59  638M    0     0   9.9M      0  0:01:47  0:01:03  0:00:44 10.0Mcurl: (18) transfer closed with 450919099 bytes remaining to read

(note the 0:01:03 in the curl progress note)

We could not reproduce the issue when serving from cache -- only for misses. Similarly, we can only reproduce with https requests, not http.

[zwoop]

Not 100% certain, but backing out b34de98 from master seems to "fix" the issues in the test case that I've been doing. I'm not sure this makes a lot of sense though, since that commit shouldn't be on 7.0.0 ??

Maybe there are two (or more??) issues here?

[realpdm]

I can confirm this behavior too in testing a build in the ats 7.x branch. i have not tried backing out the mentioned commit though.

My test is uploading files (POST) and I can confirm if I dial down the no_activity_timeout_in to a low value the uploads fail at that time, despite sending data. the PR 2239 doesn't seem to fix the POST failure problem.

[maskit]

@realpdm I confirmed the POST request issue.

If you keep uploading data fast enough, SSL_ERROR_WANT_READ won't be happen and ATS keep reading the data without updating inactivity timer here.
https://github.com/apache/trafficserver/blob/7.0.x/iocore/net/SSLNetVConnection.cc#L205

The issues seems to be introduced with #629.
@oknet pointed out the issue on the PR, however we haven't made a fix for it.

[shinrich]

It looks like the issue is that the UnixNetVConnection version of read_from_net calls net_activity(vc, thread) which resets the next_activity_timeout_at timestamp after getting done with the read loop.

The ssl_read_from_net() should probably make a similar call. Otherwise, it appears it only gets reset via set_enabled. This appears to be a latent issue perhaps made work with the change to make the SSL read loop more aggressive. I'll try to set up a PR for this (and perhaps an autest).

Nevermind. The ssl version does call net_activity(). Looking some more.