You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@trafficserver.apache.org by ezko <er...@harmonicinc.com> on 2019/01/18 17:24:05 UTC
ATS 7.1.5 not caching header Range: bytes=0-
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/
Re: ATS 7.1.5 not caching header Range: bytes=0-
Posted by ezko <er...@harmonicinc.com>.
thanks,
but we don't need to handle range requests.
we are using HLS with small file segments.
we just want to ignore the header so it doesn't prevent ATS from caching.
thank,
erez
--
Sent from: http://apache-traffic-server.24303.n7.nabble.com/
RE: ATS 7.1.5 not caching header Range: bytes=0-
Posted by Evan Zelkowitz <ev...@gmail.com>.
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/
Re: ATS 7.1.5 not caching header Range: bytes=0-
Posted by Miles Libbey <ml...@apache.org>.
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/