You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "Leif Hedstrom (Updated) (JIRA)" <ji...@apache.org> on 2011/12/15 23:23:33 UTC
[jira] [Updated] (TS-1054) TSFetchUrl takes an address but does the
DNS lookup anyway
[ 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: 3.1.2
> 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
> Fix For: 3.1.2
>
>
> 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