Hello Leif,
Thank you for your reply. I appreciate it.
I am attaching the logs to this email. I am sorry I had to clear it a
bit to remove my company specific lines - I hope they were not related.
But the interesting log lines start at 150 to 277 when it is evaluating
the alternates.
And how do I disable the vary on headers? Would I just have to set the
CONFIG proxy.config.http.cache.enable_default_vary_headers INT 1
to
CONFIG proxy.config.http.cache.enable_default_vary_headers INT 0
I will try this and get back to you.
Thank you once again.
Regards,
-Gokce
On 11/04/2011 06:06 PM, Leif Hedstrom wrote:
On 11/4/11 11:44 AM, Gokce Toykuyu wrote:
Hello,
We are trying to utilize TS cache for the responses from our web
service. We seem to have either a configuration issue or an HTTP header
mismatch or..well, we need your help:) basically, in the below
scenario, if I change the Accept: header to include "application/*" or
specifically "application/json" (e.g. Accept: text/*, text/html,
application/json) then it becomes a cache hit on TS and the origin
server is not called. I tried setting the vary headers and alternates
but nothing worked. Unfortunately, we don't have control over the
calling server, which is a middle man between the end user and us, and
it sends the Accept: header in the request but our response is
application/json which gets transmitted through this middle man back to
the caller.
Well, besides that "middle layer" being kinda nutty, why not just turn off
the Vary header in your origin response? Does that not "work" ? I'm not
entirely sure as to why this "breaks" anyways, you are Vary'ing on
Accept-Encoding, which is not the same as "Accept". I'm guessing some logic
here prevents us from accidentally serving out a cache alternate with
certainty that we're doing it right.
-- Leif
[Nov 3 23:33:45.801] Server {4132408208} DEBUG: (http_seq) HttpAccept:mainEvent] accepted connection
[Nov 3 23:33:45.801] Server {4132408208} DEBUG: (http_cs) [307] session born, netvc a0b2658
[Nov 3 23:33:45.801] Server {4132408208} DEBUG: (http_cs) [307] using accept inactivity timeout [120 seconds]
[Nov 3 23:33:45.802] Server {4132408208} DEBUG: (http_cs) [307] Starting transaction 1 using sm [307]
[Nov 3 23:33:45.802] Server {4132408208} DEBUG: (http) [307] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Nov 3 23:33:45.802] Server {4132408208} DEBUG: (http) [307] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Nov 3 23:33:45.802] Server {4132408208} DEBUG: (http) [307] done parsing client request header
[Nov 3 23:33:45.803] Server {4132408208} DEBUG: (http_trans) START HttpTransact::ModifyRequest
[Nov 3 23:33:45.803] Server {4132408208} DEBUG: (http_trans) [ink_cluster_time] local: 1320363225, highest_delta: 0, cluster: 1320363225
[Nov 3 23:33:45.803] Server {4132408208} DEBUG: (http_trans) END HttpTransact::ModifyRequest
[Nov 3 23:33:45.803] Server {4132408208} DEBUG: (http_trans) Next action HTTP_API_READ_REQUEST_PRE_REMAP; HttpTransact::StartRemapRequest
[Nov 3 23:33:45.804] Server {4132408208} DEBUG: (http) [307] State Transition: STATE_UNDEFINED -> HTTP_API_READ_REQUEST_PRE_REMAP
[Nov 3 23:33:45.804] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : HTTP_API_READ_REQUEST_PRE_REMAP
[Nov 3 23:33:45.804] Server {4132408208} DEBUG: (http_trans) START HttpTransact::StartRemapRequest
[Nov 3 23:33:45.804] Server {4132408208} DEBUG: (http_trans) Before Remapping:
[Nov 3 23:33:45.804] Server {4132408208} DEBUG: (http) HTTP_HEADER 0xFFFFFFFFF15BC848: [T: 3, L: 32, OBJFLAGS: 0]
[Nov 3 23:33:45.805] Server {4132408208} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0xFFFFFFFFF15BC9F0, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0xFFFFFFFFF15BC868]
[Nov 3 23:33:45.805] Server {4132408208} DEBUG: (http) URL 0xFFFFFFFFF15BC9F0: [T: 2, L: 72, OBJFLAGS: 0]
[Nov 3 23:33:45.805] Server {4132408208} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 95,
[Nov 3 23:33:45.805] Server {4132408208} DEBUG: (http) SCHEME: "http", SCHEME_LEN: 4,
[Nov 3 23:33:45.806] Server {4132408208} DEBUG: (http) USER: "", USER_LEN: 0,
[Nov 3 23:33:45.806] Server {4132408208} DEBUG: (http) PASSWORD: "", PASSWORD_LEN: 0,
[Nov 3 23:33:45.806] Server {4132408208} DEBUG: (http) HOST: "", HOST_LEN: 0,
[Nov 3 23:33:45.806] Server {4132408208} DEBUG: (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Nov 3 23:33:45.806] Server {4132408208} DEBUG: (http) PATH: "my/url/path", PATH_LEN: 35,
[Nov 3 23:33:45.807] Server {4132408208} DEBUG: (http) PARAMS: "", PARAMS_LEN: 0,
[Nov 3 23:33:45.807] Server {4132408208} DEBUG: (http) QUERY: "ft=json", QUERY_LEN: 7,
[Nov 3 23:33:45.807] Server {4132408208} DEBUG: (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Nov 3 23:33:45.807] Server {4132408208} DEBUG: (http) MIME_HEADER 0xFFFFFFFFF15BC868: [T: 4, L: 392, OBJFLAGS: 0]
[Nov 3 23:33:45.807] Server {4132408208} DEBUG: (http)
[PBITS: 0x0008000001080001, SLACC: 0xFFFFFFFFFFFFFFF3FFFFFFFFFF2FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF0FFFF, HEADBLK: 0xFFFFFFFFF15BC8A0, TAILBLK: 0xFFFFFFFFF15BC8A0]
[Nov 3 23:33:45.808] Server {4132408208} DEBUG: (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Nov 3 23:33:45.808] Server {4132408208} DEBUG: (http) FIELD_BLOCK 0xFFFFFFFFF15BC8A0: [T: 5, L: 332, OBJFLAGS: 0]
[Nov 3 23:33:45.808] Server {4132408208} DEBUG: (http) [FREETOP: 4, NEXTBLK: 0x0]
[Nov 3 23:33:45.809] Server {4132408208} DEBUG: (http) SLOT # 0 (0xFFFFFFFFF15BC8AC), LIVE
[Nov 3 23:33:45.809] Server {4132408208} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 65,
[Nov 3 23:33:45.809] Server {4132408208} DEBUG: (http) V: "curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7", V_LEN: 105,
[Nov 3 23:33:45.809] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 119, F: 1]
[Nov 3 23:33:45.810] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.810] Server {4132408208} DEBUG: (http) SLOT # 1 (0xFFFFFFFFF15BC8C0), LIVE
[Nov 3 23:33:45.810] Server {4132408208} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Nov 3 23:33:45.810] Server {4132408208} DEBUG: (http) V: "xxx.com:4080", V_LEN: 40,
[Nov 3 23:33:45.810] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 48, F: 1]
[Nov 3 23:33:45.811] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.811] Server {4132408208} DEBUG: (http) SLOT # 2 (0xFFFFFFFFF15BC8D4), LIVE
[Nov 3 23:33:45.811] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 91, F: 1]
[Nov 3 23:33:45.812] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.812] Server {4132408208} DEBUG: (http) SLOT # 3 (0xFFFFFFFFF15BC8E8), LIVE
[Nov 3 23:33:45.812] Server {4132408208} DEBUG: (http) [N: "Accept", N_LEN: 6, N_IDX: 0,
[Nov 3 23:33:45.812] Server {4132408208} DEBUG: (http) V: "text/*, text/html", V_LEN: 17,
[Nov 3 23:33:45.812] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 27, F: 1]
[Nov 3 23:33:45.812] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.813] Server {4132408208} DEBUG: (http_trans) END HttpTransact::StartRemapRequest
[Nov 3 23:33:45.813] Server {4132408208} DEBUG: (http_trans) Next action HTTP_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Nov 3 23:33:45.813] Server {4132408208} DEBUG: (http) [307] State Transition: HTTP_API_READ_REQUEST_PRE_REMAP -> HTTP_REMAP_REQUEST
[Nov 3 23:33:45.813] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : HTTP_REMAP_REQUEST
[Nov 3 23:33:45.814] Server {4132408208} DEBUG: (http_seq) [HttpSM::do_remap_request] Remapping request
[Nov 3 23:33:45.814] Server {4132408208} DEBUG: (http_trans) START HttpTransact::EndRemapRequest
[Nov 3 23:33:45.814] Server {4132408208} DEBUG: (http_trans) After Remapping:
[Nov 3 23:33:45.814] Server {4132408208} DEBUG: (http) HTTP_HEADER 0xFFFFFFFFF15BC848: [T: 3, L: 32, OBJFLAGS: 0]
[Nov 3 23:33:45.814] Server {4132408208} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0xFFFFFFFFF15BC9F0, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0xFFFFFFFFF15BC868]
[Nov 3 23:33:45.815] Server {4132408208} DEBUG: (http) URL 0xFFFFFFFFF15BC9F0: [T: 2, L: 72, OBJFLAGS: 0]
[Nov 3 23:33:45.815] Server {4132408208} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 95,
[Nov 3 23:33:45.815] Server {4132408208} DEBUG: (http) SCHEME: "http", SCHEME_LEN: 4,
[Nov 3 23:33:45.815] Server {4132408208} DEBUG: (http) USER: "", USER_LEN: 0,
[Nov 3 23:33:45.815] Server {4132408208} DEBUG: (http) PASSWORD: "", PASSWORD_LEN: 0,
[Nov 3 23:33:45.816] Server {4132408208} DEBUG: (http) HOST: "xxx2.com", HOST_LEN: 28,
[Nov 3 23:33:45.816] Server {4132408208} DEBUG: (http) PORT: "8080", PORT_LEN: 4, PORT_NUM: 8080
[Nov 3 23:33:45.816] Server {4132408208} DEBUG: (http) PATH: "my/url/path", PATH_LEN: 35,
[Nov 3 23:33:45.816] Server {4132408208} DEBUG: (http) PARAMS: "", PARAMS_LEN: 0,
[Nov 3 23:33:45.816] Server {4132408208} DEBUG: (http) QUERY: "ft=json", QUERY_LEN: 7,
[Nov 3 23:33:45.817] Server {4132408208} DEBUG: (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Nov 3 23:33:45.817] Server {4132408208} DEBUG: (http) MIME_HEADER 0xFFFFFFFFF15BC868: [T: 4, L: 392, OBJFLAGS: 0]
[Nov 3 23:33:45.817] Server {4132408208} DEBUG: (http)
[PBITS: 0x0008000001080001, SLACC: 0xFFFFFFFFFFFFFFF3FFFFFFFFFF2FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF0FFFF, HEADBLK: 0xFFFFFFFFF15BC8A0, TAILBLK: 0xFFFFFFFFF15BC8A0]
[Nov 3 23:33:45.818] Server {4132408208} DEBUG: (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Nov 3 23:33:45.818] Server {4132408208} DEBUG: (http) FIELD_BLOCK 0xFFFFFFFFF15BC8A0: [T: 5, L: 332, OBJFLAGS: 0]
[Nov 3 23:33:45.818] Server {4132408208} DEBUG: (http) [FREETOP: 4, NEXTBLK: 0x0]
[Nov 3 23:33:45.818] Server {4132408208} DEBUG: (http) SLOT # 0 (0xFFFFFFFFF15BC8AC), LIVE
[Nov 3 23:33:45.818] Server {4132408208} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 65,
[Nov 3 23:33:45.819] Server {4132408208} DEBUG: (http) V: "curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7", V_LEN: 105,
[Nov 3 23:33:45.819] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 119, F: 1]
[Nov 3 23:33:45.819] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.819] Server {4132408208} DEBUG: (http) SLOT # 1 (0xFFFFFFFFF15BC8C0), LIVE
[Nov 3 23:33:45.820] Server {4132408208} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Nov 3 23:33:45.820] Server {4132408208} DEBUG: (http) V: "xxx2.com:8080", V_LEN: 33,
[Nov 3 23:33:45.820] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 0, RAWLEN: 41, F: 1]
[Nov 3 23:33:45.820] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.820] Server {4132408208} DEBUG: (http) SLOT # 2 (0xFFFFFFFFF15BC8D4), LIVE
[Nov 3 23:33:45.821] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 91, F: 1]
[Nov 3 23:33:45.821] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.821] Server {4132408208} DEBUG: (http) SLOT # 3 (0xFFFFFFFFF15BC8E8), LIVE
[Nov 3 23:33:45.822] Server {4132408208} DEBUG: (http) [N: "Accept", N_LEN: 6, N_IDX: 0,
[Nov 3 23:33:45.822] Server {4132408208} DEBUG: (http) V: "text/*, text/html", V_LEN: 17,
[Nov 3 23:33:45.822] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 27, F: 1]
[Nov 3 23:33:45.822] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.822] Server {4132408208} DEBUG: (http_trans) END HttpTransact::EndRemapRequest
[Nov 3 23:33:45.822] Server {4132408208} DEBUG: (http_trans) Next action HTTP_API_READ_REQUEST_HDR; HttpTransact::HandleRequest
[Nov 3 23:33:45.823] Server {4132408208} DEBUG: (http) [307] State Transition: HTTP_REMAP_REQUEST -> API_READ_REQUEST_HDR
[Nov 3 23:33:45.823] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : API_READ_REQUEST_HDR
[Nov 3 23:33:45.823] Server {4132408208} DEBUG: (http_trans) START HttpTransact/HandleRequest
[Nov 3 23:33:45.823] Server {4132408208} DEBUG: (http_trans) [is_request_valid]no request header errors
[Nov 3 23:33:45.824] Server {4132408208} DEBUG: (http_seq) [HttpTransact::HandleRequest] request valid.
[Nov 3 23:33:45.824] Server {4132408208} DEBUG: (http) HTTP_HEADER 0xFFFFFFFFF15BC848: [T: 3, L: 32, OBJFLAGS: 0]
[Nov 3 23:33:45.824] Server {4132408208} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0xFFFFFFFFF15BC9F0, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0xFFFFFFFFF15BC868]
[Nov 3 23:33:45.824] Server {4132408208} DEBUG: (http) URL 0xFFFFFFFFF15BC9F0: [T: 2, L: 72, OBJFLAGS: 0]
[Nov 3 23:33:45.825] Server {4132408208} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 95,
[Nov 3 23:33:45.825] Server {4132408208} DEBUG: (http) SCHEME: "http", SCHEME_LEN: 4,
[Nov 3 23:33:45.825] Server {4132408208} DEBUG: (http) USER: "", USER_LEN: 0,
[Nov 3 23:33:45.825] Server {4132408208} DEBUG: (http) PASSWORD: "", PASSWORD_LEN: 0,
[Nov 3 23:33:45.825] Server {4132408208} DEBUG: (http) HOST: "xxx2.com", HOST_LEN: 28,
[Nov 3 23:33:45.826] Server {4132408208} DEBUG: (http) PORT: "8080", PORT_LEN: 4, PORT_NUM: 8080
[Nov 3 23:33:45.826] Server {4132408208} DEBUG: (http) PATH: "my/url/path", PATH_LEN: 35,
[Nov 3 23:33:45.826] Server {4132408208} DEBUG: (http) PARAMS: "", PARAMS_LEN: 0,
[Nov 3 23:33:45.826] Server {4132408208} DEBUG: (http) QUERY: "ft=json", QUERY_LEN: 7,
[Nov 3 23:33:45.826] Server {4132408208} DEBUG: (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Nov 3 23:33:45.827] Server {4132408208} DEBUG: (http) MIME_HEADER 0xFFFFFFFFF15BC868: [T: 4, L: 392, OBJFLAGS: 0]
[Nov 3 23:33:45.827] Server {4132408208} DEBUG: (http)
[PBITS: 0x0008000001080001, SLACC: 0xFFFFFFFFFFFFFFF3FFFFFFFFFF2FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF0FFFF, HEADBLK: 0xFFFFFFFFF15BC8A0, TAILBLK: 0xFFFFFFFFF15BC8A0]
[Nov 3 23:33:45.827] Server {4132408208} DEBUG: (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Nov 3 23:33:45.827] Server {4132408208} DEBUG: (http) FIELD_BLOCK 0xFFFFFFFFF15BC8A0: [T: 5, L: 332, OBJFLAGS: 0]
[Nov 3 23:33:45.828] Server {4132408208} DEBUG: (http) [FREETOP: 4, NEXTBLK: 0x0]
[Nov 3 23:33:45.828] Server {4132408208} DEBUG: (http) SLOT # 0 (0xFFFFFFFFF15BC8AC), LIVE
[Nov 3 23:33:45.828] Server {4132408208} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 65,
[Nov 3 23:33:45.828] Server {4132408208} DEBUG: (http) V: "curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7", V_LEN: 105,
[Nov 3 23:33:45.829] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 119, F: 1]
[Nov 3 23:33:45.829] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.829] Server {4132408208} DEBUG: (http) SLOT # 1 (0xFFFFFFFFF15BC8C0), LIVE
[Nov 3 23:33:45.829] Server {4132408208} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Nov 3 23:33:45.829] Server {4132408208} DEBUG: (http) V: "xxx2.com:8080", V_LEN: 33,
[Nov 3 23:33:45.830] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 0, RAWLEN: 41, F: 1]
[Nov 3 23:33:45.830] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.830] Server {4132408208} DEBUG: (http) SLOT # 2 (0xFFFFFFFFF15BC8D4), LIVE
[Nov 3 23:33:45.831] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 91, F: 1]
[Nov 3 23:33:45.831] Server {4132408208} DEBUG: (http)
[Nov 3 23:33:45.831] Server {4132408208} DEBUG: (http) SLOT # 3 (0xFFFFFFFFF15BC8E8), LIVE
[Nov 3 23:33:45.831] Server {4132408208} DEBUG: (http) [N: "Accept", N_LEN: 6, N_IDX: 0,
[Nov 3 23:33:45.831] Server {4132408208} DEBUG: (http) V: "text/*, text/html", V_LEN: 17,
[Nov 3 23:33:45.832] Server {4132408208} DEBUG: (http) NEXTDUP: 0x0, RAW: 1, RAWLEN: 27, F: 1]
[Nov 3 23:33:45.832] Server {4132408208} DEBUG: (http)
+++++++++ Incoming Request +++++++++
-- State Machine Id: 307
GET http://xxx2.com:8080/my/url/path?ft=json HTTP/1.1
User-Agent: curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7
Host: xxx2.com:8080
Accept: text/*, text/html
[Nov 3 23:33:45.833] Server {4132408208} DEBUG: (http_auth) User is authorized
[Nov 3 23:33:45.833] Server {4132408208} DEBUG: (http_trans) [DecideCacheLookup] Will do cache lookup.
[Nov 3 23:33:45.833] Server {4132408208} DEBUG: (http_seq) [DecideCacheLookup] Will do cache lookup
[Nov 3 23:33:45.833] Server {4132408208} DEBUG: (http_trans) Next action CACHE_LOOKUP; NULL
[Nov 3 23:33:45.834] Server {4132408208} DEBUG: (http) [307] State Transition: API_READ_REQUEST_HDR -> CACHE_LOOKUP
[Nov 3 23:33:45.834] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : CACHE_LOOKUP
[Nov 3 23:33:45.834] Server {4132408208} DEBUG: (http_seq) [HttpSM::do_cache_lookup_and_read] Issuing cache lookup
[Nov 3 23:33:45.834] Server {4132408208} DEBUG: (http_match) [SelectFromAlternates] # alternates = 3
[Nov 3 23:33:45.835] Server {4132408208} DEBUG: (http_seq) [SelectFromAlternates] 3 alternates for this cached doc
[alts] There are 3 alternates for this request header.
[Nov 3 23:33:45.835] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: Accept match = -1
[Nov 3 23:33:45.835] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: Accept match = -1
[Nov 3 23:33:45.835] Server {4132408208} DEBUG: (http_alternate) Content-Type and Accept -1.000000
[Nov 3 23:33:45.835] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptCharset match = -2
[Nov 3 23:33:45.836] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptCharset match = -2
[Nov 3 23:33:45.836] Server {4132408208} DEBUG: (http_alternate) Content-Type and Accept-Charset -2.000000
[Nov 3 23:33:45.836] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptEncoding match = -2
[Nov 3 23:33:45.836] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptEncoding match = -2
[Nov 3 23:33:45.837] Server {4132408208} DEBUG: (http_alternate) Content-Encoding and Accept-Encoding -2.000000
[Nov 3 23:33:45.837] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptLanguage match = -2
[Nov 3 23:33:45.837] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptLanguage match = -2
[Nov 3 23:33:45.837] Server {4132408208} DEBUG: (http_alternate) Content-Language and Accept-Language -2.000000
[Nov 3 23:33:45.837] Server {4132408208} DEBUG: (http_alternate) Mult's Quality Factor: -1.000000
[Nov 3 23:33:45.838] Server {4132408208} DEBUG: (http_alternate) ----------End of Alternate----------
[Nov 3 23:33:45.838] Server {4132408208} DEBUG: (http_trans) [ink_cluster_time] local: 1320363225, highest_delta: 0, cluster: 1320363225
[Nov 3 23:33:45.838] Server {4132408208} DEBUG: (http_age) [calculate_document_age] age_value: 0
[Nov 3 23:33:45.838] Server {4132408208} DEBUG: (http_age) [calculate_document_age] date_value: 1320362980
[Nov 3 23:33:45.839] Server {4132408208} DEBUG: (http_age) [calculate_document_age] response_time: 1320362980
[Nov 3 23:33:45.839] Server {4132408208} DEBUG: (http_age) [calculate_document_age] now: 1320363225
[Nov 3 23:33:45.839] Server {4132408208} DEBUG: (http_age) [calculate_document_age] now (fixed): 1320363225
[Nov 3 23:33:45.839] Server {4132408208} DEBUG: (http_age) [calculate_document_age] apparent_age: 0
[Nov 3 23:33:45.839] Server {4132408208} DEBUG: (http_age) [calculate_document_age] corrected_received_age: 0
[Nov 3 23:33:45.840] Server {4132408208} DEBUG: (http_age) [calculate_document_age] response_delay: 0
[Nov 3 23:33:45.840] Server {4132408208} DEBUG: (http_age) [calculate_document_age] corrected_initial_age: 0
[Nov 3 23:33:45.840] Server {4132408208} DEBUG: (http_age) [calculate_document_age] resident_time: 245
[Nov 3 23:33:45.840] Server {4132408208} DEBUG: (http_age) [calculate_document_age] current_age: 245
[alts] ---- alternate #1 (Q = -1) has these request/response hdrs:
GET http://xxx2.com:8080/my/url/path?ft=json HTTP/1.1
User-Agent: curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7
Host: xxx2.com:8080
Accept: text/*, text/html
HTTP/1.1 200 OK
Date: Thu, 03 Nov 2011 23:29:40 GMT
Content-Length: 1003
Cache-Control: public,max-age=264
Vary: Accept-Encoding
Connection: close
Content-Type: application/json; charset=UTF-8
[Nov 3 23:33:45.842] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: Accept match = -1
[Nov 3 23:33:45.842] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: Accept match = -1
[Nov 3 23:33:45.843] Server {4132408208} DEBUG: (http_alternate) Content-Type and Accept -1.000000
[Nov 3 23:33:45.843] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptCharset match = -2
[Nov 3 23:33:45.843] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptCharset match = -2
[Nov 3 23:33:45.843] Server {4132408208} DEBUG: (http_alternate) Content-Type and Accept-Charset -2.000000
[Nov 3 23:33:45.844] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptEncoding match = -2
[Nov 3 23:33:45.844] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptEncoding match = -2
[Nov 3 23:33:45.844] Server {4132408208} DEBUG: (http_alternate) Content-Encoding and Accept-Encoding -2.000000
[Nov 3 23:33:45.844] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptLanguage match = -2
[Nov 3 23:33:45.844] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptLanguage match = -2
[Nov 3 23:33:45.845] Server {4132408208} DEBUG: (http_alternate) Content-Language and Accept-Language -2.000000
[Nov 3 23:33:45.845] Server {4132408208} DEBUG: (http_alternate) Mult's Quality Factor: -1.000000
[Nov 3 23:33:45.845] Server {4132408208} DEBUG: (http_alternate) ----------End of Alternate----------
[Nov 3 23:33:45.845] Server {4132408208} DEBUG: (http_age) [calculate_document_age] age_value: 0
[Nov 3 23:33:45.846] Server {4132408208} DEBUG: (http_age) [calculate_document_age] date_value: 1320362989
[Nov 3 23:33:45.846] Server {4132408208} DEBUG: (http_age) [calculate_document_age] response_time: 1320362989
[Nov 3 23:33:45.846] Server {4132408208} DEBUG: (http_age) [calculate_document_age] now: 1320363225
[Nov 3 23:33:45.846] Server {4132408208} DEBUG: (http_age) [calculate_document_age] now (fixed): 1320363225
[Nov 3 23:33:45.847] Server {4132408208} DEBUG: (http_age) [calculate_document_age] apparent_age: 0
[Nov 3 23:33:45.847] Server {4132408208} DEBUG: (http_age) [calculate_document_age] corrected_received_age: 0
[Nov 3 23:33:45.847] Server {4132408208} DEBUG: (http_age) [calculate_document_age] response_delay: 0
[Nov 3 23:33:45.847] Server {4132408208} DEBUG: (http_age) [calculate_document_age] corrected_initial_age: 0
[Nov 3 23:33:45.847] Server {4132408208} DEBUG: (http_age) [calculate_document_age] resident_time: 236
[Nov 3 23:33:45.848] Server {4132408208} DEBUG: (http_age) [calculate_document_age] current_age: 236
[alts] ---- alternate #2 (Q = -1) has these request/response hdrs:
GET http://xxx2.com:8080/my/url/path?ft=json HTTP/1.1
User-Agent: curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7
Host: xxx2.com:8080
Accept: text/*, text/html
HTTP/1.1 200 OK
Date: Thu, 03 Nov 2011 23:29:49 GMT
Content-Length: 1003
Cache-Control: public,max-age=255
Vary: Accept-Encoding
Connection: close
Content-Type: application/json; charset=UTF-8
[Nov 3 23:33:45.850] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: Accept match = -1
[Nov 3 23:33:45.850] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: Accept match = -1
[Nov 3 23:33:45.850] Server {4132408208} DEBUG: (http_alternate) Content-Type and Accept -1.000000
[Nov 3 23:33:45.850] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptCharset match = -2
[Nov 3 23:33:45.850] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptCharset match = -2
[Nov 3 23:33:45.851] Server {4132408208} DEBUG: (http_alternate) Content-Type and Accept-Charset -2.000000
[Nov 3 23:33:45.851] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptEncoding match = -2
[Nov 3 23:33:45.851] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptEncoding match = -2
[Nov 3 23:33:45.851] Server {4132408208} DEBUG: (http_alternate) Content-Encoding and Accept-Encoding -2.000000
[Nov 3 23:33:45.852] Server {4132408208} DEBUG: (http_match) CalcQualityOfMatch: AcceptLanguage match = -2
[Nov 3 23:33:45.852] Server {4132408208} DEBUG: (http_seq) CalcQualityOfMatch: AcceptLanguage match = -2
[Nov 3 23:33:45.852] Server {4132408208} DEBUG: (http_alternate) Content-Language and Accept-Language -2.000000
[Nov 3 23:33:45.852] Server {4132408208} DEBUG: (http_alternate) Mult's Quality Factor: -1.000000
[Nov 3 23:33:45.852] Server {4132408208} DEBUG: (http_alternate) ----------End of Alternate----------
[Nov 3 23:33:45.853] Server {4132408208} DEBUG: (http_age) [calculate_document_age] age_value: 0
[Nov 3 23:33:45.853] Server {4132408208} DEBUG: (http_age) [calculate_document_age] date_value: 1320363106
[Nov 3 23:33:45.853] Server {4132408208} DEBUG: (http_age) [calculate_document_age] response_time: 1320363107
[Nov 3 23:33:45.853] Server {4132408208} DEBUG: (http_age) [calculate_document_age] now: 1320363225
[Nov 3 23:33:45.854] Server {4132408208} DEBUG: (http_age) [calculate_document_age] now (fixed): 1320363225
[Nov 3 23:33:45.854] Server {4132408208} DEBUG: (http_age) [calculate_document_age] apparent_age: 1
[Nov 3 23:33:45.854] Server {4132408208} DEBUG: (http_age) [calculate_document_age] corrected_received_age: 1
[Nov 3 23:33:45.854] Server {4132408208} DEBUG: (http_age) [calculate_document_age] response_delay: 1
[Nov 3 23:33:45.854] Server {4132408208} DEBUG: (http_age) [calculate_document_age] corrected_initial_age: 2
[Nov 3 23:33:45.855] Server {4132408208} DEBUG: (http_age) [calculate_document_age] resident_time: 118
[Nov 3 23:33:45.855] Server {4132408208} DEBUG: (http_age) [calculate_document_age] current_age: 120
[alts] ---- alternate #3 (Q = -1) has these request/response hdrs:
GET http://xxx2.com:8080/my/url/path?ft=json HTTP/1.1
User-Agent: curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7
Host: xxx2.com:8080
Accept: text/*, text/html
HTTP/1.1 200 OK
Date: Thu, 03 Nov 2011 23:31:46 GMT
Content-Length: 1003
Cache-Control: public,max-age=137
Vary: Accept-Encoding
Connection: close
Content-Type: application/json; charset=UTF-8
[Nov 3 23:33:45.857] Server {4132408208} DEBUG: (http_seq) [SelectFromAlternates] Chosen alternate # 2
[alts] and the winner is alternate number 3
[Nov 3 23:33:45.857] Server {4132408208} DEBUG: (http_cache) [307] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Nov 3 23:33:45.857] Server {4132408208} DEBUG: (http) [307] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ_FAILED]
[Nov 3 23:33:45.857] Server {4132408208} DEBUG: (http) [307] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Nov 3 23:33:45.858] Server {4132408208} DEBUG: (http) [307] cache_open_read - CACHE_EVENT_OPEN_READ_FAILED
[Nov 3 23:33:45.858] Server {4132408208} DEBUG: (http) [state_cache_open_read] open read failed.
[Nov 3 23:33:45.858] Server {4132408208} DEBUG: (http_trans) [HttpTransact::HandleCacheOpenRead]
[Nov 3 23:33:45.858] Server {4132408208} DEBUG: (http_trans) CacheOpenRead -- miss
[Nov 3 23:33:45.859] Server {4132408208} DEBUG: (http_trans) Next action DNS_LOOKUP; OSDNSLookup
[Nov 3 23:33:45.859] Server {4132408208} DEBUG: (http) [307] State Transition: CACHE_LOOKUP -> DNS_LOOKUP
[Nov 3 23:33:45.859] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : DNS_LOOKUP
[Nov 3 23:33:45.859] Server {4132408208} DEBUG: (http_seq) [HttpStateMachineGet::do_hostdb_lookup] Doing DNS Lookup
[Nov 3 23:33:45.859] Server {4132408208} DEBUG: (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1
[Nov 3 23:33:45.860] Server {4132408208} DEBUG: (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful
[Nov 3 23:33:45.860] Server {4132408208} DEBUG: (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP: 98.137.154.59
[Nov 3 23:33:45.860] Server {4132408208} DEBUG: (http_trans) Next action HttpTransact::HTTP_API_OS_DNS; HandleCacheOpenReadMiss
[Nov 3 23:33:45.860] Server {4132408208} DEBUG: (http) [307] State Transition: DNS_LOOKUP -> API_OS_DNS
[Nov 3 23:33:45.860] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : API_OS_DNS
[Nov 3 23:33:45.861] Server {4132408208} DEBUG: (http_trans) [HandleCacheOpenReadMiss] --- MISS
[Nov 3 23:33:45.861] Server {4132408208} DEBUG: (http_seq) [HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Nov 3 23:33:45.862] Server {4132408208} DEBUG: (http_trans) [build_request] request like cacheable and conditional headers removed
[Nov 3 23:33:45.862] Server {4132408208} DEBUG: (http_trans) [ink_cluster_time] local: 1320363225, highest_delta: 0, cluster: 1320363225
[Nov 3 23:33:45.862] Server {4132408208} DEBUG: (http_trans) [build_request] request_sent_time: 1320363225
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 307
GET /my/url/path?ft=json HTTP/1.1
User-Agent: curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7
Host: xxx2.com:8080
Accept: text/*, text/html
Via: HTTP/1.1 xxx2.com[62899A3B] (TrafficServer/1.19.8 [uScM])
[Nov 3 23:33:45.864] Server {4132408208} DEBUG: (http) [307] State Transition: API_OS_DNS -> CACHE_ISSUE_WRITE
[Nov 3 23:33:45.864] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : CACHE_ISSUE_WRITE
[Nov 3 23:33:45.864] Server {4132408208} DEBUG: (http_cache_write) [307] writing to cache with URL http://xxx2.com:8080/my/url/path?ft=json
[Nov 3 23:33:45.864] Server {4132408208} DEBUG: (http_cache) [307] [&HttpCacheSM::state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Nov 3 23:33:45.865] Server {4132408208} DEBUG: (http) [307] [HttpSM::main_handler, CACHE_EVENT_OPEN_WRITE]
[Nov 3 23:33:45.865] Server {4132408208} DEBUG: (http) [307] [&HttpSM:state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Nov 3 23:33:45.865] Server {4132408208} DEBUG: (http_trans) Next action next; NULL
[Nov 3 23:33:45.865] Server {4132408208} DEBUG: (http) [307] State Transition: CACHE_ISSUE_WRITE -> ORIGIN_SERVER_OPEN
[Nov 3 23:33:45.865] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : ORIGIN_SERVER_OPEN
[Nov 3 23:33:45.866] Server {4132408208} DEBUG: (http_track) entered inside do_http_server_open
[Nov 3 23:33:45.866] Server {4132408208} DEBUG: (http) [307] open connection to xxx2.com: 98.137.154.59
[Nov 3 23:33:45.866] Server {4132408208} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Nov 3 23:33:45.866] Server {4132408208} DEBUG: (http) calling netProcessor.connect_re
[Nov 3 23:33:45.867] Server {4132408208} DEBUG: (http) [307] [HttpSM::main_handler, NET_EVENT_OPEN]
[Nov 3 23:33:45.867] Server {4132408208} DEBUG: (http_track) entered inside state_http_server_open
[Nov 3 23:33:45.867] Server {4132408208} DEBUG: (http) [307] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
[Nov 3 23:33:45.867] Server {4132408208} DEBUG: (http_ss) [316] session born, netvc a0b31f8
[Nov 3 23:33:45.867] Server {4132408208} DEBUG: (http) [307] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Nov 3 23:33:45.868] Server {4132408208} DEBUG: (http) [307] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Nov 3 23:33:45.986] Server {4132408208} DEBUG: (http) [307] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Nov 3 23:33:45.986] Server {4132408208} DEBUG: (http) [307] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY]
[Nov 3 23:33:45.986] Server {4132408208} DEBUG: (http_seq) Done parsing server response header
[Nov 3 23:33:45.986] Server {4132408208} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers]
[Nov 3 23:33:45.987] Server {4132408208} DEBUG: (http_trans) [HttpTransact::HandleResponse]
[Nov 3 23:33:45.987] Server {4132408208} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received
[Nov 3 23:33:45.987] Server {4132408208} DEBUG: (http_trans) [ink_cluster_time] local: 1320363225, highest_delta: 0, cluster: 1320363225
[Nov 3 23:33:45.987] Server {4132408208} DEBUG: (http_trans) [HandleResponse] response_received_time: 1320363225
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 307
HTTP/1.1 200 OK
Date: Thu, 03 Nov 2011 23:33:45 GMT
Content-Length: 1003
Cache-Control: public,max-age=65
Vary: Accept-Encoding
Connection: close
Content-Type: application/json; charset=UTF-8
[Nov 3 23:33:45.988] Server {4132408208} DEBUG: (http_trans) [is_response_valid] No errors in response
[Nov 3 23:33:45.989] Server {4132408208} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response valid
[Nov 3 23:33:45.989] Server {4132408208} DEBUG: (http_trans) [handle_response_from_server] (hrfs)
[Nov 3 23:33:45.989] Server {4132408208} DEBUG: (http_trans) [hrfs] connection alive
[Nov 3 23:33:45.989] Server {4132408208} DEBUG: (http_trans) [handle_forward_server_connection_open] (hfsco)
[Nov 3 23:33:45.989] Server {4132408208} DEBUG: (http_seq) [HttpTransact::handle_server_connection_open]
[Nov 3 23:33:45.990] Server {4132408208} DEBUG: (http_trans) [hfsco] cache action: CACHE_DO_WRITE
[Nov 3 23:33:45.990] Server {4132408208} DEBUG: (http_trans) [handle_cache_operation_on_forward_server_response] (hcoofsr)
[Nov 3 23:33:45.990] Server {4132408208} DEBUG: (http_seq) [handle_cache_operation_on_forward_server_response]
[Nov 3 23:33:45.990] Server {4132408208} DEBUG: (http_trans) [is_response_cacheable] client permits storing
[Nov 3 23:33:45.991] Server {4132408208} DEBUG: (http_trans) [is_response_cacheable] YES by response cache control
[Nov 3 23:33:45.991] Server {4132408208} DEBUG: (http_trans) [hcoofsr] response cacheable
[Nov 3 23:33:45.991] Server {4132408208} DEBUG: (http_trans) [hcoofsr] response code: 200
[Nov 3 23:33:45.991] Server {4132408208} DEBUG: (http_trans) [hcoofsr] cache write
+++++++++ Cached Request Hdr +++++++++
-- State Machine Id: 307
GET http://xxx2.com:8080/my/url/path?ft=json HTTP/1.1
User-Agent: curl/7.21.2 (x86_64-unknown-linux-gnu) libcurl/7.21.2 OpenSSL/1.0.0c zlib/1.2.5 libidn/1.15 libssh2/1.2.7
Host: xxx2.com:8080
Accept: text/*, text/html
[Nov 3 23:33:45.992] Server {4132408208} DEBUG: (http_age) [calculate_document_age] age_value: 0
[Nov 3 23:33:45.993] Server {4132408208} DEBUG: (http_age) [calculate_document_age] date_value: 1320363225
[Nov 3 23:33:45.993] Server {4132408208} DEBUG: (http_age) [calculate_document_age] response_time: 1320363225
[Nov 3 23:33:45.993] Server {4132408208} DEBUG: (http_age) [calculate_document_age] now: 1320363225
[Nov 3 23:33:45.993] Server {4132408208} DEBUG: (http_age) [calculate_document_age] now (fixed): 1320363225
[Nov 3 23:33:45.994] Server {4132408208} DEBUG: (http_age) [calculate_document_age] apparent_age: 0
[Nov 3 23:33:45.994] Server {4132408208} DEBUG: (http_age) [calculate_document_age] corrected_received_age: 0
[Nov 3 23:33:45.994] Server {4132408208} DEBUG: (http_age) [calculate_document_age] response_delay: 0
[Nov 3 23:33:45.994] Server {4132408208} DEBUG: (http_age) [calculate_document_age] corrected_initial_age: 0
[Nov 3 23:33:45.994] Server {4132408208} DEBUG: (http_age) [calculate_document_age] resident_time: 0
[Nov 3 23:33:45.995] Server {4132408208} DEBUG: (http_age) [calculate_document_age] current_age: 0
[Nov 3 23:33:45.995] Server {4132408208} DEBUG: (http_trans) [WUTS code generation] Hit/Miss: 49, Log: 51, Hier: 50, Status: 200
[Nov 3 23:33:45.995] Server {4132408208} DEBUG: (http_trans) Adding Server: TS/1.19.8
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 307
HTTP/1.1 200 OK
Date: Thu, 03 Nov 2011 23:33:45 GMT
Content-Length: 1003
Cache-Control: public,max-age=65
Vary: Accept-Encoding
Connection: close
Content-Type: application/json; charset=UTF-8
+++++++++ Proxy's Response +++++++++
-- State Machine Id: 307
HTTP/1.1 200 OK
Date: Thu, 03 Nov 2011 23:33:45 GMT
Content-Length: 1003
Cache-Control: public,max-age=65
Vary: Accept-Encoding
Content-Type: application/json; charset=UTF-8
Age: 0
Transfer-Encoding: chunked
Connection: keep-alive
Via: HTTP/1.1 xxx2.com (TrafficServer/1.19.8 [cMsSfW])
Server: TS/1.19.8
[Nov 3 23:33:45.997] Server {4132408208} DEBUG: (http) [307] State Transition: ORIGIN_SERVER_OPEN -> SERVER_READ
[Nov 3 23:33:45.998] Server {4132408208} DEBUG: (http) HttpSM::set_next_state to : SERVER_READ
[Nov 3 23:33:45.998] Server {4132408208} DEBUG: (http_redirect) [HttpSM::do_redirect]
[Nov 3 23:33:45.998] Server {4132408208} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers]
[Nov 3 23:33:45.998] Server {4132408208} DEBUG: (http_tunnel) [307] adding producer 'http server'
[Nov 3 23:33:45.999] Server {4132408208} DEBUG: (http_tunnel) [307] adding consumer 'user agent'
[Nov 3 23:33:45.999] Server {4132408208} DEBUG: (http) [307] perform_cache_write_action CACHE_DO_WRITE
[Nov 3 23:33:45.999] Server {4132408208} DEBUG: (http_tunnel) [307] adding consumer 'cache write'
[Nov 3 23:33:45.999] Server {4132408208} DEBUG: (http_tunnel) [307] producer_handler [http server VC_EVENT_READ_READY]
[Nov 3 23:33:45.999] Server {4132408208} DEBUG: (http_tunnel) [307] producer_handler_dechunked [http server VC_EVENT_READ_READY]
[Nov 3 23:33:46.000] Server {4132408208} DEBUG: (http_chunk) creating a chunk of size 1003 bytes
[Nov 3 23:33:46.000] Server {4132408208} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: 0 event: 100
[Nov 3 23:33:46.000] Server {4132408208} DEBUG: (http_tunnel) [307] consumer_handler [user agent VC_EVENT_WRITE_READY]
[Nov 3 23:33:46.001] Server {4132408208} DEBUG: (http_tunnel) [307] consumer_handler [cache write VC_EVENT_WRITE_READY]
[Nov 3 23:33:46.001] Server {4132408208} DEBUG: (http_tunnel) [307] producer_handler [http server VC_EVENT_EOS]
[Nov 3 23:33:46.001] Server {4132408208} DEBUG: (http_tunnel) [307] producer_handler_dechunked [http server VC_EVENT_EOS]
[Nov 3 23:33:46.001] Server {4132408208} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: 0 event: 104
[Nov 3 23:33:46.002] Server {4132408208} DEBUG: (http) [307] [&HttpSM::tunnel_handler_server, VC_EVENT_EOS]
[Nov 3 23:33:46.002] Server {4132408208} DEBUG: (http_tunnel) [307] consumer_handler [cache write VC_EVENT_WRITE_COMPLETE]
[Nov 3 23:33:46.002] Server {4132408208} DEBUG: (http) [307] [&HttpSM::tunnel_handler_cache_write, VC_EVENT_WRITE_COMPLETE]
[Nov 3 23:33:46.003] Server {4132408208} DEBUG: (http_ss) [316] session closed
[Nov 3 23:33:46.003] Server {4132408208} DEBUG: (http_tunnel) [307] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Nov 3 23:33:46.003] Server {4132408208} DEBUG: (http) [307] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Nov 3 23:33:46.004] Server {4132408208} DEBUG: (http_cs) [307] session released by sm [307]
[Nov 3 23:33:46.004] Server {4132408208} DEBUG: (http_cs) [307] initiating io for next header
[Nov 3 23:33:46.004] Server {4132408208} DEBUG: (http) [307] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Nov 3 23:33:46.004] Server {4132408208} DEBUG: (http) [307] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Nov 3 23:33:46.004] Server {4132408208} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers]
[Nov 3 23:33:46.005] Server {4132408208} DEBUG: (http_seq) [HttpStateMachineGet::update_stats] Logging transaction
[Nov 3 23:33:46.005] Server {4132408208} DEBUG: (http) [update_stats] os_read_time=136500000, 1320363225985611000, 1320363226002394000
[Nov 3 23:33:46.006] Server {4132408208} DEBUG: (http) cache_lookup_time=23561000, os_read_time=136500000
[Nov 3 23:33:46.006] Server {4132408208} DEBUG: (http) cache_bytes=0, origin_server_bytes=1420
[Nov 3 23:33:46.006] Server {4132408208} DEBUG: (http) [307] dellocating sm
[Nov 3 23:33:46.006] Server {4132408208} DEBUG: (http_cs) [307] [&HttpClientSession::state_keep_alive, VC_EVENT_EOS]
[Nov 3 23:33:46.006] Server {4132408208} DEBUG: (http_cs) [307] session closed
[Nov 3 23:33:46.007] Server {4132408208} DEBUG: (http_cs) [307] session destroy
