masaori335 edited a comment on issue #7915: URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853639438
Debug log with `http` tag is more interesting. It might be some bug around connect retry and dechunk. I'm not sure how #7809 is related. It's possible I'm tracking another bug. <details><summary>Debug logs of good case</summary> ``` +++++++++ Proxy's Request +++++++++ -- State Machine Id: 0 POST / HTTP/1.1 Host: 127.0.0.1:61000 Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0) [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:2243 (LookupSkipOpenServer)> (http_trans) Next action next; HttpTransact::HandleResponse [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_ORIGIN_SERVER_OPEN [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4] [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [0] open connection to 127.0.0.1: 127.0.0.1:61000 [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [0] max_proxy_cycles = 0 [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [0] dst_port = 61000 local_port = 61003 [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [0] count = 0 <= max_proxy_cycles = 0 : allowing loop [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed [Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [1] session born, netvc 0x7fffec061c40 [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [0] setting handler for TCP handshake [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [0] receiving frame header [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [0] frame header length=16384, type=0, flags=0x1, streamid=1 [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [0] completed frame read, 16384 bytes available [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [0] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535 [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:971 (state_watch_for_client_abort)> (http) [0] [&HttpSM::state_watch_for_client_abort, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [0] TCP Handshake complete +++++++++ Proxy's Request after hooks +++++++++ -- State Machine Id: 0 POST / HTTP/1.1 Host: 127.0.0.1:61000 Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0) Transfer-Encoding: chunked [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [0] adding producer 'user agent post' [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [0] adding consumer 'http server post' [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [0] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9 [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [0] producer_handler_dechunked [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [0 0 0] event: 102, state: 10 [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:3579 (tunnel_handler_post_ua)> (http) [0] [&HttpSM::tunnel_handler_post_ua, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:3685 (tunnel_handler_post_server)> (http) [0] [&HttpSM::tunnel_handler_post_server, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE] [Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2787 (tunnel_handler_post)> (http) [0] [&HttpSM::tunnel_handler_post, HTTP_TUNNEL_EVENT_DONE] [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:1959 (state_read_server_response_header)> (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:2067 (state_read_server_response_header)> (http_seq) Done parsing server response header [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:8308 (clear)> (http_redirect) [PostDataBuffers::clear] [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3468 (HandleResponse)> (http_trans) [0] [HttpTransact::HandleResponse] [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3469 (HandleResponse)> (http_seq) [0] [HttpTransact::HandleResponse] Response received [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3476 (HandleResponse)> (http_trans) [0] [HandleResponse] response_received_time: 1622704296 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 0 HTTP/1.1 405 METHOD NOT ALLOWED Server: gunicorn Date: Thu, 03 Jun 2021 07:11:36 GMT Connection: close Content-Type: text/html; charset=utf-8 Allow: HEAD, GET, OPTIONS Content-Length: 178 Access-Control-Allow-Origin: * Access-Control-Allow-Credentials: true [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:334 (is_response_valid)> (http_trans) [0] [is_response_valid] No errors in response [Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3493 (HandleResponse)> (http_seq) [0] [HttpTransact::HandleResponse] Response valid ``` </details> <details><summary>Debug logs of bad case</summary> ``` +++++++++ Proxy's Request +++++++++ -- State Machine Id: 2 POST / HTTP/1.1 Host: 127.0.0.1:61000 Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0) [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:2243 (LookupSkipOpenServer)> (http_trans) Next action next; HttpTransact::HandleResponse [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_ORIGIN_SERVER_OPEN [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4] [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [2] open connection to 127.0.0.1: 127.0.0.1:61000 [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [2] max_proxy_cycles = 0 [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [2] dst_port = 61000 local_port = 61003 [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [2] count = 0 <= max_proxy_cycles = 0 : allowing loop [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT] [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT] [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [5] session born, netvc 0x7fffec0614c0 [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [2] setting handler for TCP handshake [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [4] receiving frame header [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [4] frame header length=16384, type=0, flags=0x1, streamid=1 [Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [4] completed frame read, 16384 bytes available [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [4] [1] Received DATA frame [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [4] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535 [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:971 (state_watch_for_client_abort)> (http) [2] [&HttpSM::state_watch_for_client_abort, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [2] TCP Handshake complete +++++++++ Proxy's Request after hooks +++++++++ -- State Machine Id: 2 POST / HTTP/1.1 Host: 127.0.0.1:61000 Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0) Transfer-Encoding: chunked [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [2] adding producer 'user agent post' [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [2] adding consumer 'http server post' [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9 [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [0 0 0] event: 102, state: 10 [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:3579 (tunnel_handler_post_ua)> (http) [2] [&HttpSM::tunnel_handler_post_ua, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:3685 (tunnel_handler_post_server)> (http) [2] [&HttpSM::tunnel_handler_post_server, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE] [Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2787 (tunnel_handler_post)> (http) [2] [&HttpSM::tunnel_handler_post, HTTP_TUNNEL_EVENT_DONE] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1959 (state_read_server_response_header)> (http) [2] [&HttpSM::state_read_server_response_header, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:5636 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <Http1ServerSession.cc:138 (do_io_close)> (http_ss) [5] session close: nevtc 0x7fffec0614c0 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3468 (HandleResponse)> (http_trans) [2] [HttpTransact::HandleResponse] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3469 (HandleResponse)> (http_seq) [2] [HttpTransact::HandleResponse] Response received [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3476 (HandleResponse)> (http_trans) [2] [HandleResponse] response_received_time: 1622704426 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 2 HTTP/1.0 0 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3491 (HandleResponse)> (http_seq) [2] [HttpTransact::HandleResponse] Response not valid [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3760 (handle_response_from_server)> (http_trans) [2] [handle_response_from_server] (hrfs) [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3798 (handle_response_from_server)> (http_trans) [2] max_connect_retries: 3 s->current.attempts: 0 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3892 (error_log_connection_failure)> (http_trans) [2] [0] failed to connect [5] to 127.0.0.1 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3942 (retry_server_connection_not_open)> (http_trans) [2] [retry_server_connection_not_open] attempts now: 1, max: 3 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3822 (handle_response_from_server)> (http_trans) [2] [handle_response_from_server] Error. Retrying... [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_ORIGIN_SERVER_OPEN [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [2] open connection to 127.0.0.1: 127.0.0.1:61000 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [2] max_proxy_cycles = 0 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [2] dst_port = 61000 local_port = 61003 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [2] count = 0 <= max_proxy_cycles = 0 : allowing loop [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [6] session born, netvc 0x7fffec061100 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [2] setting handler for TCP handshake [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [2] TCP Handshake complete +++++++++ Proxy's Request after hooks +++++++++ -- State Machine Id: 2 POST / HTTP/1.1 Host: 127.0.0.1:61000 Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0) Transfer-Encoding: chunked, chunked [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [2] adding producer 'user agent post' [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [2] adding consumer 'http server post' [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9 [Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] # timeout ``` </details> -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected]
