[
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: 5.2.0)
> 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
>
> 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 was sent by Atlassian JIRA
(v6.3.4#6332)
