Uploaded image for project: 'Traffic Server'
  1. Traffic Server
  2. TS-3404

PluginVC not notifying ActiveSide of EOS due to race condition in handling terminating chunk.

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 5.3.0
    • 5.2.1, 5.3.0
    • Core
    • None

    Description

      When there's a race condition in receiving the terminating chunk (of size 0), PluginVC is not notifying the ActiveSide (for e.g. FetchSM) of EOS, causing it to hang until an eventual timeout occurs.

      The code below checks if the other_side is closed or in write shutdown state to send the EOS,
      https://github.com/apache/trafficserver/blob/master/proxy/PluginVC.cc#L638

      but, in the race condition observed in our environment, the PassiveSide's write_state is in shutdown (set via consumer_handler handling the event VC_EVENT_WRITE_COMPLETE at the final terminating chunk and HttpSM calling do_io_close with IO_SHUTDOWN_WRITE on the passive side.

      The below simple fix resolves the issue:

        if (act_on <= 0) {
    if (other_side->closed || other_side->write_state.shutdown || write_state.shutdown) {
      read_state.vio._cont->handleEvent(VC_EVENT_EOS, &read_state.vio);
    }
    return;
  }

      Below are the debug logs that indicate the failed and working cases due to the race condition:

      Working Case:

      [Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] adding producer 'http server'
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] adding consumer 'user agent'
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http) [205] perform_cache_write_action CACHE_DO_NO_ACTION
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) tunnel_run started, p_arg is NULL
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() = 368
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [producer_run] do_dechunking::Copied header of size 179
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_cs) tcp_init_cwnd_set 0
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_cs) desired TCP congestion window is 0
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() = 368
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [producer_run] do_dechunking p->chunked_handler.skip_bytes = 179
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) read chunk size of 57 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) completed read of chunk of 57 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) read chunk size of 120 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) completed read of chunk of 120 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) read chunk size of 3 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) completed read of chunk of 3 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) read chunk size of 0 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) completed read of trailers
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http) [205] [&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_ss) [205] session closing, netvc 0x7f85ec0158b0
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http_cs) [205] session half close
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] calling plugin on hook TS_HTTP_TXN_CLOSE_HOOK at hook 0x220a210
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http_seq) [HttpSM::update_stats] Logging transaction
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] deallocating sm
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [fetch_handler] calling fetch_plugin
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [process_fetch_read] I am here read
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [process_fetch_read] number of bytes in read ready 359
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [process_fetch_read] copied 359 bytes
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [process_fetch_read] total copied 359 bytes
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [fetch_handler] calling fetch_plugin
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [process_fetch_read] I am here read
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [get_info_from_buffer] total avail 359
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (FetchSM) [process_fetch_read] received EOS
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (FetchSM) [cleanUp] calling cleanup
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_tunnel) [204] producer_handler [http server VC_EVENT_READ_READY]

[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_tunnel) [204] producer_handler_dechunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_chunk) creating a chunk of size 267 bytes
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_cs) [205] [&HttpClientSession::state_wait_for_close, VC_EVENT_EOS]
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_cs) [205] session closed
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_cs) [205] session destroy
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_tunnel) [204] producer_handler [http server VC_EVENT_EOS]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_tunnel) [204] producer_handler_dechunked [http server VC_EVENT_EOS]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 104
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http) [204] [&HttpSM::tunnel_handler_server, VC_EVENT_EOS]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http) [204] [HttpSM::tunnel_handler_server] finishing HTTP tunnel
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_ss) [204] session closing, netvc 0x7f85f0002770
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_tunnel) [204] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http) [204] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_cs) [204] session released by sm [204]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_cs) [204] initiating io for next header
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http) [204] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:16.556] Server {0x7f865d664700} DEBUG: (http) [204] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:16.556] Server {0x7f865d664700} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers]

      Failed Case:

      [Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] adding producer 'http server'
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] adding consumer 'user agent'
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] perform_cache_write_action CACHE_DO_NO_ACTION
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) tunnel_run started, p_arg is NULL
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() = 368
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [producer_run] do_dechunking::Copied header of size 179
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_cs) tcp_init_cwnd_set 0
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_cs) desired TCP congestion window is 0
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() = 368
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [producer_run] do_dechunking p->chunked_handler.skip_bytes = 179
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) read chunk size of 57 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) completed read of chunk of 57 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) read chunk size of 120 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) completed read of chunk of 120 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) read chunk size of 3 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) completed read of chunk of 3 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] consumer_handler [user agent VC_EVENT_WRITE_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM) [fetch_handler] calling fetch_plugin
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM) [process_fetch_read] I am here read
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM) [process_fetch_read] number of bytes in read ready 359
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM) [process_fetch_read] copied 359 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM) [process_fetch_read] total copied 359 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] consumer_handler [user agent VC_EVENT_WRITE_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) read chunk size of 0 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) completed read of trailers
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] [&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_cs) [207] session half close
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_ss) [207] session closing, netvc 0x7f85ec015600
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] calling plugin on hook TS_HTTP_TXN_CLOSE_HOOK at hook 0x220a210
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] [&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] [&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_seq) [HttpSM::update_stats] Logging transaction
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] deallocating sm
[Feb 22 22:03:22.140] Server {0x7f85f7330700} DEBUG: (http_tunnel) [206] producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:22.140] Server {0x7f85f7330700} DEBUG: (http_tunnel) [206] producer_handler_dechunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:22.140] Server {0x7f85f7330700} DEBUG: (http_chunk) creating a chunk of size 190 bytes
[Feb 22 22:03:22.140] Server {0x7f85f7330700} DEBUG: (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:22.140] Server {0x7f865d563700} DEBUG: (http_tunnel) [206] consumer_handler [user agent VC_EVENT_WRITE_READY]
[Feb 22 22:03:22.140] Server {0x7f865d563700} DEBUG: (http_tunnel) [206] producer_handler [http server VC_EVENT_EOS]
[Feb 22 22:03:22.140] Server {0x7f865d563700} DEBUG: (http_tunnel) [206] producer_handler_dechunked [http server VC_EVENT_EOS]

      Attachments

        Issue Links

          is related to

          Bug - A problem which impairs or prevents the functions of the product. TS-3777 TSHttpConnect and POST request does not fire TS_VCONN_READ_COMPLETE nor TS_VCONN_EOS

          • Major - Major loss of function.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. TS-4960 Undo internal request tunnelling hacks

          • Major - Major loss of function.
          • Open

          Improvement - An improvement or enhancement to an existing feature or task. TS-4836 POST correctness should not depend on the internal flag

          • Major - Major loss of function.
          • Open

          Activity

            People

              sudheerv Sudheer Vinukonda
              sudheerv Sudheer Vinukonda
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: