TSFetchUrl takes an address but does the DNS lookup anyway
----------------------------------------------------------
Key: TS-1054
URL: https://issues.apache.org/jira/browse/TS-1054
Project: Traffic Server
Issue Type: Bug
Components: Performance
Affects Versions: 3.0.2
Reporter: James Peach
Priority: Minor
TSFetchUrl() takes an IP address as one of its arguments, so the API client has
to resolve the hostname portion of any URL it wants to fetch. However once you
get into the HTTP state machine, the host gets resolved again. One of these DNS
queries is redundant for performance reasons. Additionally, the plugin might
have some special knowledge about which IP address to use that the DNS resolver
doesn't, in which case the result would be wrong.
[Dec 14 20:36:29.414] Server {0x7fff7b5f9960} DIAG: (plugin) [1] http request
(90 of 90 bytes):
GET http://www.iana.org//_css/2011.1/fonts/OpenSans-SemiBold.ttf HTTP/1.1
accept: */*
[Dec 14 20:36:29.415] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [init] FetchSM
initialized for request with headers
--
GET http://www.iana.org//_css/2011.1/fonts/OpenSans-SemiBold.ttf HTTP/1.1
accept: */*
--
[Dec 14 20:36:29.424] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [httpConnect]
calling httpconnect write
[Dec 14 20:36:29.424] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Created
PluginVCCore at 0x102872c00, active 0x102872c38, passive 0x102872e10
[Dec 14 20:36:29.424] Server {0x7fff7b5f9960} DEBUG: (http_seq)
HttpAccept:mainEvent] accepted connection
[Dec 14 20:36:29.425] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0] session
born, netvc 0x102872e10
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0] using accept
inactivity timeout [120 seconds]
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0] Starting
transaction 1 using sm [0]
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
do_io_read for 0 bytes
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
do_io_read for -1 bytes
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
do_io_read for -1 bytes
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
do_io_write for 90 bytes
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc_event) [0] Passive:
Received event 1
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side; act_on 0
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive: closed?
0 shutdown? 0
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc_event) [0] Active:
Received event 1
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_read_side
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_read_side; act_on 0
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active: closed?
0 shutdown? 0
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_write_side
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_write_side; act_on 90
[Dec 14 20:36:29.436] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_write_side; added 90
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_write] calling process write
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side; act_on 90
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side; added 90
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, VC_EVENT_READ_READY]
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) [0] done parsing
client request header
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
reenable Read
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http_trans) START
HttpTransact::ModifyRequest
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[ink_cluster_time] local: 1323923789, highest_delta: 0, cluster: 1323923789
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http_trans) END
HttpTransact::ModifyRequest
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http_trans) Next action
HTTP_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: STATE_UNDEFINED -> API_READ_REQUEST_HDR
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http_trans) START
HttpTransact::StartRemapRequest
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http_trans) Before
Remapping:
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) HTTP_HEADER
0x12F2888: [T: 3, L: 48, OBJFLAGS: 0]
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) [TYPE: REQ, V:
10001, URL: 0x12F2B08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x12F28B8]
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) URL 0x12F2B08: [T:
2, L: 112, OBJFLAGS: 0]
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) [URLTYPE: 1,
SWKSIDX: 94,
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) SCHEME: "http",
SCHEME_LEN: 4,
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) USER: "",
USER_LEN: 0,
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) PASSWORD: "",
PASSWORD_LEN: 0,
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) HOST:
"www.iana.org", HOST_LEN: 12,
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) PORT: "",
PORT_LEN: 0, PORT_NUM: 0
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) PATH:
"/_css/2011.1/fonts/OpenSans-SemiBold.ttf", PATH_LEN: 40,
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) PARAMS: "",
PARAMS_LEN: 0,
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) QUERY: "",
QUERY_LEN: 0,
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) FRAGMENT: "",
FRAGMENT_LEN: 0]
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http) MIME_HEADER
0x12F28B8: [T: 4, L: 592, OBJFLAGS: 0]
[Dec 14 20:36:29.437] Server {0x7fff7b5f9960} DEBUG: (http)
[PBITS: 0x0000000001000001, SLACC: 0xFFFFFFF0FFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x12F28F8, TAILBLK: 0x12F28F8]
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) [CBITS:
0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) FIELD_BLOCK
0x12F28F8: [T: 5, L: 528, OBJFLAGS: 0]
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) [FREETOP: 2,
NEXTBLK: 0x0]
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) SLOT # 0
(0x12F2908), LIVE
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) [N: "accept",
N_LEN: 6, N_IDX: 4,
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) V: "*/*", V_LEN: 3,
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) NEXTDUP: 0x0, RAW:
1, RAWLEN: 13, F: 1]
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http)
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) SLOT # 1
(0x12F2928), LIVE
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) [N: "Host", N_LEN:
4, N_IDX: 30,
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) V: "www.iana.org",
V_LEN: 12,
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) NEXTDUP: 0x0, RAW:
0, RAWLEN: 16, F: 1]
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http)
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http_trans) END
HttpTransact::StartRemapRequest
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http_trans) Next action
HTTP_API_PRE_REMAP; HttpTransact::PerformRemap
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: API_READ_REQUEST_HDR -> HTTP_API_PRE_REMAP
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http_trans) Inside
PerformRemap
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http_trans) Next action
HTTP_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: HTTP_API_PRE_REMAP -> HTTP_REMAP_REQUEST
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpSM::do_remap_request] Remapping request
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http_trans) START
HttpTransact::EndRemapRequest
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http_trans)
EndRemapRequest host is www.iana.org
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http_trans) After
Remapping:
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) HTTP_HEADER
0x12F2888: [T: 3, L: 48, OBJFLAGS: 0]
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) [TYPE: REQ, V:
10001, URL: 0x12F2B08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x12F28B8]
[Dec 14 20:36:29.438] Server {0x7fff7b5f9960} DEBUG: (http) URL 0x12F2B08: [T:
2, L: 112, OBJFLAGS: 0]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) [URLTYPE: 1,
SWKSIDX: 94,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) SCHEME: "http",
SCHEME_LEN: 4,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) USER: "",
USER_LEN: 0,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) PASSWORD: "",
PASSWORD_LEN: 0,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) HOST:
"www.iana.org", HOST_LEN: 12,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) PORT: "",
PORT_LEN: 0, PORT_NUM: 0
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) PATH:
"_css/2011.1/fonts/OpenSans-SemiBold.ttf", PATH_LEN: 39,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) PARAMS: "",
PARAMS_LEN: 0,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) QUERY: "",
QUERY_LEN: 0,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) FRAGMENT: "",
FRAGMENT_LEN: 0]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) MIME_HEADER
0x12F28B8: [T: 4, L: 592, OBJFLAGS: 0]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http)
[PBITS: 0x0000000001000001, SLACC: 0xFFFFFFF0FFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x12F28F8, TAILBLK: 0x12F28F8]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) [CBITS:
0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) FIELD_BLOCK
0x12F28F8: [T: 5, L: 528, OBJFLAGS: 0]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) [FREETOP: 2,
NEXTBLK: 0x0]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) SLOT # 0
(0x12F2908), LIVE
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) [N: "accept",
N_LEN: 6, N_IDX: 4,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) V: "*/*", V_LEN: 3,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) NEXTDUP: 0x0, RAW:
1, RAWLEN: 13, F: 1]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http)
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) SLOT # 1
(0x12F2928), LIVE
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) [N: "Host", N_LEN:
4, N_IDX: 30,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) V: "www.iana.org",
V_LEN: 12,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) NEXTDUP: 0x0, RAW:
0, RAWLEN: 16, F: 1]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http)
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http_trans) END
HttpTransact::EndRemapRequest
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http_trans) Next action
HTTP_API_POST_REMAP; HttpTransact::HandleRequest
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: HTTP_REMAP_REQUEST -> HTTP_API_POST_REMAP
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http_trans) START
HttpTransact::HandleRequest
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[is_request_valid]no request header errors
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpTransact::HandleRequest] request valid.
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) HTTP_HEADER
0x12F2888: [T: 3, L: 48, OBJFLAGS: 0]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) [TYPE: REQ, V:
10001, URL: 0x12F2B08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x12F28B8]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) URL 0x12F2B08: [T:
2, L: 112, OBJFLAGS: 0]
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) [URLTYPE: 1,
SWKSIDX: 94,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) SCHEME: "http",
SCHEME_LEN: 4,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) USER: "",
USER_LEN: 0,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) PASSWORD: "",
PASSWORD_LEN: 0,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) HOST:
"www.iana.org", HOST_LEN: 12,
[Dec 14 20:36:29.439] Server {0x7fff7b5f9960} DEBUG: (http) PORT: "",
PORT_LEN: 0, PORT_NUM: 0
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) PATH:
"_css/2011.1/fonts/OpenSans-SemiBold.ttf", PATH_LEN: 39,
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) PARAMS: "",
PARAMS_LEN: 0,
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) QUERY: "",
QUERY_LEN: 0,
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) FRAGMENT: "",
FRAGMENT_LEN: 0]
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) MIME_HEADER
0x12F28B8: [T: 4, L: 592, OBJFLAGS: 0]
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http)
[PBITS: 0x0000000001000001, SLACC: 0xFFFFFFF0FFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x12F28F8, TAILBLK: 0x12F28F8]
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) [CBITS:
0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) FIELD_BLOCK
0x12F28F8: [T: 5, L: 528, OBJFLAGS: 0]
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) [FREETOP: 2,
NEXTBLK: 0x0]
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) SLOT # 0
(0x12F2908), LIVE
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) [N: "accept",
N_LEN: 6, N_IDX: 4,
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) V: "*/*", V_LEN: 3,
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) NEXTDUP: 0x0, RAW:
1, RAWLEN: 13, F: 1]
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http)
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) SLOT # 1
(0x12F2928), LIVE
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) [N: "Host", N_LEN:
4, N_IDX: 30,
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) V: "www.iana.org",
V_LEN: 12,
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http) NEXTDUP: 0x0, RAW:
0, RAWLEN: 16, F: 1]
[Dec 14 20:36:29.440] Server {0x7fff7b5f9960} DEBUG: (http)
+++++++++ Incoming Request +++++++++
-- State Machine Id: 0
GET http://www.iana.org/_css/2011.1/fonts/OpenSans-SemiBold.ttf HTTP/1.1
accept: */*
Host: www.iana.org
[Dec 14 20:36:29.441] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[DecideCacheLookup] Will do cache lookup.
[Dec 14 20:36:29.441] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[DecideCacheLookup] Will do cache lookup
[Dec 14 20:36:29.441] Server {0x7fff7b5f9960} DEBUG: (http_trans) Next action
CACHE_LOOKUP; NULL
[Dec 14 20:36:29.441] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: HTTP_API_POST_REMAP -> CACHE_LOOKUP
[Dec 14 20:36:29.441] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpSM::do_cache_lookup_and_read] [0] Issuing cache lookup for URL
http://www.iana.org/_css/2011.1/fonts/OpenSans-SemiBold.ttf
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http_cache) [0]
[&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, CACHE_EVENT_OPEN_READ_FAILED]
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http) [0] cache_open_read
- CACHE_EVENT_OPEN_READ_FAILED
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http)
[state_cache_open_read] open read failed.
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[HttpTransact::HandleCacheOpenRead]
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http_trans) CacheOpenRead
-- miss
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http_trans) Next action
DNS_LOOKUP; OSDNSLookup
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: CACHE_LOOKUP -> DNS_LOOKUP
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpStateMachineGet::do_hostdb_lookup] Doing DNS Lookup
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active: reenable
Write
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (pvc_event) [0] Passive:
Received event 1
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side; act_on 0
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive: closed?
0 shutdown? 0
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (pvc_event) [0] Active:
Received event 1
[Dec 14 20:36:29.442] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_write_side
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, EVENT_HOST_DB_LOOKUP]
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::state_hostdb_lookup, EVENT_HOST_DB_LOOKUP]
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[HttpTransact::OSDNSLookup] This was attempt 1
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpTransact::OSDNSLookup] DNS Lookup successful
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_trans) [OSDNSLookup]
DNS lookup for O.S. successful IP: 192.0.32.8
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_trans) Next action
HttpTransact::HTTP_API_OS_DNS; HandleCacheOpenReadMiss
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: DNS_LOOKUP -> API_OS_DNS
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[HandleCacheOpenReadMiss] --- MISS
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_trans) client_ip_set
= 0
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_trans) inserted
request header 'Client-ip: 8.32.0.192'
[Dec 14 20:36:29.466] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[add_client_ip_to_outgoing_request] Appended connecting client's (8.32.0.192)
to the X-Forwards header
[Dec 14 20:36:29.467] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[build_request] request like cacheable and conditional headers removed
[Dec 14 20:36:29.467] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[ink_cluster_time] local: 1323923789, highest_delta: 0, cluster: 1323923789
[Dec 14 20:36:29.467] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[build_request] request_sent_time: 1323923789
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 0
GET /_css/2011.1/fonts/OpenSans-SemiBold.ttf HTTP/1.1
accept: */*
Host: www.iana.org
Client-ip: 8.32.0.192
X-Forwarded-For: 8.32.0.192
Via: http/1.1 blacko.local[FE800000000000000000000000000001]
(ApacheTrafficServer/3.1.1-unstable [uScMs f p eN:t cCMi p s ])
[Dec 14 20:36:29.467] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: API_OS_DNS -> CACHE_ISSUE_WRITE
[Dec 14 20:36:29.467] Server {0x7fff7b5f9960} DEBUG: (http_cache_write) [0]
writing to cache with URL
http://www.iana.org/_css/2011.1/fonts/OpenSans-SemiBold.ttf
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http_cache) [0]
[&HttpCacheSM::state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, CACHE_EVENT_OPEN_WRITE]
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM:state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http_trans) Next action
next; NULL
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: CACHE_ISSUE_WRITE -> ORIGIN_SERVER_OPEN
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http_track) entered
inside do_http_server_open
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http) [0] open connection
to www.iana.org: 192.0.32.8:80
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpSM::do_http_server_open] Sending request to server
[Dec 14 20:36:29.468] Server {0x7fff7b5f9960} DEBUG: (http) calling
netProcessor.connect_re
[Dec 14 20:36:29.469] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, NET_EVENT_OPEN]
[Dec 14 20:36:29.469] Server {0x7fff7b5f9960} DEBUG: (http_track) entered
inside state_http_server_open
[Dec 14 20:36:29.469] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::state_http_server_open, NET_EVENT_OPEN]
[Dec 14 20:36:29.469] Server {0x7fff7b5f9960} DEBUG: (http_ss) [0] session
born, netvc 0x102850240
[Dec 14 20:36:29.508] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Dec 14 20:36:29.511] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Dec 14 20:36:29.559] Server {0x7fff7b5f9960} DEBUG: (spdy.protocol) attempting
to read 8192 bytes
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (spdy.protocol) read 3449
bytes
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, VC_EVENT_READ_READY]
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY]
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_seq) Done parsing
server response header
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[HttpTransact::HandleResponse]
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpTransact::HandleResponse] Response received
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[ink_cluster_time] local: 1323923789, highest_delta: 0, cluster: 1323923789
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[HandleResponse] response_received_time: 1323923789
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 0
HTTP/1.1 404 NOT FOUND
Date: Thu, 15 Dec 2011 04:36:26 GMT
Server: Apache/2.2.3 (CentOS)
Connection: close
Content-Type: text/html; charset=utf-8
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[is_response_valid] No errors in response
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpTransact::HandleResponse] Response valid
[Dec 14 20:36:29.560] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[handle_response_from_server] (hrfs)
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_trans) [hrfs]
connection alive
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[handle_forward_server_connection_open] (hfsco)
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpTransact::handle_server_connection_open]
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http) server info =
192.0.32.8:80
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_trans) [hfsco] cache
action: CACHE_DO_WRITE
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[handle_cache_operation_on_forward_server_response] (hcoofsr)
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[handle_cache_operation_on_forward_server_response]
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[is_response_cacheable] client permits storing
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_trans)
[is_response_cacheable] NO by default
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_trans) [hcoofsr]
response code: 404
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] age_value: 0
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] date_value: 1323923786
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] response_time: 1323923789
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] now: 1323923789
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] now (fixed): 1323923789
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] apparent_age: 3
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] corrected_received_age: 3
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] response_delay: 0
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] corrected_initial_age: 3
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] resident_time: 0
[Dec 14 20:36:29.561] Server {0x7fff7b5f9960} DEBUG: (http_age)
[calculate_document_age] current_age: 3
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http_trans) [WUTS code
generation] Hit/Miss: 49, Log: 51, Hier: 50, Status: 404
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http_trans) Adding
Server: ATS/3.1.1-unstable
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 0
HTTP/1.1 404 NOT FOUND
Date: Thu, 15 Dec 2011 04:36:26 GMT
Server: Apache/2.2.3 (CentOS)
Connection: close
Content-Type: text/html; charset=utf-8
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 0
HTTP/1.1 404 NOT FOUND
Date: Thu, 15 Dec 2011 04:36:26 GMT
Server: ATS/3.1.1-unstable
Content-Type: text/html; charset=utf-8
Age: 3
Transfer-Encoding: chunked
Connection: keep-alive
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: ORIGIN_SERVER_OPEN -> SERVER_READ
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpSM::do_redirect]
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0] adding
producer 'http server'
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0] adding
consumer 'user agent'
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http) [0]
perform_cache_write_action CACHE_DO_NO_ACTION
[Dec 14 20:36:29.562] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) tunnel_run
started, p_arg is NULL
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_cs)
tcp_init_cwnd_set 0
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_cs) desired TCP
congestion window is 0
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
do_io_write for -1 bytes
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_dechunked [http server VC_EVENT_READ_READY]
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_chunk) creating a
chunk of size 3296 bytes
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
reenable Write
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (spdy.protocol) attempting
to read 32768 bytes
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (spdy.protocol) read 0
bytes
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (spdy.protocol) triggering
EOS
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_EOS]
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_dechunked [http server VC_EVENT_EOS]
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 104
[Dec 14 20:36:30.192] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::tunnel_handler_server, VC_EVENT_EOS]
Breakpoint 1, HttpServerSession::do_io_close (this=0x101b68510, alerrno=-1) at
HttpServerSession.cc:117
117 if (state == HSS_ACTIVE) {
(gdb) c
Continuing.
[Dec 14 20:36:31.338] Server {0x7fff7b5f9960} DEBUG: (http_ss) [0] session
closed
[Dec 14 20:36:31.362] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
reenable Write
[Dec 14 20:36:31.362] Server {0x7fff7b5f9960} DEBUG: (pvc_event) [0] Passive:
Received event 1
[Dec 14 20:36:31.362] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_write_side
[Dec 14 20:36:31.363] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_write_side; act_on 3499
[Dec 14 20:36:31.386] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_write_side; added 3499
[Dec 14 20:36:31.386] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Dec 14 20:36:31.387] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Dec 14 20:36:31.387] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0] session
released by sm [0]
[Dec 14 20:36:31.387] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0] initiating
io for next header
[Dec 14 20:36:31.387] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
do_io_read for -1 bytes
[Dec 14 20:36:31.387] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Dec 14 20:36:31.387] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Dec 14 20:36:31.387] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Dec 14 20:36:31.396] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpStateMachineGet::update_stats] Logging transaction
[Dec 14 20:36:31.396] Server {0x7fff7b5f9960} DEBUG: (http) [0] dellocating sm
[Dec 14 20:36:31.396] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_read_side
[Dec 14 20:36:31.396] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_read_side; act_on 3499
[Dec 14 20:36:31.396] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_read_side; added 3499
[Dec 14 20:36:31.396] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 14 20:36:31.396] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 14 20:36:31.396] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 3499
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active: reenable
Read
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
reenable Write
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc_event) [0] Passive:
Received event 1
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_read_side; act_on 0
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive: closed?
0 shutdown? 0
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Passive:
process_write_side
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc_event) [0] Active:
Received event 1
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_read_side
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active:
process_read_side; act_on 0
[Dec 14 20:36:31.397] Server {0x7fff7b5f9960} DEBUG: (pvc) [0] Active: closed?
0 shutdown? 0
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (pvc_event) [0] Passive:
Received event 2
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (http_cs) [0]
[&HttpClientSession::state_keep_alive, VC_EVENT_ACTIVE_TIMEOUT]
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (pvc) [0] Passive: do_io_close
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (http_cs) [0] session closed
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (http_cs) [0] session destroy
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (pvc) [0] Passive:
process_close
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (pvc_event) [0] Active:
Received event 1
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (pvc) [0] Active:
process_read_side
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (pvc) [0] Active:
process_read_side; act_on 0
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (pvc) [0] Active: closed? 1
shutdown? 0
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 14 20:38:26.380] Server {0x102602000} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 14 20:38:26.381] Server {0x102602000} DEBUG: (FetchSM)
[get_info_from_buffer] total avail 3308
[Dec 14 20:38:26.381] Server {0x102602000} DEBUG: (FetchSM)
[process_fetch_read] number of bytes 3308, resp=0x102808600
[Dec 14 20:38:26.381] Server {0x102602000} DEBUG: (FetchSM)
[process_fetch_read] Completed data fetch of size 3308, notifying caller
[Dec 14 20:38:26.382] Server {0x102602000} DIAG: (plugin) [1] http request (191
of 191 bytes):
HTTP/1.1 404 NOT FOUND
Date: Thu, 15 Dec 2011 04:36:26 GMT
Server: ATS/3.1.1-unstable
Content-Type: text/html; charset=utf-8
Age: 3
Transfer-Encoding: chunked
Connection: keep-alive
[Dec 14 20:38:26.383] Server {0x102602000} DEBUG: (FetchSM)
[process_fetch_read] received EOS
[Dec 14 20:38:26.383] Server {0x102602000} DEBUG: (FetchSM) [cleanUp] calling
cleanup
[Dec 14 20:38:26.383] Server {0x102602000} DEBUG: (pvc) [0] Active: do_io_close
[Dec 14 20:38:26.383] Server {0x102602000} DEBUG: (pvc) [0] Active:
process_close
[Dec 14 20:38:26.383] Server {0x102602000} DEBUG: (pvc) [0] Destroying
PluginVCCore at 0x102872c00
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
