[
https://issues.apache.org/jira/browse/TS-3415?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14340324#comment-14340324
]
Susan Hinrichs commented on TS-3415:
------------------------------------
I think the issue is that HTTP/2 processing is resetting the connection back to
the server before it has read all the data. The client then hangs out waiting
for the rest of the data to show up. This might be related to the issue that
[~briang] noted in TS-3413. In fact I'm fairly certain that this is the case.
The code in question is
{code}
if (stream->is_body_done() && payload_length < send_size) {
flags |= HTTP2_FLAGS_DATA_END_STREAM;
}
{code}
Based on the chrome:net-internals, I see two SPDY_SESSION_RECV_DATA of size
8183 and 2944 respectively. Then a SPDY_SESSION_SEND_RST_STREAM.
Doing a packet capture on the ATS machine on the outgoing interface, I can sum
the SSL application data frames, and see a set that is roughly the size of the
first RECV_DATA and another set that is roughly the size of the second
RECV_DATA and a third set that will be at least as big as the first set, but it
is interrupted with a RST back to the origin server.
I set a break point on the flags line in the code above and tracked through the
setting of the stream->is_done field. payload_length was 2922 and send_size
was 8183. The logic for setting send_size and payload_length is below.
{code}
size_t window_size = min(this->client_rwnd, stream->client_rwnd);
size_t send_size = min(buf_len, window_size);
size_t payload_length =
fetch_sm->ext_read_data(reinterpret_cast<char*>(payload_buffer), send_size);
{code}
The buf_len is approximately 16K, so send_size is being set to the window_size.
It seems likely that as the window size increases, you will have smaller
payloads that will trigger the second condition. So I'm not sure what the
intent was with that check. [~rokubo] can you explain.
In any case, the stream->is_body_done() shouldn't be true at this point either.
I tracked through that logic, and the is_done field is set because FetchSM
sent TS_FETCH_EVENT_EXT_BODY_DONE. And this happened because
fetch_sm->has_body() was false. This was the case because check_chunked() was
false and the CONTENT_LENGTH field was not present. I added a presence check
there and the bug has squished through to someplace else which I'm tracking
down now.
> H2 sending FIN stream too early
> -------------------------------
>
> Key: TS-3415
> URL: https://issues.apache.org/jira/browse/TS-3415
> Project: Traffic Server
> Issue Type: Bug
> Components: HTTP/2
> Reporter: Sudheer Vinukonda
> Attachments: ts-3415-3414.diff, ts-3415.diff
>
>
> With H2 running on the docs/jenkins server, some of us have noticed empty
> pages on chrome/FF when hitting those servers. Looking at the H2 traces, it
> seems that ATS is sending FIN streams (both SPDY_SESSION_RECV_HEADERS and
> SPDY_SESSION_RECV_DATA with fin flag set to true) before sending the data
> frames. This makes the browser display blank pages.
> Example:
> {code}
> t=31890437 [st=140] SPDY_SESSION_RECV_DATA
> --> fin = true
> --> size = 0
> --> stream_id = 1
> t=31890437 [st=140] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 2591
> --> stream_id = 1
> {code}
> Detailed traces below:
> {code}
> 1112054: SPDY_SESSION
> ci.trafficserver.apache.org:443 (DIRECT)
> Start Time: 2015-02-26 13:30:14.060
> t=31890297 [st= 0] +SPDY_SESSION [dt=?]
> --> host = "ci.trafficserver.apache.org:443"
> --> proxy = "DIRECT"
> t=31890297 [st= 0] SPDY_SESSION_INITIALIZED
> --> protocol = "h2-14"
> --> source_dependency = 1112049 (SOCKET)
> t=31890297 [st= 0] SPDY_SESSION_SEND_SETTINGS
> --> settings = ["[id:3 flags:0 value:1000]","[id:4
> flags:0 value:10485760]"]
> t=31890297 [st= 0] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 10420224
> --> window_size = 10485760
> t=31890297 [st= 0] SPDY_SESSION_SENT_WINDOW_UPDATE_FRAME
> --> delta = 10420224
> --> stream_id = 0
> t=31890297 [st= 0] SPDY_SESSION_SYN_STREAM
> --> fin = true
> --> :authority: ci.trafficserver.apache.org
> :method: GET
> :path: /job/tsqa-master/180/consoleFull
> :scheme: https
> accept:
> text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
> accept-encoding: gzip, deflate, sdch
> accept-language: en-US,en;q=0.8
> cache-control: max-age=0
> cookie: [71 bytes were stripped]
> user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
> 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.115
> Safari/537.36
> --> spdy_priority = 0
> --> stream_id = 1
> --> unidirectional = false
> t=31890335 [st= 38] SPDY_SESSION_RECV_SETTINGS
> --> clear_persisted = false
> --> host = "ci.trafficserver.apache.org:443"
> t=31890335 [st= 38] SPDY_SESSION_RECV_SETTING
> --> flags = 0
> --> id = 1
> --> value = 4096
> t=31890335 [st= 38] SPDY_SESSION_RECV_SETTING
> --> flags = 0
> --> id = 2
> --> value = 0
> t=31890335 [st= 38] SPDY_SESSION_RECV_SETTING
> --> flags = 0
> --> id = 3
> --> value = 100
> t=31890436 [st=139] SPDY_SESSION_RECV_HEADERS
> --> fin = true
> --> :status: 200
> age: 1
> cache-control: no-cache,no-store,must-revalidate
> content-encoding: gzip
> content-type: text/html;charset=UTF-8
> date: Thu, 26 Feb 2015 21:30:14 GMT
> expires: Thu, 01 Jan 1970 00:00:00 GMT
> server: ATS/5.3.0
> set-cookie: [67 bytes were stripped]
> strict-transport-security: max-age=86400
> via: http/1.1 ATS (ApacheTrafficServer/5.3.0
> [cMsSf ])
> x-frame-options: sameorigin
> x-hudson: 1.395
> x-hudson-cli-port: 40666
> x-hudson-theme: default
> x-instance-identity:
> MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEA5JuJJnF3WReAyfHqknx9O1JV3chT6Iihwk/UIOYpZ6tLORwKrzPYVO6ho7cpwT9Jtfj91lb9Gpx0FZnhGZXsdh9SMYG8gUfGo3DRy9dLkXjNu5kYo9PQk701PvnCQJSByIpzGWTCoIwfgWTGqMEuGYZ5TvRbLnmm9j9ujo2SQpOeAUXi9f0d27wcb/MOYv8H8nICgsAcpp1AaTcboabfsJYWNodDDPYvtCjfIbQhBov5qDFnsmYXbmWavXaJ2ZGI24jSmdebFcto7NlbLLAI0JFHFualDGvfcY51NGaiK1+MNxllYsEnVSP6kSdxEtJSHOxN7z6oRVGKExh104YyDQIDAQAB
> x-jenkins: 1.598
> x-jenkins-cli-port: 40666
> x-jenkins-cli2-port: 40666
> x-jenkins-session: 906fc928
> --> stream_id = 1
> t=31890437 [st=140] SPDY_SESSION_RECV_DATA
> --> fin = true
> --> size = 0
> --> stream_id = 1
> t=31890437 [st=140] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 2591
> --> stream_id = 1
> t=31890437 [st=140] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -2591
> --> window_size = 10483169
> t=31890437 [st=140] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 2591
> --> window_size = 10485760
> t=31890437 [st=140] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 5592
> --> stream_id = 1
> t=31890437 [st=140] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -5592
> --> window_size = 10480168
> t=31890437 [st=140] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 5592
> --> window_size = 10485760
> t=31890437 [st=140] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 2591
> --> stream_id = 1
> t=31890437 [st=140] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -2591
> --> window_size = 10483169
> t=31890437 [st=140] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 2591
> --> window_size = 10485760
> t=31890488 [st=191] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 3900
> --> stream_id = 1
> t=31890488 [st=191] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -3900
> --> window_size = 10481860
> t=31890488 [st=191] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 3900
> --> window_size = 10485760
> t=31890488 [st=191] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 1692
> --> stream_id = 1
> t=31890488 [st=191] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -1692
> --> window_size = 10484068
> t=31890488 [st=191] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 1692
> --> window_size = 10485760
> t=31890488 [st=191] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 6491
> --> stream_id = 1
> t=31890488 [st=191] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -6491
> --> window_size = 10479269
> t=31890488 [st=191] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 6491
> --> window_size = 10485760
> t=31890488 [st=191] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 1692
> --> stream_id = 1
> t=31890488 [st=191] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -1692
> --> window_size = 10484068
> t=31890488 [st=191] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 1692
> --> window_size = 10485760
> t=31890488 [st=191] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 6491
> --> stream_id = 1
> t=31890488 [st=191] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -6491
> --> window_size = 10479269
> t=31890488 [st=191] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 6491
> --> window_size = 10485760
> t=31890488 [st=191] SPDY_SESSION_RECV_DATA
> --> fin = false
> --> size = 647
> --> stream_id = 1
> t=31890488 [st=191] SPDY_SESSION_UPDATE_RECV_WINDOW
> --> delta = -647
> --> window_size = 10485113
> t=31890488 [st=191] SPDY_STREAM_UPDATE_RECV_WINDOW
> --> delta = 647
> --> window_size = 10485760
> t=31890488 [st=191] SPDY_SESSION_RECV_DATA
> --> fin = true
> --> size = 0
> --> stream_id = 1
> t=31890490 [st=193] SPDY_SESSION_SYN_STREAM
> --> fin = true
> --> :authority: ci.trafficserver.apache.org
> :method: GET
> :path: /favicon.ico
> :scheme: https
> accept: */*
> accept-encoding: gzip, deflate, sdch
> accept-language: en-US,en;q=0.8
> cookie: [71 bytes were stripped]
> if-modified-since: Fri, 30 Jan 2015 15:31:33 GMT
> user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
> 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.115
> Safari/537.36
> --> spdy_priority = 4
> --> stream_id = 3
> --> unidirectional = false
> t=31890555 [st=258] SPDY_SESSION_RECV_HEADERS
> --> fin = true
> --> :status: 304
> date: Thu, 26 Feb 2015 21:30:14 GMT
> expires: Mon, 09 Feb 2015 19:39:27 GMT
> server: ATS/5.3.0
> strict-transport-security: max-age=86400
> via: http/1.1 ATS (ApacheTrafficServer/5.3.0
> [cSsNfU])
> --> stream_id = 3
> t=31890555 [st=258] SPDY_SESSION_RECV_DATA
> --> fin = true
> --> size = 0
> --> stream_id = 3
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
