You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@trafficserver.apache.org by "Olsen, Brian (Contractor)" <Br...@comcast.com> on 2019/01/24 15:18:26 UTC
Re: [EXTERNAL] RE: ATS 7.1.5 not caching header Range: bytes=0-
There is also the new “slice” plugin that can be backported. It works similar to nginx’s slice plugin and uses the cache_range_requests to handle the actual parent block fetching and caching. Just need to be careful that you aren’t overwriting the source data as this version (just like the nginx plugin) can’t self heal in case it runs into an etag or last modified mismatch between slice blocks.
From: Evan Zelkowitz <ev...@gmail.com>
Reply-To: "users@trafficserver.apache.org" <us...@trafficserver.apache.org>
Date: Friday, January 18, 2019 at 10:43 AM
To: "users@trafficserver.apache.org" <us...@trafficserver.apache.org>
Subject: [EXTERNAL] RE: ATS 7.1.5 not caching header Range: bytes=0-
Also depending on your use case you can look at the cache range requests plugin which does let you cache ranges, across various parents as well, however this only works if you have strictly defined requests otherwise you’ll pollute your cache. In conjunction with that you can also use the slice plugin which changes range requests into well defined byte boundaries that you can use with cache range requests
Or just background fetch 😊 all depends on what you need
________________________________
From: Miles Libbey <ml...@apache.org>
Sent: Friday, January 18, 2019 10:33:52 AM
To: users@trafficserver.apache.org
Subject: Re: ATS 7.1.5 not caching header Range: bytes=0-
We use the background fetch plugin for this case.
https://docs.trafficserver.apache.org/en/8.0.x/admin-guide/plugins/background_fetch.en.html
ATS can not fill the cache from a range request (but can fulfill range
requests from objects in cache already). So, with the background fetch
plugin, when the range request comes in, ATS fetches the range from
origin, and starts a full GET request to origin in the background.
Then, when the next request comes in, the object may then be in cache
from the plugin's request.
miles
On Fri, Jan 18, 2019 at 9:24 AM ezko <er...@harmonicinc.com> wrote:
>
> Hi,
> we have a standard ATS 7.1.5 reverse proxy setup and we noticed ATS doesn't
> cache anything when we use VLC. we looked at the debug logs (see complete
> logs below). our guess is that the issue is related to the header Range:
> bytes=0-
> we tried: curl -vvv -H "Range: bytes=0-" http://XXXX/seq-55.ts and confirmed
> it's not being cached.
> Is this expected ?
> is there a switch to ignore Range header (like no-cache , max-age or
> authentication) ?
> or can we use header rewrite plugin with REMAP_PSEUDO_HOOK to remove it from
> the client request ?
> Thanks,
> Erez
>
>
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240] State
> Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SERVER_READ
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_redirect)
> is_redirect_required 0
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) Setup Server
> Transfer
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> adding producer 'http server'
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> adding consumer 'user agent'
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> perform_cache_write_action CACHE_DO_NO_ACTION
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel)
> tunnel_run started, p_arg is provided
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_cs)
> tcp_init_cwnd_set 1
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> producer_handler [http server VC_EVENT_READ_READY]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> producer_handler_dechunked [http server VC_EVENT_READ_READY]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_redirect)
> [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> producer_handler [http server VC_EVENT_READ_READY]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> producer_handler_dechunked [http server VC_EVENT_READ_READY]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4096 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4096 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4096 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4096 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4096 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4096 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4096 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4096 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_redirect)
> [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> producer_handler [http server VC_EVENT_READ_READY]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> producer_handler_dechunked [http server VC_EVENT_READ_READY]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_chunk) creating a
> chunk of size 4036 bytes
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_redirect)
> [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> producer_handler [http server VC_EVENT_EOS]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> producer_handler_dechunked [http server VC_EVENT_EOS]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_redirect)
> [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 104
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> [&HttpSM::tunnel_handler_server, VC_EVENT_EOS]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> [HttpSM::tunnel_handler_server] finishing HTTP tunnel
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_ss) [184] session
> closing, netvc 0x2afb600074f8
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_tunnel) [240]
> consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_cs) [213] session
> closed
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_redirect)
> [PostDataBuffers::clear]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240] calling
> plugin on hook TS_HTTP_TXN_CLOSE_HOOK at hook 0x1ecaf40
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_cs) [213] session
> destroy
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_cs)
> tcp_init_cwnd_set 1
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http_seq)
> [HttpSM::update_stats] Logging transaction
> [Jan 18 16:43:15.426] Server {0x2afb18910700} DEBUG: (http) [240]
> deallocating sm
> [Jan 18 16:43:16.323] Server {0x2afb18c16700} DEBUG: (http) probe needs
> data, read..
> [Jan 18 16:43:16.323] Server {0x2afb18c16700} DEBUG: (http_seq)
> [HttpSessionAccept:mainEvent 0x2afc88011e40] accepted connection from
> 10.42.37.125:33744 transport type = 1
> [Jan 18 16:43:16.323] Server {0x2afb18c16700} DEBUG: (http_cs) [214] session
> born, netvc 0x2afc88011e40
> [Jan 18 16:43:16.323] Server {0x2afb18c16700} DEBUG: (http_cs)
> tcp_init_cwnd_set 0
> [Jan 18 16:43:16.323] Server {0x2afb18c16700} DEBUG: (http_cs) [214] data
> already in buffer, starting new transaction
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_txn) [214]
> Starting transaction 1 using sm [241]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [HttpSM::main_handler, VC_EVENT_READ_READY]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] done
> parsing client request header
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> START HttpTransact::ModifyRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans)
> [ink_cluster_time] local: 1547829796, highest_delta: 0, cluster: 1547829796
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241] END
> HttpTransact::ModifyRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> Checking if transaction wants to upgrade
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) Next
> action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] State
> Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] calling
> plugin on hook TS_HTTP_READ_REQUEST_HDR_HOOK at hook 0x1ecafe0
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] calling
> plugin on hook TS_HTTP_READ_REQUEST_HDR_HOOK at hook 0x1ecafc0
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] calling
> plugin on hook TS_HTTP_READ_REQUEST_HDR_HOOK at hook 0x1ecaf80
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] calling
> plugin on hook TS_HTTP_READ_REQUEST_HDR_HOOK at hook 0x1ecaf20
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] calling
> plugin on hook TS_HTTP_READ_REQUEST_HDR_HOOK at hook 0x1ecaf00
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> START HttpTransact::StartRemapRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> Before Remapping:
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) HTTP_HEADER
> 0x2afb2c031088: [T: 3, L: 48, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [TYPE: REQ, V:
> 10001, URL: 0x2afb2c031308, METHOD: "GET", METHOD_LEN: 3, FIELDS:
> 0x2afb2c0310b8]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) URL
> 0x2afb2c031308: [T: 2, L: 112, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [URLTYPE: 1,
> SWKSIDX: 99,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SCHEME: "http",
> SCHEME_LEN: 4,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) USER: "",
> USER_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PASSWORD: "",
> PASSWORD_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) HOST: "",
> HOST_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PORT: "",
> PORT_LEN: 0, PORT_NUM: 0
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PATH:
> "assets/sintel/video/250kbit/seq-38.ts", PATH_LEN: 37,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PARAMS: "",
> PARAMS_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) QUERY: "",
> QUERY_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) FRAGMENT: "",
> FRAGMENT_LEN: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) MIME_HEADER
> 0x2afb2c0310b8: [T: 4, L: 592, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [PBITS: 0x0008040001000800, SLACC: 0xFFFFFFFFFFFFFFF3FFFFFFFFFFF1FFF2,
> HEADBLK: 0x2afb2c0310f8, TAILBLK: 0x2afb2c0310f8]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [CBITS:
> 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$:
> 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) FIELD_BLOCK
> 0x2afb2c0310f8: [T: 5, L: 528, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [FREETOP: 5,
> NEXTBLK: (nil)]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 0
> (0x2afb2c031108), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N: "Host",
> N_LEN: 4, N_IDX: 30,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V:
> "vds-cache.test3.cdn.telkomsel.demo.hvds.tv", V_LEN: 42,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 50, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 1
> (0x2afb2c031128), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N:
> "User-Agent", N_LEN: 10, N_IDX: 64,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V: "VLC/2.2.2
> LibVLC/2.2.2", V_LEN: 22,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 36, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 2
> (0x2afb2c031148), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N: "Range",
> N_LEN: 5, N_IDX: 52,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V: "bytes=0-",
> V_LEN: 8,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 17, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 3
> (0x2afb2c031168), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N:
> "Connection", N_LEN: 10, N_IDX: 12,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V: "close",
> V_LEN: 5,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 19, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 4
> (0x2afb2c031188), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N:
> "Icy-MetaData", N_LEN: 12, N_IDX: -1,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V: "1", V_LEN:
> 1,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 17, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241] END
> HttpTransact::StartRemapRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) Next
> action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] State
> Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> Inside PerformRemap
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) Next
> action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] State
> Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_seq)
> [HttpSM::do_remap_request] Remapping request
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> START HttpTransact::EndRemapRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> EndRemapRequest host is 10.42.37.125
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> After Remapping:
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) HTTP_HEADER
> 0x2afb2c031088: [T: 3, L: 48, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [TYPE: REQ, V:
> 10001, URL: 0x2afb2c031308, METHOD: "GET", METHOD_LEN: 3, FIELDS:
> 0x2afb2c0310b8]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) URL
> 0x2afb2c031308: [T: 2, L: 112, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [URLTYPE: 1,
> SWKSIDX: 99,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SCHEME: "http",
> SCHEME_LEN: 4,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) USER: "",
> USER_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PASSWORD: "",
> PASSWORD_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) HOST:
> "10.42.37.125", HOST_LEN: 12,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PORT: "9999",
> PORT_LEN: 4, PORT_NUM: 9999
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PATH:
> "assets/sintel/video/250kbit/seq-38.ts", PATH_LEN: 37,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PARAMS: "",
> PARAMS_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) QUERY: "",
> QUERY_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) FRAGMENT: "",
> FRAGMENT_LEN: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) MIME_HEADER
> 0x2afb2c0310b8: [T: 4, L: 592, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [PBITS: 0x0008040001000800, SLACC: 0xFFFFFFFFFFFFFFF3FFFFFFFFFFF1FFF2,
> HEADBLK: 0x2afb2c0310f8, TAILBLK: 0x2afb2c0310f8]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [CBITS:
> 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$:
> 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) FIELD_BLOCK
> 0x2afb2c0310f8: [T: 5, L: 528, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [FREETOP: 5,
> NEXTBLK: (nil)]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 0
> (0x2afb2c031108), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N: "Host",
> N_LEN: 4, N_IDX: 30,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V:
> "10.42.37.125:9999", V_LEN: 17,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 0, RAWLEN: 25, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 1
> (0x2afb2c031128), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N:
> "User-Agent", N_LEN: 10, N_IDX: 64,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V: "VLC/2.2.2
> LibVLC/2.2.2", V_LEN: 22,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 36, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 2
> (0x2afb2c031148), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N: "Range",
> N_LEN: 5, N_IDX: 52,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V: "bytes=0-",
> V_LEN: 8,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 17, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 3
> (0x2afb2c031168), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N:
> "Connection", N_LEN: 10, N_IDX: 12,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V: "close",
> V_LEN: 5,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 19, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SLOT # 4
> (0x2afb2c031188), LIVE
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [N:
> "Icy-MetaData", N_LEN: 12, N_IDX: -1,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) V: "1", V_LEN:
> 1,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 17, F: 1]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241] END
> HttpTransact::EndRemapRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) Next
> action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] State
> Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241] calling
> plugin on hook TS_HTTP_POST_REMAP_HOOK at hook 0x1ecaf60
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> START HttpTransact::HandleRequest
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [init_stat_vars_from_req] set req cont length to 0
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [is_request_valid] no request header errors
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http_seq) [241]
> [HttpTransact::HandleRequest] request valid.
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) HTTP_HEADER
> 0x2afb2c031088: [T: 3, L: 48, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [TYPE: REQ, V:
> 10001, URL: 0x2afb2c031308, METHOD: "GET", METHOD_LEN: 3, FIELDS:
> 0x2afb2c0310b8]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) URL
> 0x2afb2c031308: [T: 2, L: 112, OBJFLAGS: 0]
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) [URLTYPE: 1,
> SWKSIDX: 99,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) SCHEME: "http",
> SCHEME_LEN: 4,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) USER: "",
> USER_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PASSWORD: "",
> PASSWORD_LEN: 0,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) HOST:
> "10.42.37.125", HOST_LEN: 12,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PORT: "9999",
> PORT_LEN: 4, PORT_NUM: 9999
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PATH:
> "assets/sintel/video/250kbit/seq-38.ts", PATH_LEN: 37,
> [Jan 18 16:43:16.324] Server {0x2afb18c16700} DEBUG: (http) PARAMS: "",
> PARAMS_LEN: 0,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) QUERY: "",
> QUERY_LEN: 0,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) FRAGMENT: "",
> FRAGMENT_LEN: 0]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) MIME_HEADER
> 0x2afb2c0310b8: [T: 4, L: 592, OBJFLAGS: 0]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http)
> [PBITS: 0x0008040001000800, SLACC: 0xFFFFFFFFFFFFFFF3FFFFFFFFFFF1FFF2,
> HEADBLK: 0x2afb2c0310f8, TAILBLK: 0x2afb2c0310f8]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [CBITS:
> 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$:
> 0]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) FIELD_BLOCK
> 0x2afb2c0310f8: [T: 5, L: 528, OBJFLAGS: 0]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [FREETOP: 5,
> NEXTBLK: (nil)]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) SLOT # 0
> (0x2afb2c031108), LIVE
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [N: "Host",
> N_LEN: 4, N_IDX: 30,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) V:
> "10.42.37.125:9999", V_LEN: 17,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 0, RAWLEN: 25, F: 1]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) SLOT # 1
> (0x2afb2c031128), LIVE
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [N:
> "User-Agent", N_LEN: 10, N_IDX: 64,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) V: "VLC/2.2.2
> LibVLC/2.2.2", V_LEN: 22,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 36, F: 1]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) SLOT # 2
> (0x2afb2c031148), LIVE
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [N: "Range",
> N_LEN: 5, N_IDX: 52,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) V: "bytes=0-",
> V_LEN: 8,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 17, F: 1]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) SLOT # 3
> (0x2afb2c031168), LIVE
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [N:
> "Connection", N_LEN: 10, N_IDX: 12,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) V: "close",
> V_LEN: 5,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 19, F: 1]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http)
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) SLOT # 4
> (0x2afb2c031188), LIVE
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [N:
> "Icy-MetaData", N_LEN: 12, N_IDX: -1,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) V: "1", V_LEN:
> 1,
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) NEXTDUP: (nil),
> RAW: 1, RAWLEN: 17, F: 1]
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http)
> +++++++++ Incoming Request +++++++++
> -- State Machine Id: 241
> GET http://10.42.37.125:9999/assets/sintel/video/250kbit/seq-38.ts HTTP/1.1
> Host: 10.42.37.125:9999
> User-Agent: VLC/2.2.2 LibVLC/2.2.2
> Range: bytes=0-
> Connection: close
> Icy-MetaData: 1
>
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http_trans) Next
> action SM_ACTION_DNS_LOOKUP; OSDNSLookup
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [241] State
> Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_DNS_LOOKUP
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http_seq)
> [HttpSM::do_hostdb_lookup] Doing DNS Lookup
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http_trans)
> [ink_cluster_time] local: 1547829796, highest_delta: 0, cluster: 1547829796
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [HttpTransact::OSDNSLookup] This was attempt 0
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http_seq) [241]
> [HttpTransact::OSDNSLookup] DNS Lookup successful
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [OSDNSLookup] DNS lookup for O.S. successful IP: 10.42.37.125
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http_trans) Next
> action SM_ACTION_DNS_REVERSE_LOOKUP; HttpTransact::StartAccessControl
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http) [241] State
> Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_DNS_REVERSE_LOOKUP
> [Jan 18 16:43:16.325] Server {0x2afb18c16700} DEBUG: (http_seq)
> [HttpSM::do_hostdb_reverse_lookup] Doing reverse DNS Lookup
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> [HttpSM::main_handler, EVENT_HOST_DB_LOOKUP]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> [&HttpSM::state_hostdb_reverse_lookup, EVENT_HOST_DB_LOOKUP]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241] reverse
> DNS lookup failed for '10.42.37.125'
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) Next
> action SM_ACTION_API_OS_DNS; HttpTransact::DecideCacheLookup
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241] State
> Transition: SM_ACTION_DNS_REVERSE_LOOKUP -> SM_ACTION_API_OS_DNS
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> [DecideCacheLookup] Will do cache lookup.
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_seq) [241]
> [DecideCacheLookup] Will do cache lookup
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) Next
> action SM_ACTION_CACHE_LOOKUP; nullptr
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241] State
> Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_CACHE_LOOKUP
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_seq)
> [HttpSM::do_cache_lookup_and_read] [241] Issuing cache lookup for URL
> http://10.42.37.125:9999/assets/sintel/video/250kbit/seq-38.ts
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_cache) [241]
> [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> [HttpSM::main_handler, CACHE_EVENT_OPEN_READ_FAILED]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with ECACHE_NO_DOC (-20400)
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http)
> [state_cache_open_read] open read failed.
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241] calling
> plugin on hook TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK at hook 0x1ecafa0
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241] calling
> plugin on hook TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK at hook 0x1ecaec0
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241]
> [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> [HttpTransact::HandleCacheOpenRead]
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> CacheOpenRead -- miss
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> [HandleCacheOpenReadMiss] --- MISS
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_seq) [241]
> [HttpTransact::HandleCacheOpenReadMiss] Miss in cache
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> get_ka_info_from_config, server_info->http_version 65537, check_hostdb 0
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> client_ip_set = 0
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> inserted request header 'Client-ip: 10.42.37.125'
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> [add_client_ip_to_outgoing_request] Appended connecting client's
> (10.42.37.125) to the X-Forwards header
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> [build_request] removing host name from url
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> [build_request] request not like cacheable and conditional headers not
> removed
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans)
> [ink_cluster_time] local: 1547829796, highest_delta: 0, cluster: 1547829796
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_trans) [241]
> [build_request] request_sent_time: 1547829796
> +++++++++ Proxy's Request +++++++++
> -- State Machine Id: 241
> GET /assets/sintel/video/250kbit/seq-38.ts HTTP/1.1
> Host: 10.42.37.125:9999
> User-Agent: VLC/2.2.2 LibVLC/2.2.2
> Range: bytes=0-
> Icy-MetaData: 1
> Client-ip: 10.42.37.125
> X-Forwarded-For: 10.42.37.125
> Via: http/1.1 vds-cache[8c1882df-0bbf-4201-9f5f-3aa543e95285]
> (ApacheTrafficServer/7.1.5)
>
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http) [241] State
> Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_ORIGIN_SERVER_OPEN
> [Jan 18 16:43:16.328] Server {0x2afb13717700} DEBUG: (http_track) entered
> inside do_http_server_open ][ipv4]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http) [241]
> [HttpSM::main_handler, VC_EVENT_INTERVAL]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_track) entered
> inside state_http_server_open
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_http_server_open, VC_EVENT_INTERVAL]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_track) entered
> inside do_http_server_open ][ipv4]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http) [241] open
> connection to 10.42.37.125: 10.42.37.125:9999
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_seq)
> [HttpSM::do_http_server_open] Sending request to server
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_ss) [acquire
> session] thread pool search successful
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_ss) [150]
> [acquire session] return session from shared pool
> +++++++++ Proxy's Request after hooks +++++++++
> -- State Machine Id: 241
> GET /assets/sintel/video/250kbit/seq-38.ts HTTP/1.1
> Host: 10.42.37.125:9999
> User-Agent: VLC/2.2.2 LibVLC/2.2.2
> Range: bytes=0-
> Icy-MetaData: 1
> Client-ip: 10.42.37.125
> X-Forwarded-For: 10.42.37.125
> Via: http/1.1 vds-cache[8c1882df-0bbf-4201-9f5f-3aa543e95285]
> (ApacheTrafficServer/7.1.5)
>
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http) [241]
> [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http) [241]
> [HttpSM::main_handler, VC_EVENT_READ_READY]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http) [241]
> [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_seq) Done parsing
> server response header
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_redirect)
> [PostDataBuffers::clear]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [HttpTransact::HandleResponse]
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_seq) [241]
> [HttpTransact::HandleResponse] Response received
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_trans)
> [ink_cluster_time] local: 1547829796, highest_delta: 0, cluster: 1547829796
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [HandleResponse] response_received_time: 1547829796
> +++++++++ Incoming O.S. Response +++++++++
> -- State Machine Id: 241
> HTTP/1.1 206 Partial Content
> Server: nginx/1.15.6
> Date: Fri, 18 Jan 2019 16:43:16 GMT
> Content-Type: video/mp2t
> Content-Length: 46060
> Last-Modified: Wed, 19 Dec 2018 11:00:43 GMT
> Connection: keep-alive
> ETag: "5c1a24db-b3ec"
> Content-Range: bytes 0-46059/46060
>
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [is_response_valid] No errors in response
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_seq) [241]
> [HttpTransact::HandleResponse] Response valid
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_hdrs) [241]
> [initialize_state_variables_from_response]Server is keep-alive.
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [handle_response_from_server] (hrfs)
> [Jan 18 16:43:16.328] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [hrfs] connection alive
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [handle_forward_server_connection_open] (hfsco)
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_seq) [241]
> [HttpTransact::handle_server_connection_open]
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http) server info =
> 10.42.37.125:9999
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [hfsco] cache action: CACHE_DO_NO_ACTION
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [handle_no_cache_operation_on_forward_server_response] (hncoofsr)
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_seq) [241]
> [handle_no_cache_operation_on_forward_server_response]
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] age_value: 0
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] date_value: 1547829796
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] response_time: 1547829796
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] now: 1547829796
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] now (fixed): 1547829796
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] apparent_age: 0
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] corrected_received_age: 0
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] response_delay: 0
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] corrected_initial_age: 0
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] resident_time: 0
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_age)
> [calculate_document_age] current_age: 0
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_trans) [241]
> [handle_content_length_header] RESPONSE cont len in hdr is 46060
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_trans) [Squid
> code generation] Hit/Miss: 1, Log: 3, Hier: 2
> [Jan 18 16:43:16.329] Server {0x2afb18c16700} DEBUG: (http_trans) Adding
> Server: ATS/7.1.5
> +++++++++ Base Header for Building Response +++++++++
> -- State Machine Id: 241
> HTTP/1.1 206 Partial Content
> Server: nginx/1.15.6
> Date: Fri, 18 Jan 2019 16:43:16 GMT
> Content-Type: video/mp2t
> Content-Length: 46060
> Last-Modified: Wed, 19 Dec 2018 11:00:43 GMT
> Connection: keep-alive
> ETag: "5c1a24db-b3ec"
> Content-Range: bytes 0-46059/46060
>
> +++++++++ Proxy's Response 2 +++++++++
> -- State Machine Id: 241
> HTTP/1.1 206 Partial Content
> Server: ATS/7.1.5
> Date: Fri, 18 Jan 2019 16:43:16 GMT
> Content-Type: video/mp2t
> Content-Length: 46060
> Last-Modified: Wed, 19 Dec 2018 11:00:43 GMT
> ETag: "5c1a24db-b3ec"
> Content-Range: bytes 0-46059/46060
> Age: 0
> Connection: close
> Via: http/1.1 vds-cache (ApacheTrafficServer/7.1.5 [uScMs f p eN:t cCMi p
> sS])
>
>
>
>
>
> --
> Sent from: http://apache-traffic-server.24303.n7.nabble.com/