[
https://issues.apache.org/jira/browse/TS-3049?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14115342#comment-14115342
]
Sudheer Vinukonda commented on TS-3049:
---------------------------------------
Debugging further, it seems that FetchSM may never see the chunking (confirmed
with the logs below, that for a chunked response, in both working and failing
cases, body_done is sent immediately after header_done events). If the data is
all available by the time header_done is sent, the body is able to be sent
correctly, and if the data is not available by then, empty body is returned.
Working Case Logs:
{code}
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel) tunnel_run
started, p_arg is NULL
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
636
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel)
[producer_run] do_dechunking::Copied header of size 636
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_cs)
tcp_init_cwnd_set 0
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_cs) desired TCP
congestion window is 0
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
636
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.skip_bytes = 636
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel) [18]
producer_handler [http server VC_EVENT_READ_READY]
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel) [18]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel) [18]
producer_handler [http server VC_EVENT_READ_READY]
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel) [18]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_chunk) read chunk
size of 11978 bytes
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_chunk) completed
read of chunk of 11978 bytes
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel) [18]
consumer_handler [cache write VC_EVENT_WRITE_READY]
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (http_tunnel) [18]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 12614
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (FetchSM)
[process_fetch_read] copied 12614 bytes
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (FetchSM)
[process_fetch_read] total copied 12614 bytes
[Aug 29 14:47:07.183] Server {0x2b8425c4c700} DEBUG: (spdy) ----[FETCH HEADER
DONE]
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy)
----spdylay_submit_syn_reply
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy-event)
++++SpdyClientSession[1], EVENT:-2, ret:0
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy) ----[FETCH BODY
DONE]
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy)
----spdylay_submit_data
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy-event)
++++SpdyClientSession[1], EVENT:-4, ret:0
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (http_tunnel) [18]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy) ----[WRITE EVENT]
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy)
----spdy_send_callback, length:392
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy) ----SEND SYN_REPLY
(sm_id:1, stream_id:1, flag:0, length:384)
Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (FetchSM) [cleanUp] calling
cleanup
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy) ****Delete
Request[1:1]
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy)
----spdy_send_callback, length:3794
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy) ----SEND DATA frame
(sm_id:1, stream_id:1, flag:1, length:3786)
[Aug 29 14:47:07.184] Server {0x2b8425c4c700} DEBUG: (spdy-event)
++++SpdyClientSession[1], EVENT:101, ret:0
{code}
Failed Case Logs:
{code}
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
636
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel)
[producer_run] do_dechunking::Copied header of size 636
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_cs)
tcp_init_cwnd_set 0
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_cs) desired TCP
congestion window is 0
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
636
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.skip_bytes = 636
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel) [125828193]
producer_handler [http server VC_EVENT_READ_READY]
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel) [125828193]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel) [125828193]
consumer_handler [cache write VC_EVENT_WRITE_READY]
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel) [125828193]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 636
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (FetchSM)
[process_fetch_read] copied 636 bytes
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (FetchSM)
[process_fetch_read] total copied 636 bytes
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy) ----[FETCH HEADER
DONE]
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy)
----spdylay_submit_syn_reply
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy-event)
++++SpdyClientSession[5468429], EVENT:-2, ret:0
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy) ----[FETCH BODY
DONE]
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy)
----spdylay_submit_syn_reply
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy-event)
++++SpdyClientSession[5468429], EVENT:-2, ret:0
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy) ----[FETCH BODY
DONE]
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy)
----spdylay_submit_data
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (spdy-event)
++++SpdyClientSession[5468429], EVENT:-4, ret:0
[Aug 28 14:12:55.052] Server {0x2aebb6757700} DEBUG: (http_tunnel) [125828193]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Aug 28 14:12:55.053] Server {0x2aebb6757700} DEBUG: (spdy) ----[WRITE EVENT]
[Aug 28 14:12:55.053] Server {0x2aebb6757700} DEBUG: (spdy)
----spdy_send_callback, length:393
[Aug 28 14:12:55.053] Server {0x2aebb6757700} DEBUG: (spdy) ----SEND SYN_REPLY
(sm_id:5468429, stream_id:1, flag:0, length:385)
[Aug 28 14:12:55.053] Server {0x2aebb6757700} DEBUG: (FetchSM) [cleanUp]
calling cleanup
[Aug 28 14:12:55.053] Server {0x2aebb6757700} DEBUG: (spdy) ****Delete
Request[5468429:1]
[Aug 28 14:12:55.053] Server {0x2aebb6757700} DEBUG: (spdy)
----spdy_send_callback, length:8
[Aug 28 14:12:55.053] Server {0x2aebb6757700} DEBUG: (spdy) ----SEND DATA frame
(sm_id:5468429, stream_id:1, flag:1, length:0)
[Aug 28 14:12:55.053] Server {0x2aebb6757700} DEBUG: (spdy-event)
++++SpdyClientSession[5468429], EVENT:101, ret:0
{code}
> SPDY requests returning 200 OK with empty body..
> ------------------------------------------------
>
> Key: TS-3049
> URL: https://issues.apache.org/jira/browse/TS-3049
> Project: Traffic Server
> Issue Type: Bug
> Components: SPDY
> Affects Versions: 5.0.1
> Reporter: Sudheer Vinukonda
> Assignee: Brian Geffon
> Priority: Blocker
> Fix For: 5.1.0
>
> Attachments: ts3049.pcap
>
>
> Ran into another issue in our production, where some SPDY requests were
> returning a valid response (200 OK), but, with no data (empty body).
> Below is a sample response:
> {code}
> t=688758 [st= 1] SPDY_SESSION_SYN_STREAM
> --> fin = true
> --> :host: ********
> :method: GET
> :path: /********.js
> :scheme: https
> :version: HTTP/1.1
> accept:
> text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
> accept-encoding: gzip,deflate
> accept-language: en-US,en;q=0.8
> cache-control: max-age=0
> cookie: [215 bytes were stripped]
> user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS
> X 10_9_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.94
> Safari/537.36
> --> spdy_priority = 0
> --> stream_id = 1
> --> unidirectional = false
> t=688941 [st= 184] SPDY_SESSION_SYN_REPLY
> --> fin = false
> --> :status: 200 OK
> :version: HTTP/1.1
> accept-ranges: bytes
> age: 2
> cache-control: max-age=536112000
> content-encoding: gzip
> content-type: application/javascript
> date: Wed, 27 Aug 2014 23:39:53 GMT
> etag: "************************"
> expires: Sat, 05 Sep 2026 00:00:00 GMT
> last-modified: Wed, 27 Aug 2014 20:09:00 GMT
> server: ATS
> vary: Accept-Encoding
> via: HTTP/1.1 ********** (ApacheTrafficServer)
> x-ysws-request-id: **********
> x-ysws-visited-replicas: *********
> --> stream_id = 1
> t=688941 [st= 184] SPDY_SESSION_RECV_DATA
> --> fin = true
> --> size = 0
> --> stream_id = 1
> {code}
> Investigating further, it seems that the issue occurs, when the response from
> the origin is chunked. Debugging further, it looks like there's a bug in
> FetchSM - check_body_done() is broken for chunked encoding case.
> {code}
> bool
> FetchSM::check_body_done()
> {
> if (!check_chunked()) {
> if (resp_content_length == resp_recived_body_len +
> resp_reader->read_avail())
> return true;
> return false;
> }
> //
> // TODO: check whether the chunked body is done
> //
> return true;
> }
> {code}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
