[
https://issues.apache.org/jira/browse/TS-2306?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13882637#comment-13882637
]
Thach Tran edited comment on TS-2306 at 1/27/14 8:48 AM:
---------------------------------------------------------
Hi Ron,
Thanks for looking into this. My apologies for the late reply.
I can still reproduce with trafficserver's master HEAD in git. I just realised
that the problem description contained some typos which could be the reason why
you couldn't recreate. I corrected it now.
Basically the problem is with a ~10GB file, client <> ATS is unencrypted, and
ATS <> origin is SSL-encrypted (http://localhost:8081/files/testfile10g.bin
with the remap above), then I am seeing the download hung on client side and
eventually terminated by ATS. With the same download but ATS <> origin is
unencrypted (http://localhost:8080/files/testfile10g.bin with the remap above)
then everything seems ok.
Answers to your questions are as follows.
bq. What is the exact size of the testfile10g.bin?
10737418240 bytes = 10GB which I generated using
{noformat}
dd if=/dev/zero of=testfile10g.bin bs=1 count=0 seek=10G
{noformat}
bq. What version of ATS are you running?
I've just tested this with master's HEAD
(6215bf9e9dc3bf21f9507ce6856891e8168331c2)
bq. What version of apache are you running (is it the same for port 80 and port
443)?
Apache/2.2.22 (Ubuntu) and yes it is the same software listening on both 80 and
443.
bq. What client are you testing with (curl hopefully)?
Yes it is curl v7.22.0. The command is simply
{noformat}
curl -o /dev/null http://localhost:8081/files/testfile10g.bin
{noformat}
bq. You commented "will hang very quickly without getting much data back". Does
this mean it did get some data back? If yes, how much before it stalled?
Below is the curl output. Looks like curl received 44.2M before ATS closed the
connection.
{noformat}
$ curl -o /dev/null http://localhost:8081/jabberc/testfile10g.bin
% Total % Received % Xferd AverageDload AverageUpload TimeTotal
TimeSpent TimeLeft CurrentSpeed
0 10.0G 0 44.2M 0 0 1050k 0 2:46:25
0:00:43 2:45:42 0
curl: (18) transfer closed with 10691019050 bytes remaining to read
{noformat}
bq. Does the transfer hang forever or does it recover and continue with the
transfer?
>From client point of view, it hang for a while before ATS closed the
>connection. I got some diag output from ATS which suggests the connection is
>terminated due to some sort of inactivity timeout; I'm just not sure on which
>side (client or origin) ATS decided there's an inactivity timeout. Snippet of
>diags for terminating client connection looks like below.
{noformat}
[Jan 27 08:29:31.860] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.861] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.861] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.862] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.862] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.863] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.863] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.864] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.864] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.864] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.864] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.865] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.865] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.866] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.866] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.866] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http) [4]
[HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http) [4]
[&HttpSM::state_watch_for_client_abort, VC_EVENT_INACTIVITY_TIMEOUT]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http) [4]
[watch_for_client_abort] forwarding event VC_EVENT_INACTIVITY_TIMEOUT to tunnel
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
consumer_handler [user agent VC_EVENT_INACTIVITY_TIMEOUT]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http) [4]
[&HttpSM::tunnel_handler_ua, VC_EVENT_INACTIVITY_TIMEOUT]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_ss) [4] session
closed
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_cs) [4] session
closed
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_cs) [4] session
destroy
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http) [4]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http) [4]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http_seq)
[HttpSM::update_stats] Logging transaction
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http) [4] deallocating sm
{noformat}
>From what I can see in diags, these two lines repeated many times before the
>inactivity timeout stuff kicks in.
{noformat}
[Jan 27 08:29:31.336] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.337] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
{noformat}
was (Author: thachtran):
Hi Ron,
Thanks for looking into this. My apologies for the late reply.
I can still reproduce with trafficserver's master HEAD in git. I just realised
that the problem description contained some typos which could be the reason why
you couldn't recreate. I corrected it now.
Basically the problem is with a ~10GB file, client <-> ATS is unencrypted, and
ATS <-> origin is SSL-encrypted (http://localhost:8081/files/testfile10g.bin
with the remap above), then I am seeing the download hung on client side and
eventually terminated by ATS. With the same download but ATS <-> origin is
unencrypted (http://localhost:8080/files/testfile10g.bin with the remap above)
then everything seems ok.
Answers to your questions are as follows.
bq. What is the exact size of the testfile10g.bin?
10737418240 bytes = 10GB which I generated using
{noformat}
dd if=/dev/zero of=testfile10g.bin bs=1 count=0 seek=10G
{noformat}
bq. What version of ATS are you running?
I've just tested this with master's HEAD
(6215bf9e9dc3bf21f9507ce6856891e8168331c2)
bq. What version of apache are you running (is it the same for port 80 and port
443)?
Apache/2.2.22 (Ubuntu) and yes it is the same software listening on both 80 and
443.
bq. What client are you testing with (curl hopefully)?
Yes it is curl v7.22.0. The command is simply
{noformat}
curl -o /dev/null http://localhost:8081/files/testfile10g.bin
{noformat}
bq. You commented "will hang very quickly without getting much data back". Does
this mean it did get some data back? If yes, how much before it stalled?
Below is the curl output. Looks like curl received 44.2M before ATS closed the
connection.
{noformat}
$ curl -o /dev/null http://localhost:8081/jabberc/testfile10g.bin
% Total % Received % Xferd AverageDload AverageUpload TimeTotal
TimeSpent TimeLeft CurrentSpeed
0 10.0G 0 44.2M 0 0 1050k 0 2:46:25
0:00:43 2:45:42 0
curl: (18) transfer closed with 10691019050 bytes remaining to read
{noformat}
bq. Does the transfer hang forever or does it recover and continue with the
transfer?
>From client point of view, it hang for a while before ATS closed the
>connection. I got some diag output from ATS which suggests the connection is
>terminated due to some sort of inactivity timeout; I'm just not sure on which
>side (client or origin) ATS decided there's an inactivity timeout. Snippet of
>diags for terminating client connection looks like below.
{noformat}
[Jan 27 08:29:31.860] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.861] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.861] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.862] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.862] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.863] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.863] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.864] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.864] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.864] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.864] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.865] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.865] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.866] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.866] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.866] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http) [4]
[HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http) [4]
[&HttpSM::state_watch_for_client_abort, VC_EVENT_INACTIVITY_TIMEOUT]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http) [4]
[watch_for_client_abort] forwarding event VC_EVENT_INACTIVITY_TIMEOUT to tunnel
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
consumer_handler [user agent VC_EVENT_INACTIVITY_TIMEOUT]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http) [4]
[&HttpSM::tunnel_handler_ua, VC_EVENT_INACTIVITY_TIMEOUT]
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_ss) [4] session
closed
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_cs) [4] session
closed
[Jan 27 08:29:31.867] Server {0x7fda41130700} DEBUG: (http_cs) [4] session
destroy
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http) [4]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http) [4]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http_seq)
[HttpSM::update_stats] Logging transaction
[Jan 27 08:29:38.700] Server {0x7fda41130700} DEBUG: (http) [4] deallocating sm
{noformat}
>From what I can see in diags, these two lines repeated many times before the
>inactivity timeout stuff kicks in.
{noformat}
[Jan 27 08:29:31.336] Server {0x7fda41130700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 27 08:29:31.337] Server {0x7fda41130700} DEBUG: (http_tunnel) [4]
producer_handler [http server VC_EVENT_READ_READY]
{noformat}
> Client connection hang while downloading big file from origin server over SSL
> connection
> ----------------------------------------------------------------------------------------
>
> Key: TS-2306
> URL: https://issues.apache.org/jira/browse/TS-2306
> Project: Traffic Server
> Issue Type: Bug
> Components: Network, SSL
> Reporter: Thach Tran
> Fix For: 4.2.0
>
>
> Setup:
> ATS in reverse proxy mode and Apache server in the backend to serve some very
> large test files (~10GB). Backend Apache server listens on both 80 for plain
> HTTP and 443 for HTTPS. Remap rules for ATS (with two plain HTTP ports of
> 8080 and 8081):
> map http://localhost:8080/ http://localhost/
> map http://localhost:8081/ https://localhost/
> What I am seeing is request for http://localhost:8081/files/testfile10g.bin
> will hang very quickly without getting much data back while request for
> http://localhost:8080/files/testfile10g.bin will continue to download just
> fine until it's finished. I've tried with other smaller files (~200MB, ~1MB)
> and it seems to work fine.
> I've disabled the caching (proxy.config.http.cache.http=0) in case it has
> something to do with that.
> I'm wondering if this is similar to TS-2211 but in reverse direction (client
> is non-SSL while origin connection is SSL). I've tested with trunk which
> includes a fix for TS-2211 but still be able to reproduce this.
> In my test setup both ATS and Apache are running on the same Linux Mint 13
> box (which is effectively Ubuntu 12.04) with OpenSSL version 1.0.1.
> Any help would be much appreciated.
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
