[ https://issues.apache.org/jira/browse/TS-1054?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Leif Hedstrom updated TS-1054: ------------------------------ Fix Version/s: (was: 3.1.2) 3.1.3 Moving out to 3.1.3 for now. > 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 > Assignee: James Peach > Priority: Minor > Fix For: 3.1.3 > > > 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