[
https://issues.apache.org/jira/browse/TS-3415?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14340753#comment-14340753
]
Susan Hinrichs commented on TS-3415:
------------------------------------
Much more time spent staring at HTTP/2 logs.
Without the ts-3415.diff patch, the fetch from the tsqa console immediately
returns a FIN REC_DATA because the response is not chunked and does not have a
content-length field. In that case, all the data appears to be sent after the
FIN (in three groupings), but the client browser rightly ignores it.
With the ts-3415.diff patch, no FIN gets sent immediately, which is good. But
after the first grouping of data sent, (two RECV_DATA's in the log below), the
browser sends a Reset with Status = 5. This takes down the connection, so ATS
doesn't try to send the rest of the data.
What does status = 5 mean? I assume that the data we are sending is not quite
in the expected format?
{code}
53238: SPDY_SESSION
Start Time: 2015-02-27 14:06:00.262
t=16750 [st= 0] SPDY_SESSION_PING
--> is_ack = false
--> type = "sent"
--> unique_id = 1
t=16750 [st= 0] SPDY_SESSION_SYN_STREAM
--> fin = true
--> :authority: asba.safelyfiled.com
:method: GET
:path: /ci/job/tsqa-master/185/console
: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: [235 bytes were stripped]
user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.115 Safari/537.36
--> spdy_priority = 0
--> stream_id = 5
--> unidirectional = false
t=16752 [st= 2] SPDY_SESSION_PING
--> is_ack = true
--> type = "received"
--> unique_id = -1379995682
t=16962 [st=212] SPDY_SESSION_RECV_HEADERS
--> fin = false
--> :status: 200
age: 0
cache-control: no-cache,no-store,must-revalidate
content-encoding: gzip
content-type: text/html;charset=UTF-8
date: Fri, 27 Feb 2015 20:06:00 GMT
expires: 0
server: ATS/5.3.0
strict-transport-security: max-age=86400
via: http/1.1 ATS (ApacheTrafficServer/5.3.0 [cMsSf ])
x-consoleannotator:
sYriu+AwnIcSEtOy0iQVABcxuHkFbgPxm377AUU32BfKGlNwhplRMGA9NtzZR9STdlikP9dCjaQSFIh9UcRoWrTLX4aJ9k1PondxJHjBs0vUrbfQMdUYl80xbVfN/+pB
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 = 5
t=16963 [st=213] SPDY_SESSION_RECV_DATA
--> fin = false
--> size = 8183
--> stream_id = 5
t=16963 [st=213] SPDY_SESSION_UPDATE_RECV_WINDOW
--> delta = -8183
--> window_size = 10477577
t=16964 [st=214] SPDY_SESSION_RECV_DATA
--> fin = false
--> size = 2944
--> stream_id = 5
t=16964 [st=214] SPDY_SESSION_UPDATE_RECV_WINDOW
--> delta = -2944
--> window_size = 10474633
t=16967 [st=217] SPDY_STREAM_UPDATE_RECV_WINDOW
--> delta = 8183
--> window_size = 10482816
t=16967 [st=217] SPDY_STREAM_UPDATE_RECV_WINDOW
--> delta = 2944
--> window_size = 10485760
t=16967 [st=217] SPDY_SESSION_SEND_RST_STREAM
--> description = ""
--> status = 5
--> stream_id = 5
{code}
> 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)
