kanseiishikawa commented on issue #12632: URL: https://github.com/apache/trafficserver/issues/12632#issuecomment-3486218948
this is debug log ``` [Nov 4 14:10:23.234] [ET_NET 1] DEBUG: <Http1ClientSession.cc:191 (new_connection)> (http_cs) [9] session born, netvc 0x7f6ec801e880 [Nov 4 14:10:23.234] [ET_NET 1] DEBUG: <Http1ClientSession.cc:430 (release)> (http_cs) [9] data already in buffer, starting new transaction [Nov 4 14:10:23.234] [ET_NET 1] DEBUG: <ProxyTransaction.cc:50 (new_transaction)> (http_txn) [9] Starting transaction 1 using sm [8] [Nov 4 14:10:23.235] [ET_NET 1] DEBUG: <Http1ClientSession.cc:433 (release)> (http_cs) [9] initiating io for next header [Nov 4 14:10:23.239] [ET_NET 1] DEBUG: <Http1ClientSession.cc:374 (state_keep_alive)> (http_cs) [9] [&Http1ClientSession::state_keep_alive, VC_EVENT_EOS/TS_EVENT_VCONN_EOS] [Nov 4 14:10:23.239] [ET_NET 1] DEBUG: <Http1ClientSession.cc:265 (do_io_close)> (http_cs) [9] session closed [Nov 4 14:10:23.239] [ET_NET 1] DEBUG: <Http1ClientSession.cc:75 (destroy)> (http_cs) [9] session destroy [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <ProxyTransaction.cc:50 (new_transaction)> (http_txn) [10] Starting transaction 1 using sm [9] [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpSM.cc:2741 (main_handler)> (http) [9] VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY, 100 [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpSM.cc:686 (state_read_client_request_header)> (http) [9] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpSM.cc:842 (state_read_client_request_header)> (http) [9] done parsing client request header [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:5564 (set_client_request_state)> (http_trans) [9] set req cont length to -1 [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:1364 (ModifyRequest)> (http_trans) [9] START HttpTransact::ModifyRequest [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:1438 (ModifyRequest)> (http_trans) [9] END HttpTransact::ModifyRequest [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:975 (StartRemapRequest)> (http_trans) [9] START HttpTransact::StartRemapRequest [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:995 (StartRemapRequest)> (http_trans) [9] Before Remapping: [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:1007 (StartRemapRequest)> (http_trans) [9] END HttpTransact::StartRemapRequest [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:1009 (StartRemapRequest)> (http_trans) [9] Checking if transaction wants to upgrade [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:1022 (PerformRemap)> (http_trans) [9] Inside PerformRemap [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpSM.cc:4222 (do_remap_request)> (http_seq) [9] Remapping request [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:1029 (EndRemapRequest)> (http_trans) [9] START HttpTransact::EndRemapRequest [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:1035 (EndRemapRequest)> (http_trans) [9] EndRemapRequest host is www.86kz17.com [Nov 4 14:12:25.549] [ET_NET 1] DEBUG: <HttpTransact.cc:1173 (EndRemapRequest)> (http_trans) [9] After Remapping: [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpTransact.cc:1192 (EndRemapRequest)> (http_trans) [9] END HttpTransact::EndRemapRequest [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpTransact.cc:1477 (HandleRequest)> (http_trans) [9] START HttpTransact::HandleRequest [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpTransact.cc:5564 (set_client_request_state)> (http_trans) [9] set req cont length to -1 [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpTransact.cc:6471 (is_request_valid)> (http_trans) [9] no request header errors [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpTransact.cc:1499 (HandleRequest)> (http_seq) [9] request valid. [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpTransact.cc:2666 (CallOSDNSLookup)> (http) [9] www.86kz17.com [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_DNS_LOOKUP [Nov 4 14:12:25.550] [ET_NET 1] DEBUG: <HttpSM.cc:4351 (do_hostdb_lookup)> (http_seq) [9] Doing DNS Lookup [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:2741 (main_handler)> (http) [9] EVENT_HOST_DB_LOOKUP/TS_EVENT_HOST_LOOKUP, 500 [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:2392 (state_hostdb_lookup)> (http) [9] [&HttpSM::state_hostdb_lookup, EVENT_HOST_DB_LOOKUP/TS_EVENT_HOST_LOOKUP] [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:1932 (OSDNSLookup)> (http_trans) [9] Entering HttpTransact::OSDNSLookup [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:1976 (OSDNSLookup)> (http_seq) [9] DNS Lookup successful [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:2014 (OSDNSLookup)> (http_trans) [9] DNS lookup for O.S. successful IP: 52.196.213.149 [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:2197 (DecideCacheLookup)> (http_trans) [9] Will NOT do cache lookup. [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:2198 (DecideCacheLookup)> (http_seq) [9] Will NOT do cache lookup [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:597 (find_server_and_update_current_info)> (http_trans) [9] request not cacheable, so bypass parent [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:7847 (build_request)> (http_trans) [9] removing host name from url [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:7886 (build_request)> (http_trans) [9] request_sent_time: 1762265545 [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_ORIGIN_SERVER_OPEN [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:5096 (do_http_server_open)> (http_track) [9] entered inside do_http_server_open ][ipv4] [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:5129 (do_http_server_open)> (http) [9] open connection to www.86kz17.com: 52.196.213.149:80 [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:5132 (do_http_server_open)> (http_seq) [9] Sending request to server [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:6665 (will_this_request_self_loop)> (http_transact) [9] max_proxy_cycles = 0 [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:6671 (will_this_request_self_loop)> (http_transact) [9] dst_port = 80 local_port = 80 [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpTransact.cc:6724 (will_this_request_self_loop)> (http_transact) [9] count = 0 <= max_proxy_cycles = 0 : allowing loop [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:5530 (do_http_server_open)> (http) [9] calling netProcessor.connect_re [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:2741 (main_handler)> (http) [9] NET_EVENT_OPEN/TS_EVENT_NET_CONNECT, 200 [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:1879 (state_http_server_open)> (http_track) [9] entered inside state_http_server_open: NET_EVENT_OPEN/TS_EVENT_NET_CONNECT [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:1880 (state_http_server_open)> (http) [9] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT] [Nov 4 14:12:25.655] [ET_NET 1] DEBUG: <HttpSM.cc:1909 (state_http_server_open)> (http) [9] setting handler for TCP handshake [Nov 4 14:12:25.656] [ET_NET 1] DEBUG: <HttpSM.cc:2741 (main_handler)> (http) [9] VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY, 101 [Nov 4 14:12:25.656] [ET_NET 1] DEBUG: <HttpSM.cc:1879 (state_http_server_open)> (http_track) [9] entered inside state_http_server_open: VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY [Nov 4 14:12:25.656] [ET_NET 1] DEBUG: <HttpSM.cc:1880 (state_http_server_open)> (http) [9] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Nov 4 14:12:25.656] [ET_NET 1] DEBUG: <HttpSM.cc:1932 (state_http_server_open)> (http_ss) [9] TCP Handshake complete [Nov 4 14:12:25.656] [ET_NET 1] DEBUG: <HttpSM.cc:6502 (setup_server_read_response_header)> (http) [9] Setting up the header read [Nov 4 14:12:25.656] [ET_NET 1] DEBUG: <HttpSM.cc:2741 (main_handler)> (http) [9] VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE, 103 [Nov 4 14:12:25.656] [ET_NET 1] DEBUG: <HttpSM.cc:2001 (state_read_server_response_header)> (http) [9] [&HttpSM::state_read_server_response_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Nov 4 14:12:25.656] [ET_NET 1] DEBUG: <HttpSM.cc:2178 (state_send_server_request_header)> (http) [9] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpSM.cc:2741 (main_handler)> (http) [9] VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY, 100 [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpSM.cc:2001 (state_read_server_response_header)> (http) [9] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpSM.cc:2127 (state_read_server_response_header)> (http_seq) [9] Done parsing server response header [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpSM.cc:2150 (state_read_server_response_header)> (http_seq) [9] Continue processing response [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:3460 (HandleResponse)> (http_trans) [9] Entering HttpTransact::HandleResponse [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:3461 (HandleResponse)> (http_seq) [9] Response received [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:3468 (HandleResponse)> (http_trans) [9] response_received_time: 1762265545 [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:330 (is_response_valid)> (http_trans) [9] No errors in response [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:3485 (HandleResponse)> (http_seq) [9] Response valid [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:3773 (handle_response_from_server)> (http_trans) [9] (hrfs) [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:3785 (handle_response_from_server)> (http_trans) [9] [hrfs] connection alive [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:4063 (handle_forward_server_connection_open)> (http_trans) [9] (hfsco) [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:4064 (handle_forward_server_connection_open)> (http_seq) [9] Entering HttpTransact::handle_server_connection_open [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:4071 (handle_forward_server_connection_open)> (http_trans) [9] Update hostdb history of server HTTP version 0x10001 [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpSM.cc:4484 (do_hostdb_update_if_necessary)> (http) [9] server info = 52.196.213.149:80 [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:4145 (handle_forward_server_connection_open)> (http_trans) [9] [hfsco] cache action: CACHE_DO_NO_ACTION [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:4750 (handle_no_cache_operation_on_forward_server_response)> (http_trans) [9] (hncoofsr) [Nov 4 14:12:25.658] [ET_NET 1] DEBUG: <HttpTransact.cc:4751 (handle_no_cache_operation_on_forward_server_response)> (http_seq) [9] Entering handle_no_cache_operation_on_forward_server_response [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpTransact.cc:4810 (handle_no_cache_operation_on_forward_server_response)> (http_trans) [9] [hncoofsr] server sent back something other than 100,304,200 [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpTransact.cc:6796 (handle_content_length_header)> (http_trans) [9] RESPONSE cont len in hdr is 346 [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:7646 (call_transact_and_set_next_state)> (http) [9] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SERVER_READ [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:8088 (do_redirect)> (http_redirect) [9] enable_redirection 0 [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:7003 (setup_server_transfer)> (http) [9] Setup Server Transfer [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpTunnel.cc:664 (add_producer)> (http_tunnel) [9] adding producer 'http server' [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpTunnel.cc:719 (add_consumer)> (http_tunnel) [9] adding consumer 'user agent' [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:6233 (perform_cache_write_action)> (http) [9] CACHE_DO_NO_ACTION [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpTunnel.cc:1059 (producer_run)> (http_tunnel) [9] [tunnel_run] producer already done [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpTunnel.cc:1188 (producer_handler)> (http_tunnel) [9] producer_handler [http server HTTP_TUNNEL_EVENT_PRECOMPLETE] [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpTunnel.cc:1231 (producer_handler)> (http_redirect) [9] enable_redirection: [0 0 0] event: 2302, state: 0 [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:3087 (tunnel_handler_server)> (http) [9] [&HttpSM::tunnel_handler_server, HTTP_TUNNEL_EVENT_PRECOMPLETE] [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpTunnel.cc:1398 (consumer_handler)> (http_tunnel) [9] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:3366 (tunnel_handler_ua)> (http) [9] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:2741 (main_handler)> (http) [9] HTTP_TUNNEL_EVENT_DONE, 2301 [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:3036 (tunnel_handler)> (http) [9] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE] [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:7342 (kill_this)> (http_seq) [9] Logging transaction [Nov 4 14:12:25.659] [ET_NET 1] DEBUG: <HttpSM.cc:7392 (kill_this)> (http) [9] deallocating sm ``` -- 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. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
