Skip to content

Instantly share code, notes, and snippets.

@jvgutierrez

jvgutierrez/1596.log

Created February 12, 2020 13:53
Show Gist options
  • Save jvgutierrez/22d234d4afdbc6017f70f8f3fe0d8665 to your computer and use it in GitHub Desktop.
Save jvgutierrez/22d234d4afdbc6017f70f8f3fe0d8665 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
1596.log
+++++++++ Incoming Request +++++++++
-- State Machine Id: 1596
GET http://ats_httpbin_1:80/delay/20 HTTP/1.1
Host: 127.0.0.1:3128
User-Agent: curl/7.64.1
Accept: */*
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 1596
GET /delay/20 HTTP/1.1
Host: 127.0.0.1:3128
User-Agent: curl/7.64.1
Accept: */*
Client-ip: 172.19.0.1
X-Forwarded-For: 172.19.0.1
Via: http/1.1 localhost[5f3c3148-d03c-425d-8afd-60bebd4b20ba] (ApacheTrafficServer/8.0.5)
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 1596
GET /delay/20 HTTP/1.1
Host: 127.0.0.1:3128
User-Agent: curl/7.64.1
Accept: */*
Client-ip: 172.19.0.1
X-Forwarded-For: 172.19.0.1
Via: http/1.1 localhost[5f3c3148-d03c-425d-8afd-60bebd4b20ba] (ApacheTrafficServer/8.0.5)
X-Client-IP: 172.19.0.1
X-Connection-Properties: H2=0; SSR=0; SSL=-; C=-; EC=-;
X-Forwarded-Proto: https
Connection: keep-alive
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpSM.cc:580 (state_read_client_request_header)> (http) [1596] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpSM.cc:727 (state_read_client_request_header)> (http) [1596] done parsing client request header
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:985 (ModifyRequest)> (http_trans) [1596] START HttpTransact::ModifyRequest
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1059 (ModifyRequest)> (http_trans) [1596] END HttpTransact::ModifyRequest
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1060 (ModifyRequest)> (http_trans) [1596] Checking if transaction wants to upgrade
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1068 (ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:611 (StartRemapRequest)> (http_trans) [1596] START HttpTransact::StartRemapRequest
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:631 (StartRemapRequest)> (http_trans) [1596] Before Remapping:
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x2ba6ab80e088: [T: 3, L: 48, OBJFLAGS: 0]
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x2ba6ab80e308, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2ba6ab80e0b8]
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x2ba6ab80e308: [T: 2, L: 112, OBJFLAGS: 0]
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "", HOST_LEN: 0,
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "delay/20", PATH_LEN: 8,
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x2ba6ab80e0b8: [T: 4, L: 592, OBJFLAGS: 0]
[Feb 12 12:52:02.594] {0x2ba6a983a700} DEBUG: <MIME.cc:2708 (mime_hdr_describe)> (http)
[PBITS: 0x0008000001000001, SLACC: 0xFFFFFFF2FFFFFFFFFFFFFFFFFFF1FFFF, HEADBLK: 0x2ba6ab80e0f8, TAILBLK: 0x2ba6ab80e0f8]
[Feb 12 12:52:02.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:642 (StartRemapRequest)> (http_trans) [1596] END HttpTransact::StartRemapRequest
[Feb 12 12:52:02.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:643 (StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap
[Feb 12 12:52:02.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Feb 12 12:52:02.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:649 (PerformRemap)> (http_trans) [1596] Inside PerformRemap
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:650 (PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:3952 (do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:656 (EndRemapRequest)> (http_trans) [1596] START HttpTransact::EndRemapRequest
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:662 (EndRemapRequest)> (http_trans) [1596] EndRemapRequest host is ats_httpbin_1
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:800 (EndRemapRequest)> (http_trans) [1596] After Remapping:
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x2ba6ab80e088: [T: 3, L: 48, OBJFLAGS: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x2ba6ab80e308, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2ba6ab80e0b8]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x2ba6ab80e308: [T: 2, L: 112, OBJFLAGS: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "ats_httpbin_1", HOST_LEN: 13,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "80", PORT_LEN: 2, PORT_NUM: 80
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "delay/20", PATH_LEN: 8,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x2ba6ab80e0b8: [T: 4, L: 592, OBJFLAGS: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2708 (mime_hdr_describe)> (http)
[PBITS: 0x0008000001000001, SLACC: 0xFFFFFFF2FFFFFFFFFFFFFFFFFFF1FFFF, HEADBLK: 0x2ba6ab80e0f8, TAILBLK: 0x2ba6ab80e0f8]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2713 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x2ba6ab80e0f8: [T: 5, L: 528, OBJFLAGS: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2733 (mime_field_block_describe)> (http) SLOT # 0 (0x2ba6ab80e108), LIVE
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2742 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2743 (mime_field_block_describe)> (http) V: "127.0.0.1:3128", V_LEN: 14,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2745 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2748 (mime_field_block_describe)> (http)
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2733 (mime_field_block_describe)> (http) SLOT # 1 (0x2ba6ab80e128), LIVE
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2742 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2743 (mime_field_block_describe)> (http) V: "curl/7.64.1", V_LEN: 11,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2745 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2748 (mime_field_block_describe)> (http)
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2733 (mime_field_block_describe)> (http) SLOT # 2 (0x2ba6ab80e148), LIVE
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2742 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2743 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2745 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2748 (mime_field_block_describe)> (http)
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:819 (EndRemapRequest)> (http_trans) [1596] END HttpTransact::EndRemapRequest
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:825 (EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1105 (HandleRequest)> (http_trans) [1596] START HttpTransact::HandleRequest
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:5119 (check_request_validity)> (http_trans) [1596] [init_stat_vars_from_req] set req cont length to 0
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:6187 (is_request_valid)> (http_trans) [1596] [is_request_valid] no request header errors
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1127 (HandleRequest)> (http_seq) [1596] [HttpTransact::HandleRequest] request valid.
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x2ba6ab80e088: [T: 3, L: 48, OBJFLAGS: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x2ba6ab80e308, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2ba6ab80e0b8]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x2ba6ab80e308: [T: 2, L: 112, OBJFLAGS: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "ats_httpbin_1", HOST_LEN: 13,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "80", PORT_LEN: 2, PORT_NUM: 80
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "delay/20", PATH_LEN: 8,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x2ba6ab80e0b8: [T: 4, L: 592, OBJFLAGS: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2708 (mime_hdr_describe)> (http)
[PBITS: 0x0008000001000001, SLACC: 0xFFFFFFF2FFFFFFFFFFFFFFFFFFF1FFFF, HEADBLK: 0x2ba6ab80e0f8, TAILBLK: 0x2ba6ab80e0f8]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2713 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x2ba6ab80e0f8: [T: 5, L: 528, OBJFLAGS: 0]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2733 (mime_field_block_describe)> (http) SLOT # 0 (0x2ba6ab80e108), LIVE
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2742 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2743 (mime_field_block_describe)> (http) V: "127.0.0.1:3128", V_LEN: 14,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2745 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2748 (mime_field_block_describe)> (http)
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2733 (mime_field_block_describe)> (http) SLOT # 1 (0x2ba6ab80e128), LIVE
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2742 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2743 (mime_field_block_describe)> (http) V: "curl/7.64.1", V_LEN: 11,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2745 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2748 (mime_field_block_describe)> (http)
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2733 (mime_field_block_describe)> (http) SLOT # 2 (0x2ba6ab80e148), LIVE
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2742 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2743 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2745 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <MIME.cc:2748 (mime_field_block_describe)> (http)
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1281 (HandleRequest)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; OSDNSLookup
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_DNS_LOOKUP
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4055 (do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1550 (OSDNSLookup)> (http_trans) [1596] [HttpTransact::OSDNSLookup] This was attempt 0
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1620 (OSDNSLookup)> (http_seq) [1596] [HttpTransact::OSDNSLookup] DNS Lookup successful
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1660 (OSDNSLookup)> (http_trans) [1596] [OSDNSLookup] DNS lookup for O.S. successful IP: 172.19.0.2
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1767 (HandleRequestAuthorized)> (http_trans) Next action SM_ACTION_API_OS_DNS; HttpTransact::DecideCacheLookup
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1879 (DecideCacheLookup)> (http_trans) [1596] [DecideCacheLookup] Will NOT do cache lookup.
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1880 (DecideCacheLookup)> (http_seq) [1596] [DecideCacheLookup] Will NOT do cache lookup
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1899 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_API_CACHE_LOOKUP_COMPLETE; LookupSkipOpenServer
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentSelection.cc:118 (findParent)> (parent_select) policy.ParentEnable: 1
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentSelection.cc:809 (UpdateMatch)> (parent_select) Matched with 0x557345e517d8 parent node from line 1
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:61 (selectParent)> (parent_select) In ParentRoundRobin::selectParent(): Using a round robin parent selection strategy.
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:139 (selectParent)> (parent_select) cur_index: 0, result->start_parent: 0
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:143 (selectParent)> (parent_select) FailThreshold = 10
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:145 (selectParent)> (parent_select) Selecting a parent due to little failCount (faileAt: 0 failCount: 0)
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:163 (selectParent)> (parent_select) status for ats_httpbin_1: 2
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:171 (selectParent)> (parent_select) Chosen parent = ats_httpbin_1.80
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentSelection.cc:176 (findParent)> (parent_select) PARENT_SPECIFIED
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <ParentSelection.cc:177 (findParent)> (parent_select) Result for ats_httpbin_1 was parent ats_httpbin_1:80
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1918 (LookupSkipOpenServer)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; PPDNSLookup
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_DNS_LOOKUP
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4055 (do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1406 (PPDNSLookup)> (http_trans) [1596] [HttpTransact::PPDNSLookup] This was attempt 1
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1441 (PPDNSLookup)> (http_trans) [1596] [PPDNSLookup] DNS lookup for sm_id[1596] successful IP: 172.19.0.2
Host: 127.0.0.1:3128
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:5025 (add_client_ip_to_outgoing_request)> (http_trans) [1596] client_ip_set = 0
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:5035 (add_client_ip_to_outgoing_request)> (http_trans) [1596] inserted request header 'Client-ip: 172.19.0.1'
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:5049 (add_client_ip_to_outgoing_request)> (http_trans) [1596] [add_client_ip_to_outgoing_request] Appended connecting client's (172.19.0.1) to the X-Forwards header
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:7601 (build_request)> (http_trans) [1596] [build_request] removing host name from url
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:7639 (build_request)> (http_trans) [1596] [build_request] request_sent_time: 1581511922
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_ORIGIN_SERVER_OPEN
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4667 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4694 (do_http_server_open)> (http) [1596] open connection to ats_httpbin_1: 172.19.0.2:80
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4706 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSessionManager.cc:323 (acquire_session)> (http_ss) [acquire session] thread pool search successful
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSessionManager.cc:355 (acquire_session)> (http_ss) [0] [acquire session] return session from shared pool
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1438 (state_api_callout)> (http) [1596] calling plugin on hook TS_HTTP_SEND_REQUEST_HDR_HOOK at hook 0x557345ee7fe0
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1284 (state_api_callback)> (http) [1596] [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 12 12:52:02.596] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1324 (state_api_callout)> (http) [1596] [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 12 12:52:02.597] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:02.597] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1979 (state_send_server_request_header)> (http) [1596] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1821 (state_read_server_response_header)> (http) [1596] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:5398 (handle_server_setup_error)> (http) [1596] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <HttpTunnel.cc:1144 (producer_handler)> (http_tunnel) [1787] producer_handler [http server VC_EVENT_READ_COMPLETE]
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpServerSession.cc:125 (do_io_close)> (http_ss) [0] session closing, netvc 0x2ba6e801abc0
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <HttpTunnel.cc:1188 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <HttpSM.cc:2886 (tunnel_handler_server)> (http) [1787] [&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE]
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <HttpServerSession.cc:169 (release)> (http_ss) Releasing session, private_session=0, sharing_match=2
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3131 (HandleResponse)> (http_trans) [1596] [HttpTransact::HandleResponse]
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3132 (HandleResponse)> (http_seq) [1596] [HttpTransact::HandleResponse] Response received
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <HttpSessionManager.cc:160 (releaseSession)> (http_ss) [11] [release session] session placed into shared pool
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3139 (HandleResponse)> (http_trans) [1596] [HandleResponse] response_received_time: 1581511926
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3154 (HandleResponse)> (http_seq) [1596] [HttpTransact::HandleResponse] Response not valid
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3289 (handle_response_from_parent)> (http_trans) [1596] [handle_response_from_parent] (hrfp)
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3337 (handle_response_from_parent)> (http_trans) [1596] [hrfp] connection not alive
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3351 (handle_response_from_parent)> (http_trans) [1596] [1] failed to connect to parent 172.19.0.2
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3375 (handle_response_from_parent)> (http_trans) [1596] [handle_response_from_parent] Retrying parent for attempt 2, max 2
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_ORIGIN_SERVER_OPEN
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <Http1ClientSession.cc:234 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4667 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <Http1ClientSession.cc:474 (release)> (http_cs) [1] initiating io for next header
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4694 (do_http_server_open)> (http) [1596] open connection to ats_httpbin_1: 172.19.0.2:80
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4706 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSessionManager.cc:323 (acquire_session)> (http_ss) [acquire session] thread pool search successful
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSessionManager.cc:355 (acquire_session)> (http_ss) [6] [acquire session] return session from shared pool
[Feb 12 12:52:06.595] {0x2ba6a9638700} DEBUG: <HttpSM.cc:6865 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Feb 12 12:52:06.595] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1438 (state_api_callout)> (http) [1596] calling plugin on hook TS_HTTP_SEND_REQUEST_HDR_HOOK at hook 0x557345ee7fe0
[Feb 12 12:52:06.603] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1284 (state_api_callback)> (http) [1596] [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 12 12:52:06.603] {0x2ba6a9638700} DEBUG: <HttpTransact.cc:631 (StartRemapRequest)> (http_trans) [1798] Before Remapping:
[Feb 12 12:52:06.603] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1324 (state_api_callout)> (http) [1596] [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 12 12:52:06.617] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:06.617] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1979 (state_send_server_request_header)> (http) [1596] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1821 (state_read_server_response_header)> (http) [1596] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:5398 (handle_server_setup_error)> (http) [1596] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpServerSession.cc:125 (do_io_close)> (http_ss) [6] session closing, netvc 0x2ba6e8019780
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3131 (HandleResponse)> (http_trans) [1596] [HttpTransact::HandleResponse]
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3132 (HandleResponse)> (http_seq) [1596] [HttpTransact::HandleResponse] Response received
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3139 (HandleResponse)> (http_trans) [1596] [HandleResponse] response_received_time: 1581511929
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3154 (HandleResponse)> (http_seq) [1596] [HttpTransact::HandleResponse] Response not valid
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3289 (handle_response_from_parent)> (http_trans) [1596] [handle_response_from_parent] (hrfp)
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3337 (handle_response_from_parent)> (http_trans) [1596] [hrfp] connection not alive
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3351 (handle_response_from_parent)> (http_trans) [1596] [2] failed to connect to parent 172.19.0.2
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3378 (handle_response_from_parent)> (http_trans) [1596] [handle_response_from_parent] 3 per parent attempts exhausted
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentSelection.cc:191 (nextParent)> (parent_select) ParentConfigParams::nextParent(): parent_table: 0x557345e4e2d0, result->rec: 0x557345e517d8
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentSelection.cc:207 (nextParent)> (parent_select) ParentConfigParams::nextParent(): result->r: 2, tablePtr: 0x557345e4e2d0
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentSelection.cc:210 (nextParent)> (parent_select) Calling selectParent() from nextParent
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:61 (selectParent)> (parent_select) In ParentRoundRobin::selectParent(): Using a round robin parent selection strategy.
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:139 (selectParent)> (parent_select) cur_index: 1, result->start_parent: 0
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:143 (selectParent)> (parent_select) FailThreshold = 10
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:145 (selectParent)> (parent_select) Selecting a parent due to little failCount (faileAt: 0 failCount: 0)
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:163 (selectParent)> (parent_select) status for ats_httpbin_2: 2
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentRoundRobin.cc:171 (selectParent)> (parent_select) Chosen parent = ats_httpbin_2.80
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <ParentSelection.cc:229 (nextParent)> (parent_select) Retry result for ats_httpbin_1 was parent ats_httpbin_2:80
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3411 (handle_response_from_parent)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; PPDNSLookup
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_DNS_LOOKUP
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4055 (do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1406 (PPDNSLookup)> (http_trans) [1596] [HttpTransact::PPDNSLookup] This was attempt 1
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:1441 (PPDNSLookup)> (http_trans) [1596] [PPDNSLookup] DNS lookup for sm_id[1596] successful IP: 172.19.0.3
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_ORIGIN_SERVER_OPEN
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4667 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4694 (do_http_server_open)> (http) [1596] open connection to ats_httpbin_2: 172.19.0.3:80
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4706 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSessionManager.cc:323 (acquire_session)> (http_ss) [acquire session] thread pool search successful
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSessionManager.cc:355 (acquire_session)> (http_ss) [4] [acquire session] return session from shared pool
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1438 (state_api_callout)> (http) [1596] calling plugin on hook TS_HTTP_SEND_REQUEST_HDR_HOOK at hook 0x557345ee7fe0
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1284 (state_api_callback)> (http) [1596] [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 12 12:52:09.865] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1324 (state_api_callout)> (http) [1596] [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 12 12:52:09.880] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:09.880] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1979 (state_send_server_request_header)> (http) [1596] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1821 (state_read_server_response_header)> (http) [1596] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
+++++++++ Incoming Request +++++++++
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:5398 (handle_server_setup_error)> (http) [1596] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpServerSession.cc:125 (do_io_close)> (http_ss) [4] session closing, netvc 0x2ba6e8019e40
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3131 (HandleResponse)> (http_trans) [1596] [HttpTransact::HandleResponse]
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3132 (HandleResponse)> (http_seq) [1596] [HttpTransact::HandleResponse] Response received
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3139 (HandleResponse)> (http_trans) [1596] [HandleResponse] response_received_time: 1581511933
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3154 (HandleResponse)> (http_seq) [1596] [HttpTransact::HandleResponse] Response not valid
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3289 (handle_response_from_parent)> (http_trans) [1596] [handle_response_from_parent] (hrfp)
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3337 (handle_response_from_parent)> (http_trans) [1596] [hrfp] connection not alive
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3351 (handle_response_from_parent)> (http_trans) [1596] [3] failed to connect to parent 172.19.0.3
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3375 (handle_response_from_parent)> (http_trans) [1596] [handle_response_from_parent] Retrying parent for attempt 4, max 2
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_ORIGIN_SERVER_OPEN
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4667 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4694 (do_http_server_open)> (http) [1596] open connection to ats_httpbin_2: 172.19.0.3:80
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:4706 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSessionManager.cc:323 (acquire_session)> (http_ss) [acquire session] thread pool search successful
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSessionManager.cc:355 (acquire_session)> (http_ss) [15] [acquire session] return session from shared pool
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1438 (state_api_callout)> (http) [1596] calling plugin on hook TS_HTTP_SEND_REQUEST_HDR_HOOK at hook 0x557345ee7fe0
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1284 (state_api_callback)> (http) [1596] [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 12 12:52:13.451] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1324 (state_api_callout)> (http) [1596] [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 12 12:52:13.452] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:13.452] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1979 (state_send_server_request_header)> (http) [1596] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpSM.cc:1821 (state_read_server_response_header)> (http) [1596] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpSM.cc:5398 (handle_server_setup_error)> (http) [1596] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT]
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpServerSession.cc:125 (do_io_close)> (http_ss) [15] session closing, netvc 0x2ba6e8019780
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3131 (HandleResponse)> (http_trans) [1596] [HttpTransact::HandleResponse]
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3132 (HandleResponse)> (http_seq) [1596] [HttpTransact::HandleResponse] Response received
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3139 (HandleResponse)> (http_trans) [1596] [HandleResponse] response_received_time: 1581511936
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3154 (HandleResponse)> (http_seq) [1596] [HttpTransact::HandleResponse] Response not valid
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3289 (handle_response_from_parent)> (http_trans) [1596] [handle_response_from_parent] (hrfp)
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3337 (handle_response_from_parent)> (http_trans) [1596] [hrfp] connection not alive
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3351 (handle_response_from_parent)> (http_trans) [1596] [4] failed to connect to parent 172.19.0.3
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:3395 (handle_response_from_parent)> (http_trans) [1596] [handle_response_from_parent] Error. No more retries.
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransactHeaders.cc:638 (generate_and_set_squid_codes)> (http_trans) [Squid code generation] Hit/Miss: 1, Log: u, Hier: 2
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransactHeaders.cc:1220 (add_server_header_to_response)> (http_trans) Adding Server: ATS/8.0.5
[Feb 12 12:52:16.616] {0x2ba6a9638700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [2222] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Feb 12 12:52:16.616] {0x2ba6a9638700} DEBUG: <HttpSM.cc:1821 (state_read_server_response_header)> (http) [2222] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY]
[Feb 12 12:52:16.616] {0x2ba6a9638700} DEBUG: <HttpSM.cc:1926 (state_read_server_response_header)> (http_seq) Done parsing server response header
[Feb 12 12:52:16.616] {0x2ba6a983a700} DEBUG: <HttpTransact.cc:7378 (handle_parent_died)> (http_trans) Next action SM_ACTION_SEND_ERROR_CACHE_NOOP; nullptr
[Feb 12 12:52:16.617] {0x2ba6a983a700} DEBUG: <HttpSM.cc:7142 (call_transact_and_set_next_state)> (http) [1596] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SEND_ERROR_CACHE_NOOP
[Feb 12 12:52:16.617] {0x2ba6a983a700} DEBUG: <HttpTunnel.cc:655 (add_producer)> (http_tunnel) [1596] adding producer 'internal msg'
[Feb 12 12:52:16.617] {0x2ba6a983a700} DEBUG: <HttpTunnel.cc:710 (add_consumer)> (http_tunnel) [1596] adding consumer 'user agent'
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <HttpTunnel.cc:1350 (consumer_handler)> (http_tunnel) [1596] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <HttpSM.cc:3150 (tunnel_handler_ua)> (http) [1596] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <ProxyClientTransaction.cc:67 (release)> (http_txn) [6] session released by sm [1596]
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <Http1ClientSession.cc:234 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <Http1ClientSession.cc:474 (release)> (http_cs) [6] initiating io for next header
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2549 (main_handler)> (http) [1596] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <HttpSM.cc:2835 (tunnel_handler)> (http) [1596] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <HttpSM.cc:6865 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Feb 12 12:52:16.621] {0x2ba6a983a700} DEBUG: <HttpSM.cc:6891 (kill_this)> (http) [1596] deallocating sm
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 1596
HTTP/1.0 0
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 1596
HTTP/1.1 502 Next Hop Connection Failed
Date: Wed, 12 Feb 2020 12:52:16 GMT
Connection: keep-alive
Server: ATS/8.0.5
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment