HttpRedirect doesn't work with big post request

[zizhong]

@scw00 @oknet
I guess it's related to #2766, but when I tried the older version I got some other crashes.

Nov 27 23:49:30.815] Server {0x7fffef830700} DEBUG: <ProtocolProbeSessionAccept.cc:139 (mainEvent)> (http) probe needs data, read..
[Nov 27 23:49:30.816] Server {0x7fffef830700} DEBUG: <HttpSessionAccept.cc:58 (accept)> (http_seq) [HttpSessionAccept:mainEvent 0x7fff6c018d00] accepted connection from 127.0.0.1:60296 transport type = 1
[Nov 27 23:49:30.817] Server {0x7fffef830700} DEBUG: <Http1ClientSession.cc:200 (new_connection)> (http_cs) [0] session born, netvc 0x7fff6c018d00
[Nov 27 23:49:30.817] Server {0x7fffef830700} DEBUG: <Http1ClientSession.cc:230 (do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Nov 27 23:49:30.817] Server {0x7fffef830700} DEBUG: <Http1ClientSession.cc:467 (release)> (http_cs) [0] data already in buffer, starting new transaction
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <ProxyClientTransaction.cc:52 (new_transaction)> (http_txn) [0] Starting transaction 1 using sm [0]
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:362 (state_add_to_list)> (http) [0] [&HttpSM::state_add_to_list, VC_EVENT_NONE]
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:576 (state_read_client_request_header)> (http) [0] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:723 (state_read_client_request_header)> (http) [0] done parsing client request header
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:988 (ModifyRequest)> (http_trans) [0] START HttpTransact::ModifyRequest
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1062 (ModifyRequest)> (http_trans) [0] END HttpTransact::ModifyRequest
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1063 (ModifyRequest)> (http_trans) [0] Checking if transaction wants to upgrade
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1071 (ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:595 (StartRemapRequest)> (http_trans) [0] START HttpTransact::StartRemapRequest
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:635 (StartRemapRequest)> (http_trans) [0] Before Remapping:
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x7fffedaea888: [T: 3, L:   48, OBJFLAGS: 0]
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x7fffedaeab08, METHOD: "POST", METHOD_LEN: 4, FIELDS: 0x7fffedaea8b8]
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x7fffedaeab08: [T: 2, L:  112, OBJFLAGS: 0]
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <URL.cc:1616 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <URL.cc:1618 (url_describe)> (http) 	SCHEME: "http", SCHEME_LEN: 4,
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <URL.cc:1619 (url_describe)> (http) 	USER: "", USER_LEN: 0,
[Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <URL.cc:1621 (url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1622 (url_describe)> (http) 	HOST: "", HOST_LEN: 0,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1624 (url_describe)> (http) 	PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1625 (url_describe)> (http) 	PATH: "aaa", PATH_LEN: 3,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1627 (url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1629 (url_describe)> (http) 	QUERY: "", QUERY_LEN: 0,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1631 (url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x7fffedaea8b8: [T: 4, L:  592, OBJFLAGS: 0]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2681 (mime_hdr_describe)> (http)
	[PBITS: 0x0000000001004800, SLACC: 0xFFFFFFFFFFFF1FF0FFFFFFFFFFFFFFFF, HEADBLK: 0x7fffedaea8f8, TAILBLK: 0x7fffedaea8f8]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2686 (mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x7fffedaea8f8: [T: 5, L:  528, OBJFLAGS: 0]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2702 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 0 (0x7fffedaea908), LIVE
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Connection", N_LEN: 10, N_IDX: 12,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "keep-alive", V_LEN: 10,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 1 (0x7fffedaea928), LIVE
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "6000", V_LEN: 4,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 2 (0x7fffedaea948), LIVE
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "127.0.0.1", V_LEN: 9,
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 17, F: 1]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:645 (StartRemapRequest)> (http_trans) [0] END HttpTransact::StartRemapRequest
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:646 (StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:652 (PerformRemap)> (http_trans) [0] Inside PerformRemap
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:653 (PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpSM.cc:3977 (do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:659 (EndRemapRequest)> (http_trans) [0] START HttpTransact::EndRemapRequest
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:665 (EndRemapRequest)> (http_trans) [0] EndRemapRequest host is localhost
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:803 (EndRemapRequest)> (http_trans) [0] After Remapping:
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x7fffedaea888: [T: 3, L:   48, OBJFLAGS: 0]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x7fffedaeab08, METHOD: "POST", METHOD_LEN: 4, FIELDS: 0x7fffedaea8b8]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x7fffedaeab08: [T: 2, L:  112, OBJFLAGS: 0]
[Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1616 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1618 (url_describe)> (http) 	SCHEME: "http", SCHEME_LEN: 4,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1619 (url_describe)> (http) 	USER: "", USER_LEN: 0,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1621 (url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1622 (url_describe)> (http) 	HOST: "localhost", HOST_LEN: 9,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1624 (url_describe)> (http) 	PORT: "4090", PORT_LEN: 4, PORT_NUM: 4090
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1625 (url_describe)> (http) 	PATH: "aaa", PATH_LEN: 3,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1627 (url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1629 (url_describe)> (http) 	QUERY: "", QUERY_LEN: 0,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1631 (url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x7fffedaea8b8: [T: 4, L:  592, OBJFLAGS: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2681 (mime_hdr_describe)> (http)
	[PBITS: 0x0000000001004800, SLACC: 0xFFFFFFFFFFFF1FF0FFFFFFFFFFFFFFFF, HEADBLK: 0x7fffedaea8f8, TAILBLK: 0x7fffedaea8f8]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2686 (mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x7fffedaea8f8: [T: 5, L:  528, OBJFLAGS: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2702 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 0 (0x7fffedaea908), LIVE
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Connection", N_LEN: 10, N_IDX: 12,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "keep-alive", V_LEN: 10,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 1 (0x7fffedaea928), LIVE
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "6000", V_LEN: 4,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 2 (0x7fffedaea948), LIVE
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "localhost:4090", V_LEN: 14,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 22, F: 1]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:822 (EndRemapRequest)> (http_trans) [0] END HttpTransact::EndRemapRequest
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:828 (EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1108 (HandleRequest)> (http_trans) [0] START HttpTransact::HandleRequest
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:5099 (check_request_validity)> (http_trans) [0] [init_stat_vars_from_req] set req cont length to 6000
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:6154 (is_request_valid)> (http_trans) [0] [is_request_valid] no request header errors
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1129 (HandleRequest)> (http_seq) [0] [HttpTransact::HandleRequest] request valid.
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x7fffedaea888: [T: 3, L:   48, OBJFLAGS: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x7fffedaeab08, METHOD: "POST", METHOD_LEN: 4, FIELDS: 0x7fffedaea8b8]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x7fffedaeab08: [T: 2, L:  112, OBJFLAGS: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1616 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1618 (url_describe)> (http) 	SCHEME: "http", SCHEME_LEN: 4,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1619 (url_describe)> (http) 	USER: "", USER_LEN: 0,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1621 (url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1622 (url_describe)> (http) 	HOST: "localhost", HOST_LEN: 9,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1624 (url_describe)> (http) 	PORT: "4090", PORT_LEN: 4, PORT_NUM: 4090
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1625 (url_describe)> (http) 	PATH: "aaa", PATH_LEN: 3,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1627 (url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1629 (url_describe)> (http) 	QUERY: "", QUERY_LEN: 0,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1631 (url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x7fffedaea8b8: [T: 4, L:  592, OBJFLAGS: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2681 (mime_hdr_describe)> (http)
	[PBITS: 0x0000000001004800, SLACC: 0xFFFFFFFFFFFF1FF0FFFFFFFFFFFFFFFF, HEADBLK: 0x7fffedaea8f8, TAILBLK: 0x7fffedaea8f8]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2686 (mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x7fffedaea8f8: [T: 5, L:  528, OBJFLAGS: 0]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2702 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 0 (0x7fffedaea908), LIVE
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Connection", N_LEN: 10, N_IDX: 12,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "keep-alive", V_LEN: 10,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 1 (0x7fffedaea928), LIVE
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "6000", V_LEN: 4,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) 	SLOT # 2 (0x7fffedaea948), LIVE
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "localhost:4090", V_LEN: 14,
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 22, F: 1]
[Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http)
+++++++++ Incoming Request +++++++++
-- State Machine Id: 0
POST http://localhost:4090/aaa HTTP/1.1
Connection: keep-alive
Content-Length:6000
Host: localhost:4090

[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1815 (DecideCacheLookup)> (http_trans) [0] [DecideCacheLookup] Will do cache lookup.
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1816 (DecideCacheLookup)> (http_seq) [0] [DecideCacheLookup] Will do cache lookup
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1859 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; nullptr
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4497 (do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read] [0] Issuing cache lookup for URL http://localhost:4090/aaa
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpCacheSM.cc:118 (state_cache_open_read)> (http_cache) [0] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ_FAILED]
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2512 (state_cache_open_read)> (http) [0] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2546 (state_cache_open_read)> (http) [0] cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with ECACHE_NO_DOC (-20400)
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2548 (state_cache_open_read)> (http) [state_cache_open_read] open read failed.
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2072 (HandleCacheOpenRead)> (http_trans) [0] [HttpTransact::HandleCacheOpenRead]
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2102 (HandleCacheOpenRead)> (http_trans) [0] CacheOpenRead -- miss
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2959 (HandleCacheOpenReadMiss)> (http_trans) [0] [HandleCacheOpenReadMiss] --- MISS
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2961 (HandleCacheOpenReadMiss)> (http_seq) [0] [HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:4919 (get_ka_info_from_config)> (http_trans) [0] get_ka_info_from_config, server_info->http_version 65537, check_hostdb 0
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:3018 (HandleCacheOpenReadMiss)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; OSDNSLookup
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_DNS_LOOKUP
[Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4083 (do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, EVENT_HOST_DB_LOOKUP]
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2233 (state_hostdb_lookup)> (http) [0] [&HttpSM::state_hostdb_lookup, EVENT_HOST_DB_LOOKUP]
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1543 (OSDNSLookup)> (http_trans) [0] [HttpTransact::OSDNSLookup] This was attempt 0
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1605 (OSDNSLookup)> (http_seq) [0] [HttpTransact::OSDNSLookup] DNS Lookup successful
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1644 (OSDNSLookup)> (http_trans) [0] [OSDNSLookup] DNS lookup for O.S. successful IP: 127.0.0.1
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1713 (OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS; HandleCacheOpenReadMiss
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2959 (HandleCacheOpenReadMiss)> (http_trans) [0] [HandleCacheOpenReadMiss] --- MISS
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2961 (HandleCacheOpenReadMiss)> (http_seq) [0] [HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:5018 (add_client_ip_to_outgoing_request)> (http_trans) [0] client_ip_set = 0
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:5031 (add_client_ip_to_outgoing_request)> (http_trans) [0] [add_client_ip_to_outgoing_request] Appended connecting client's (127.0.0.1) to the X-Forwards header
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:7581 (build_request)> (http_trans) [0] [build_request] removing host name from url
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:7604 (build_request)> (http_trans) [0] [build_request] request not like cacheable and conditional headers not removed
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:7622 (build_request)> (http_trans) [0] [build_request] request_sent_time: 1511855370
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 0
POST /aaa HTTP/1.1
Content-Length:6000
Host: localhost:4090
X-Forwarded-For: 127.0.0.1
Via: http/1.1 zizhang-ld2[b989e784-e78f-42ae-ad07-2d6c766da4d5] (ApacheTrafficServer/8.0.0)

[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_ORIGIN_SERVER_OPEN
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4658 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4685 (do_http_server_open)> (http) [0] open connection to localhost: 127.0.0.1:4090
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4697 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSessionManager.cc:319 (acquire_session)> (http_ss) [acquire session] thread pool search failed
[Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:5045 (do_http_server_open)> (http) calling netProcessor.connect_s
[Nov 27 23:49:30.906] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN]
[Nov 27 23:49:30.906] Server {0x7fffef830700} DEBUG: <HttpSM.cc:1735 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Nov 27 23:49:30.906] Server {0x7fffef830700} DEBUG: <HttpSM.cc:1736 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
[Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpSM.cc:1756 (state_http_server_open)> (http_ss) [0] max number of connections: 20000
[Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpServerSession.cc:85 (new_connection)> (http_ss) [0] new connection, ip: 127.0.0.1:4090, count: 1
[Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpServerSession.cc:93 (new_connection)> (http_ss) [0] session born, netvc 0x7fff6c018a00
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 0
POST /aaa HTTP/1.1
Content-Length:6000
Host: localhost:4090
X-Forwarded-For: 127.0.0.1
Via: http/1.1 zizhang-ld2[b989e784-e78f-42ae-ad07-2d6c766da4d5] (ApacheTrafficServer/8.0.0)

[Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2001 (state_send_server_request_header)> (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8071 (init)> (http_redirect) [PostDataBuffers::init]
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:657 (add_producer)> (http_tunnel) [0] adding producer 'user agent post'
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:712 (add_consumer)> (http_tunnel) [0] adding consumer 'http server post'
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:759 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:957 (producer_run)> (http_redirect) [HttpTunnel::producer_run] client post: 0 max size: 2048
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 0 bytes to buffers 0
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 200
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 400
[Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 600
[Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 800
[Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1000
[Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1200
[Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1400
[Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1600
[Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1800
[Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 2000
[Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100
[Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1165 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] post exceeds buffer limit, buffer_avail=2000 reader_avail=200 limit=2048
[Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8089 (clear)> (http_redirect) [PostDataBuffers::clear]
[Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]
[Nov 27 23:49:32.008] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY]
[Nov 27 23:49:32.008] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Nov 27 23:49:32.008] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY]

Program received signal SIGPIPE, Broken pipe.
[Switching to Thread 0x7fffef830700 (LWP 114996)]
0x0000003033ee09e7 in writev () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install LNKD-openssl-1.0.2h-0.2.11.el6.x86_64 glibc-2.12-1.149.el6_6.5.x86_64 hwloc-1.5-3.el6_5.x86_64 keyutils-libs-1.4-5.el6.x86_64 krb5-libs-1.10.3-33.el6.x86_64 libcom_err-1.41.12-21.el6.x86_64 libgcc-4.4.7-11.el6.x86_64 libselinux-2.0.94-5.8.el6.x86_64 libstdc++-4.4.7-11.el6.x86_64 libxml2-2.7.6-17.el6_6.1.x86_64 numactl-2.0.9-2.el6.x86_64 pciutils-libs-3.1.10-4.el6.x86_64 pcre-7.8-6.el6.x86_64 tcl-8.5.7-6.el6.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) bt
#0  0x0000003033ee09e7 in writev () from /lib64/libc.so.6
#1  0x00000000007b3af8 in SocketManager::writev (this=0xc81980 <socketManager>, fd=83, vector=0x7fffef82b9f0, count=1)
    at /home/zizhang/baseline/trafficserver/iocore/eventsystem/P_UnixSocketManager.h:219
#2  0x00000000007b18da in UnixNetVConnection::load_buffer_and_write (this=0x7fff6c018a00, towrite=200, buf=...,
    total_written=@0x7fffef82faa0: 0, needs=@0x7fffef82faac: 0) at UnixNetVConnection.cc:989
#3  0x00000000007afc03 in write_to_net_io (nh=0x7ffff4fc4c00, vc=0x7fff6c018a00, thread=0x7ffff4fc1010)
    at UnixNetVConnection.cc:463
#4  0x00000000007af6f0 in write_to_net (nh=0x7ffff4fc4c00, vc=0x7fff6c018a00, thread=0x7ffff4fc1010)
    at UnixNetVConnection.cc:359
#5  0x00000000007a562b in NetHandler::process_ready_list (this=0x7ffff4fc4c00) at UnixNet.cc:421
#6  0x00000000007a5cc6 in NetHandler::waitForActivity (this=0x7ffff4fc4c00, timeout=60000000) at UnixNet.cc:531
#7  0x00000000007d92c1 in EThread::execute_regular (this=0x7ffff4fc1010) at UnixEThread.cc:271
#8  0x00000000007d94bb in EThread::execute (this=0x7ffff4fc1010) at UnixEThread.cc:324
#9  0x00000000007d7ee2 in spawn_thread_internal (a=0xd154d0) at Thread.cc:85
#10 0x00007ffff72699d1 in start_thread () from /lib64/libpthread.so.0
#11 0x0000003033ee88fd in clone () from /lib64/libc.so.6

[zizhong]

Wait, is it an expected behavior to return HTTP/1.1 502 Server Hangup when the post body exceeds the limit?

[scw00]

Can you please attach the backtrace ?

Yes , big data post redirection will be disabled if post body exceeds the limit.

[zizhong]

Already in the first post. Please note the post body is exceeding the limit and the client got 502. Is it expected?

[scw00]

I think we can't get the body's length in the first times if it is a post chunk request.

So the origin code will collect the body until it exceed the limit, then disable redirect directly.

  // YTS Team, yamsat Plugin
  // Allocate and copy partial POST data to buffers. Check for the various parameters
  // including the maximum configured post data size
  if (p->alive && sm->t_state.method == HTTP_WKSIDX_POST && sm->enable_redirection && (p->vc_type == HT_HTTP_CLIENT)) {
    Debug("http_redirect", "[HttpTunnel::producer_run] client post: %" PRId64 " max size: %" PRId64 "",
          p->buffer_start->read_avail(), HttpConfig::m_master.post_copy_size);

    // (note that since we are not dechunking POST, this is the chunked size if chunked)
    if (p->buffer_start->read_avail() > HttpConfig::m_master.post_copy_size) {
      Debug("http_redirect", "[HttpTunnel::producer_handler] post exceeds buffer limit, buffer_avail=%" PRId64 " limit=%" PRId64 "",
            p->buffer_start->read_avail(), HttpConfig::m_master.post_copy_size);
      sm->disable_redirect();
    } else {
      sm->postbuf_copy_partial_data();
    }
  } 

[zizhong]

However, it's not chunked. It's a post with content-length.

[scw00]

Yes, May be we can do some fixes with not chunk post request .

[zizhong]

I tried a much bigger limit CONFIG proxy.config.http.post_copy_size INT 80000000. ATS can still get the SIGPIPE and the client still gets 502. We have a real issue here.

[scw00]

Sorry, I can't get the SIGPIPE with 50M data

> POST /a HTTP/1.1
> User-Agent: curl/7.35.0
> Host: 127.0.0.1:8080
> Accept: */*
> Content-Length: 52429001
> Expect: 100-continue
> Content-Type: multipart/form-data; boundary=------------------------5655713ecc8f06a6
> 
* Done waiting for 100-continue
< HTTP/1.1 100 Continue
< Date: Tue, 28 Nov 2017 08:38:35 GMT
* Server ATS/8.0.0 is not blacklisted
< Server: ATS/8.0.0
< HTTP/1.1 200 OK
* Server ATS/8.0.0 is not blacklisted
< Server: ATS/8.0.0
< Date: Tue, 28 Nov 2017 08:38:35 GMT
< Content-Type: application/octet-stream
< Age: 0
< Transfer-Encoding: chunked
< Connection: keep-alive
< 
hello

ats conf

CONFIG proxy.config.http.post_copy_size INT 80000000
CONFIG proxy.config.http.number_of_redirections INT 3
CONFIG proxy.config.http.redirection_enabled INT 1 

nginx.conf

http {
    include       mime.types;
    default_type  application/octet-stream;


    sendfile        on;
    keepalive_timeout  65;
    client_max_body_size 999999999;


    server {
        listen       80;
        server_name  localhost;

        location / {
            rewrite .* /scw1 redirect;
        }

        location /scw1 {
          rewrite .* /scw2 redirect;
        }

        location /scw2 {
          content_by_lua 'ngx.say("hello")';
        }

        error_page   500 502 503 504  /50x.html;
        location = /50x.html {
            root   html;
        }

    }

}

How to re-product that?

[oknet]

To debug ATS by gdb, please ignore SIGPIPE first with gdb command : handle sigpipe ignore noprint nostop

…

在 2017年11月28日，15:52，zizhong,zhang ***@***.***> 写道： @scw00 @oknet I guess it's related to #2766, but when I tried the older version I got some other crashes. Nov 27 23:49:30.815] Server {0x7fffef830700} DEBUG: <ProtocolProbeSessionAccept.cc:139 (mainEvent)> (http) probe needs data, read.. [Nov 27 23:49:30.816] Server {0x7fffef830700} DEBUG: <HttpSessionAccept.cc:58 (accept)> (http_seq) [HttpSessionAccept:mainEvent 0x7fff6c018d00] accepted connection from 127.0.0.1:60296 transport type = 1 [Nov 27 23:49:30.817] Server {0x7fffef830700} DEBUG: <Http1ClientSession.cc:200 (new_connection)> (http_cs) [0] session born, netvc 0x7fff6c018d00 [Nov 27 23:49:30.817] Server {0x7fffef830700} DEBUG: <Http1ClientSession.cc:230 (do_io_write)> (http_cs) tcp_init_cwnd_set 0 [Nov 27 23:49:30.817] Server {0x7fffef830700} DEBUG: <Http1ClientSession.cc:467 (release)> (http_cs) [0] data already in buffer, starting new transaction [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <ProxyClientTransaction.cc:52 (new_transaction)> (http_txn) [0] Starting transaction 1 using sm [0] [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:362 (state_add_to_list)> (http) [0] [&HttpSM::state_add_to_list, VC_EVENT_NONE] [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY] [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:576 (state_read_client_request_header)> (http) [0] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY] [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:723 (state_read_client_request_header)> (http) [0] done parsing client request header [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:988 (ModifyRequest)> (http_trans) [0] START HttpTransact::ModifyRequest [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1062 (ModifyRequest)> (http_trans) [0] END HttpTransact::ModifyRequest [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1063 (ModifyRequest)> (http_trans) [0] Checking if transaction wants to upgrade [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1071 (ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:595 (StartRemapRequest)> (http_trans) [0] START HttpTransact::StartRemapRequest [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:635 (StartRemapRequest)> (http_trans) [0] Before Remapping: [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x7fffedaea888: [T: 3, L: 48, OBJFLAGS: 0] [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x7fffedaeab08, METHOD: "POST", METHOD_LEN: 4, FIELDS: 0x7fffedaea8b8] [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x7fffedaeab08: [T: 2, L: 112, OBJFLAGS: 0] [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <URL.cc:1616 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99, [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <URL.cc:1618 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4, [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <URL.cc:1619 (url_describe)> (http) USER: "", USER_LEN: 0, [Nov 27 23:49:30.823] Server {0x7fffef830700} DEBUG: <URL.cc:1621 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1622 (url_describe)> (http) HOST: "", HOST_LEN: 0, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1624 (url_describe)> (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0 [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1625 (url_describe)> (http) PATH: "aaa", PATH_LEN: 3, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1627 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1629 (url_describe)> (http) QUERY: "", QUERY_LEN: 0, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1631 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x7fffedaea8b8: [T: 4, L: 592, OBJFLAGS: 0] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2681 (mime_hdr_describe)> (http) [PBITS: 0x0000000001004800, SLACC: 0xFFFFFFFFFFFF1FF0FFFFFFFFFFFFFFFF, HEADBLK: 0x7fffedaea8f8, TAILBLK: 0x7fffedaea8f8] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2686 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x7fffedaea8f8: [T: 5, L: 528, OBJFLAGS: 0] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2702 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 0 (0x7fffedaea908), LIVE [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Connection", N_LEN: 10, N_IDX: 12, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "keep-alive", V_LEN: 10, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 1 (0x7fffedaea928), LIVE [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "6000", V_LEN: 4, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 2 (0x7fffedaea948), LIVE [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "127.0.0.1", V_LEN: 9, [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 17, F: 1] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:645 (StartRemapRequest)> (http_trans) [0] END HttpTransact::StartRemapRequest [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:646 (StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:652 (PerformRemap)> (http_trans) [0] Inside PerformRemap [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:653 (PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpSM.cc:3977 (do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:659 (EndRemapRequest)> (http_trans) [0] START HttpTransact::EndRemapRequest [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:665 (EndRemapRequest)> (http_trans) [0] EndRemapRequest host is localhost [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:803 (EndRemapRequest)> (http_trans) [0] After Remapping: [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x7fffedaea888: [T: 3, L: 48, OBJFLAGS: 0] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x7fffedaeab08, METHOD: "POST", METHOD_LEN: 4, FIELDS: 0x7fffedaea8b8] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x7fffedaeab08: [T: 2, L: 112, OBJFLAGS: 0] [Nov 27 23:49:30.824] Server {0x7fffef830700} DEBUG: <URL.cc:1616 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1618 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1619 (url_describe)> (http) USER: "", USER_LEN: 0, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1621 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1622 (url_describe)> (http) HOST: "localhost", HOST_LEN: 9, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1624 (url_describe)> (http) PORT: "4090", PORT_LEN: 4, PORT_NUM: 4090 [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1625 (url_describe)> (http) PATH: "aaa", PATH_LEN: 3, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1627 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1629 (url_describe)> (http) QUERY: "", QUERY_LEN: 0, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1631 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x7fffedaea8b8: [T: 4, L: 592, OBJFLAGS: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2681 (mime_hdr_describe)> (http) [PBITS: 0x0000000001004800, SLACC: 0xFFFFFFFFFFFF1FF0FFFFFFFFFFFFFFFF, HEADBLK: 0x7fffedaea8f8, TAILBLK: 0x7fffedaea8f8] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2686 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x7fffedaea8f8: [T: 5, L: 528, OBJFLAGS: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2702 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 0 (0x7fffedaea908), LIVE [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Connection", N_LEN: 10, N_IDX: 12, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "keep-alive", V_LEN: 10, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 1 (0x7fffedaea928), LIVE [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "6000", V_LEN: 4, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 2 (0x7fffedaea948), LIVE [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "localhost:4090", V_LEN: 14, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 22, F: 1] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:822 (EndRemapRequest)> (http_trans) [0] END HttpTransact::EndRemapRequest [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:828 (EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1108 (HandleRequest)> (http_trans) [0] START HttpTransact::HandleRequest [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:5099 (check_request_validity)> (http_trans) [0] [init_stat_vars_from_req] set req cont length to 6000 [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:6154 (is_request_valid)> (http_trans) [0] [is_request_valid] no request header errors [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1129 (HandleRequest)> (http_seq) [0] [HttpTransact::HandleRequest] request valid. [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x7fffedaea888: [T: 3, L: 48, OBJFLAGS: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x7fffedaeab08, METHOD: "POST", METHOD_LEN: 4, FIELDS: 0x7fffedaea8b8] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x7fffedaeab08: [T: 2, L: 112, OBJFLAGS: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1616 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1618 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1619 (url_describe)> (http) USER: "", USER_LEN: 0, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1621 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1622 (url_describe)> (http) HOST: "localhost", HOST_LEN: 9, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1624 (url_describe)> (http) PORT: "4090", PORT_LEN: 4, PORT_NUM: 4090 [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1625 (url_describe)> (http) PATH: "aaa", PATH_LEN: 3, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1627 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1629 (url_describe)> (http) QUERY: "", QUERY_LEN: 0, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <URL.cc:1631 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x7fffedaea8b8: [T: 4, L: 592, OBJFLAGS: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2681 (mime_hdr_describe)> (http) [PBITS: 0x0000000001004800, SLACC: 0xFFFFFFFFFFFF1FF0FFFFFFFFFFFFFFFF, HEADBLK: 0x7fffedaea8f8, TAILBLK: 0x7fffedaea8f8] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2686 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x7fffedaea8f8: [T: 5, L: 528, OBJFLAGS: 0] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2702 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 0 (0x7fffedaea908), LIVE [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Connection", N_LEN: 10, N_IDX: 12, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "keep-alive", V_LEN: 10, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 1 (0x7fffedaea928), LIVE [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "6000", V_LEN: 4, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2706 (mime_field_block_describe)> (http) SLOT # 2 (0x7fffedaea948), LIVE [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2716 (mime_field_block_describe)> (http) V: "localhost:4090", V_LEN: 14, [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2718 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 22, F: 1] [Nov 27 23:49:30.825] Server {0x7fffef830700} DEBUG: <MIME.cc:2721 (mime_field_block_describe)> (http) +++++++++ Incoming Request +++++++++ -- State Machine Id: 0 POST http://localhost:4090/aaa HTTP/1.1 Connection: keep-alive Content-Length:6000 Host: localhost:4090 [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1815 (DecideCacheLookup)> (http_trans) [0] [DecideCacheLookup] Will do cache lookup. [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1816 (DecideCacheLookup)> (http_seq) [0] [DecideCacheLookup] Will do cache lookup [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1859 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; nullptr [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4497 (do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read] [0] Issuing cache lookup for URL http://localhost:4090/aaa [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpCacheSM.cc:118 (state_cache_open_read)> (http_cache) [0] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED] [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ_FAILED] [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2512 (state_cache_open_read)> (http) [0] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED] [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2546 (state_cache_open_read)> (http) [0] cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with ECACHE_NO_DOC (-20400) [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2548 (state_cache_open_read)> (http) [state_cache_open_read] open read failed. [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2072 (HandleCacheOpenRead)> (http_trans) [0] [HttpTransact::HandleCacheOpenRead] [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2102 (HandleCacheOpenRead)> (http_trans) [0] CacheOpenRead -- miss [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2959 (HandleCacheOpenReadMiss)> (http_trans) [0] [HandleCacheOpenReadMiss] --- MISS [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2961 (HandleCacheOpenReadMiss)> (http_seq) [0] [HttpTransact::HandleCacheOpenReadMiss] Miss in cache [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:4919 (get_ka_info_from_config)> (http_trans) [0] get_ka_info_from_config, server_info->http_version 65537, check_hostdb 0 [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:3018 (HandleCacheOpenReadMiss)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; OSDNSLookup [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_DNS_LOOKUP [Nov 27 23:49:30.826] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4083 (do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, EVENT_HOST_DB_LOOKUP] [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2233 (state_hostdb_lookup)> (http) [0] [&HttpSM::state_hostdb_lookup, EVENT_HOST_DB_LOOKUP] [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1543 (OSDNSLookup)> (http_trans) [0] [HttpTransact::OSDNSLookup] This was attempt 0 [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1605 (OSDNSLookup)> (http_seq) [0] [HttpTransact::OSDNSLookup] DNS Lookup successful [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1644 (OSDNSLookup)> (http_trans) [0] [OSDNSLookup] DNS lookup for O.S. successful IP: 127.0.0.1 [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:1713 (OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS; HandleCacheOpenReadMiss [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2959 (HandleCacheOpenReadMiss)> (http_trans) [0] [HandleCacheOpenReadMiss] --- MISS [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:2961 (HandleCacheOpenReadMiss)> (http_seq) [0] [HttpTransact::HandleCacheOpenReadMiss] Miss in cache [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:5018 (add_client_ip_to_outgoing_request)> (http_trans) [0] client_ip_set = 0 [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:5031 (add_client_ip_to_outgoing_request)> (http_trans) [0] [add_client_ip_to_outgoing_request] Appended connecting client's (127.0.0.1) to the X-Forwards header [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:7581 (build_request)> (http_trans) [0] [build_request] removing host name from url [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:7604 (build_request)> (http_trans) [0] [build_request] request not like cacheable and conditional headers not removed [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpTransact.cc:7622 (build_request)> (http_trans) [0] [build_request] request_sent_time: 1511855370 +++++++++ Proxy's Request +++++++++ -- State Machine Id: 0 POST /aaa HTTP/1.1 Content-Length:6000 Host: localhost:4090 X-Forwarded-For: 127.0.0.1 Via: http/1.1 zizhang-ld2[b989e784-e78f-42ae-ad07-2d6c766da4d5] (ApacheTrafficServer/8.0.0) [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:7152 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_ORIGIN_SERVER_OPEN [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4658 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4] [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4685 (do_http_server_open)> (http) [0] open connection to localhost: 127.0.0.1:4090 [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:4697 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSessionManager.cc:319 (acquire_session)> (http_ss) [acquire session] thread pool search failed [Nov 27 23:49:30.905] Server {0x7fffef830700} DEBUG: <HttpSM.cc:5045 (do_http_server_open)> (http) calling netProcessor.connect_s [Nov 27 23:49:30.906] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN] [Nov 27 23:49:30.906] Server {0x7fffef830700} DEBUG: <HttpSM.cc:1735 (state_http_server_open)> (http_track) entered inside state_http_server_open [Nov 27 23:49:30.906] Server {0x7fffef830700} DEBUG: <HttpSM.cc:1736 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN] [Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpSM.cc:1756 (state_http_server_open)> (http_ss) [0] max number of connections: 20000 [Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpServerSession.cc:85 (new_connection)> (http_ss) [0] new connection, ip: 127.0.0.1:4090, count: 1 [Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpServerSession.cc:93 (new_connection)> (http_ss) [0] session born, netvc 0x7fff6c018a00 +++++++++ Proxy's Request after hooks +++++++++ -- State Machine Id: 0 POST /aaa HTTP/1.1 Content-Length:6000 Host: localhost:4090 X-Forwarded-For: 127.0.0.1 Via: http/1.1 zizhang-ld2[b989e784-e78f-42ae-ad07-2d6c766da4d5] (ApacheTrafficServer/8.0.0) [Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2581 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE] [Nov 27 23:49:30.907] Server {0x7fffef830700} DEBUG: <HttpSM.cc:2001 (state_send_server_request_header)> (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE] [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8071 (init)> (http_redirect) [PostDataBuffers::init] [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:657 (add_producer)> (http_tunnel) [0] adding producer 'user agent post' [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:712 (add_consumer)> (http_tunnel) [0] adding consumer 'http server post' [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:759 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:957 (producer_run)> (http_redirect) [HttpTunnel::producer_run] client post: 0 max size: 2048 [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 0 bytes to buffers 0 [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 200 [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:30.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 400 [Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.006] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 600 [Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.106] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 800 [Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.206] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1000 [Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.306] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1200 [Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.407] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1400 [Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.507] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1600 [Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.607] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 1800 [Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.707] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8062 (copy_partial_post_data)> (http_redirect) [PostDataBuffers::copy_partial_post_data] wrote 200 bytes to buffers 2000 [Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 1 0] event: 100 [Nov 27 23:49:31.807] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1160 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1165 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] post exceeds buffer limit, buffer_avail=2000 reader_avail=200 limit=2048 [Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpSM.cc:8089 (clear)> (http_redirect) [PostDataBuffers::clear] [Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100 [Nov 27 23:49:31.908] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] [Nov 27 23:49:32.008] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1136 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY] [Nov 27 23:49:32.008] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1173 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100 [Nov 27 23:49:32.008] Server {0x7fffef830700} DEBUG: <HttpTunnel.cc:1332 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY] Program received signal SIGPIPE, Broken pipe. [Switching to Thread 0x7fffef830700 (LWP 114996)] 0x0000003033ee09e7 in writev () from /lib64/libc.so.6 Missing separate debuginfos, use: debuginfo-install LNKD-openssl-1.0.2h-0.2.11.el6.x86_64 glibc-2.12-1.149.el6_6.5.x86_64 hwloc-1.5-3.el6_5.x86_64 keyutils-libs-1.4-5.el6.x86_64 krb5-libs-1.10.3-33.el6.x86_64 libcom_err-1.41.12-21.el6.x86_64 libgcc-4.4.7-11.el6.x86_64 libselinux-2.0.94-5.8.el6.x86_64 libstdc++-4.4.7-11.el6.x86_64 libxml2-2.7.6-17.el6_6.1.x86_64 numactl-2.0.9-2.el6.x86_64 pciutils-libs-3.1.10-4.el6.x86_64 pcre-7.8-6.el6.x86_64 tcl-8.5.7-6.el6.x86_64 zlib-1.2.3-29.el6.x86_64 (gdb) bt #0 0x0000003033ee09e7 in writev () from /lib64/libc.so.6 #1 0x00000000007b3af8 in SocketManager::writev (this=0xc81980 <socketManager>, fd=83, vector=0x7fffef82b9f0, count=1) at /home/zizhang/baseline/trafficserver/iocore/eventsystem/P_UnixSocketManager.h:219 #2 0x00000000007b18da in UnixNetVConnection::load_buffer_and_write (this=0x7fff6c018a00, towrite=200, buf=..., ***@***.***: 0, ***@***.***: 0) at UnixNetVConnection.cc:989 #3 0x00000000007afc03 in write_to_net_io (nh=0x7ffff4fc4c00, vc=0x7fff6c018a00, thread=0x7ffff4fc1010) at UnixNetVConnection.cc:463 #4 0x00000000007af6f0 in write_to_net (nh=0x7ffff4fc4c00, vc=0x7fff6c018a00, thread=0x7ffff4fc1010) at UnixNetVConnection.cc:359 #5 0x00000000007a562b in NetHandler::process_ready_list (this=0x7ffff4fc4c00) at UnixNet.cc:421 #6 0x00000000007a5cc6 in NetHandler::waitForActivity (this=0x7ffff4fc4c00, timeout=60000000) at UnixNet.cc:531 #7 0x00000000007d92c1 in EThread::execute_regular (this=0x7ffff4fc1010) at UnixEThread.cc:271 #8 0x00000000007d94bb in EThread::execute (this=0x7ffff4fc1010) at UnixEThread.cc:324 #9 0x00000000007d7ee2 in spawn_thread_internal (a=0xd154d0) at Thread.cc:85 #10 0x00007ffff72699d1 in start_thread () from /lib64/libpthread.so.0 #11 0x0000003033ee88fd in clone () from /lib64/libc.so.6 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

[zizhong]

Thanks, @scw00 @oknet I guess it's a bug in the python server. It cannot handle big post body. Closing this issue.

[zizhong]

A related issue is pallets/flask#1974