Skip to content

Improve client_vc tracking #6889

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
zwoop merged 2 commits into from
Jul 13, 2020
Merged

Improve client_vc tracking #6889

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
ccab96d
Improve client_vc tracking
shinrich May 1, 2020
aac633d
Refine Http/2 error code
shinrich Jul 9, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 4 additions & 1 deletion doc/developer-guide/plugins/hooks-and-transactions/http-sessions.en.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,10 @@ The HTTP session hooks are:

- ``TS_HTTP_SSN_CLOSE_HOOK`` Called when an HTTP session ends (a
session ends when the client connection is closed). This hook must be
added as a global hook.
added as a global hook. The relative order of invocation between the
``TS_VCONN_CLOSE_HOOK`` and ``TS_HTTP_SSN_CLOSE_HOOK`` is undefined. In
most cases the ``TS_VCONN_CLOSE_HOOK`` will execute first, but that is
not guaranteed.

Use the session hooks to get a handle to a session (an ``TSHttpSsn``
object). If you want your plugin to be called back for each transaction
Expand Down
2 changes: 2 additions & 0 deletions iocore/net/UnixNetVConnection.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -88,6 +88,7 @@ read_signal_and_update(int event, UnixNetVConnection *vc)
case VC_EVENT_ACTIVE_TIMEOUT:
case VC_EVENT_INACTIVITY_TIMEOUT:
Debug("inactivity_cop", "event %d: null read.vio cont, closing vc %p", event, vc);
Warning("read: Closing orphaned vc %p", vc);
vc->closed = 1;
break;
default:
Expand Down Expand Up @@ -119,6 +120,7 @@ write_signal_and_update(int event, UnixNetVConnection *vc)
case VC_EVENT_ACTIVE_TIMEOUT:
case VC_EVENT_INACTIVITY_TIMEOUT:
Debug("inactivity_cop", "event %d: null write.vio cont, closing vc %p", event, vc);
Warning("write: Closing orphaned vc %p", vc);
vc->closed = 1;
break;
default:
Expand Down
54 changes: 16 additions & 38 deletions proxy/http/Http1ClientSession.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -87,6 +87,8 @@ Http1ClientSession::release_transaction()
{
released_transactions++;
if (transact_count == released_transactions) {
// Make sure we previously called release() or do_io_close() on the session
ink_release_assert(read_state != HCS_ACTIVE_READER && read_state != HCS_INIT);
destroy();
}
}
Expand All @@ -111,9 +113,6 @@ Http1ClientSession::free()
conn_decrease = false;
}

// Clean up the write VIO in case of inactivity timeout
this->do_io_write(nullptr, 0, nullptr);

// Free the transaction resources
this->trans.super_type::destroy();

Expand Down Expand Up @@ -228,25 +227,17 @@ Http1ClientSession::do_io_close(int alerrno)
slave_ka_vio = nullptr;
}
// Completed the last transaction. Just shutdown already
if (transact_count == released_transactions) {
// Or the do_io_close is due to a network error
if (transact_count == released_transactions || alerrno == HTTP_ERRNO) {
half_close = false;
}

// Clean up the write VIO in case of inactivity timeout
this->do_io_write(nullptr, 0, nullptr);

if (half_close && this->trans.get_sm()) {
read_state = HCS_HALF_CLOSED;
SET_HANDLER(&Http1ClientSession::state_wait_for_close);
HttpSsnDebug("[%" PRId64 "] session half close", con_id);

if (_vc) {
// We want the client to know that that we're finished
// writing. The write shutdown accomplishes this. Unfortunately,
// the IO Core semantics don't stop us from getting events
// on the write side of the connection like timeouts so we
// need to zero out the write of the continuation with
// the do_io_write() call (INKqa05309)
_vc->do_io_shutdown(IO_SHUTDOWN_WRITE);

ka_vio = _vc->do_io_read(this, INT64_MAX, read_buffer);
Expand All @@ -264,28 +255,22 @@ Http1ClientSession::do_io_close(int alerrno)
_reader->consume(_reader->read_avail());
} else {
read_state = HCS_CLOSED;
SET_HANDLER(&Http1ClientSession::state_wait_for_sm_shutdown);
ka_vio = _vc->do_io_read(this, INT64_MAX, read_buffer);
HttpSsnDebug("[%" PRId64 "] session closed", con_id);
HTTP_SUM_DYN_STAT(http_transactions_per_client_con, transact_count);
HTTP_DECREMENT_DYN_STAT(http_current_client_connections_stat);
conn_decrease = false;
// Can go ahead and close the netvc now, but keeping around the session object
// until all the transactions are closed
if (_vc) {
_vc->do_io_close();
_vc = nullptr;
}
}
if (transact_count == released_transactions) {
this->destroy();
}
}

int
Http1ClientSession::state_wait_for_sm_shutdown(int event, void *data)
Copy link
Contributor

@masaori335 masaori335 Jul 9, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, what we needed at #6809 was only changes in HttpSM after all?

Copy link
Member Author

@shinrich shinrich Jul 9, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, the changes in this PR moved the netvc close back to the Http1ClientSession::do_io_close(). So with that change, we didn't need the extra handler added in #6809 to track the netvc object between the time it got a terminal event and we freed the Http1ClientSession.

{
STATE_ENTER(&Http1ClientSession::state_wait_for_sm_shutdown, event, data);
ink_assert(read_state == HCS_CLOSED);

// Just eat IO events until the state machine has finished
return 0;
}

int
Http1ClientSession::state_wait_for_close(int event, void *data)
{
Expand All @@ -305,11 +290,7 @@ Http1ClientSession::state_wait_for_close(int event, void *data)
case VC_EVENT_ACTIVE_TIMEOUT:
case VC_EVENT_INACTIVITY_TIMEOUT:
half_close = false;
this->do_io_close();
if (_vc != nullptr) {
_vc->do_io_close();
_vc = nullptr;
}
this->do_io_close(EHTTP_ERROR);
break;
case VC_EVENT_READ_READY:
// Drain any data read
Expand Down Expand Up @@ -385,11 +366,7 @@ Http1ClientSession::state_keep_alive(int event, void *data)
break;

case VC_EVENT_EOS:
this->do_io_close();
if (_vc != nullptr) {
_vc->do_io_close();
_vc = nullptr;
}
this->do_io_close(EHTTP_ERROR);
break;

case VC_EVENT_READ_COMPLETE:
Expand All @@ -401,7 +378,7 @@ Http1ClientSession::state_keep_alive(int event, void *data)
case VC_EVENT_ACTIVE_TIMEOUT:
case VC_EVENT_INACTIVITY_TIMEOUT:
// Keep-alive timed out
this->do_io_close();
this->do_io_close(EHTTP_ERROR);
break;
}

Expand All @@ -414,8 +391,8 @@ Http1ClientSession::release(ProxyTransaction *trans)
{
ink_assert(read_state == HCS_ACTIVE_READER || read_state == HCS_INIT);

// Clean up the write VIO in case of inactivity timeout
this->do_io_write(nullptr, 0, nullptr);
// Timeout events should be delivered to the session
this->do_io_write(this, 0, nullptr);

// Check to see there is remaining data in the
// buffer. If there is, spin up a new state
Expand Down Expand Up @@ -487,6 +464,7 @@ Http1ClientSession::attach_server_session(Http1ServerSession *ssession, bool tra
// the server net conneciton from calling back a dead sm
SET_HANDLER(&Http1ClientSession::state_keep_alive);
slave_ka_vio = ssession->do_io_read(this, INT64_MAX, ssession->read_buffer);
this->do_io_write(this, 0, nullptr); // Capture the inactivity timeouts
ink_assert(slave_ka_vio != ka_vio);

// Transfer control of the write side as well
Expand Down
1 change: 0 additions & 1 deletion proxy/http/Http1ClientSession.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -87,7 +87,6 @@ class Http1ClientSession : public ProxySession
int state_keep_alive(int event, void *data);
int state_slave_keep_alive(int event, void *data);
int state_wait_for_close(int event, void *data);
int state_wait_for_sm_shutdown(int event, void *data);

enum C_Read_State {
HCS_INIT,
Expand Down
17 changes: 8 additions & 9 deletions proxy/http/HttpSM.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -586,7 +586,8 @@ HttpSM::attach_client_session(ProxyTransaction *client_vc, IOBufferReader *buffe
// this hook maybe asynchronous, we need to disable IO on
// client but set the continuation to be the state machine
// so if we get an timeout events the sm handles them
ua_entry->read_vio = client_vc->do_io_read(this, 0, buffer_reader->mbuf);
ua_entry->read_vio = client_vc->do_io_read(this, 0, buffer_reader->mbuf);
ua_entry->write_vio = client_vc->do_io_write(this, 0, nullptr);

/////////////////////////
// set up timeouts //
Expand Down Expand Up @@ -2768,7 +2769,6 @@ HttpSM::tunnel_handler_post(int event, void *data)
if (ua_entry->write_buffer) {
free_MIOBuffer(ua_entry->write_buffer);
ua_entry->write_buffer = nullptr;
ua_entry->vc->do_io_write(nullptr, 0, nullptr);
}
if (!p->handler_state) {
p->handler_state = HTTP_SM_POST_UA_FAIL;
Expand Down Expand Up @@ -3529,9 +3529,6 @@ HttpSM::tunnel_handler_post_ua(int event, HttpTunnelProducer *p)
// if it is active timeout case, we need to give another chance to send 408 response;
ua_txn->set_active_timeout(HRTIME_SECONDS(t_state.txn_conf->transaction_active_timeout_in));

p->vc->do_io_write(nullptr, 0, nullptr);
p->vc->do_io_shutdown(IO_SHUTDOWN_READ);

return 0;
}
// fall through
Expand All @@ -3543,8 +3540,6 @@ HttpSM::tunnel_handler_post_ua(int event, HttpTunnelProducer *p)
// server and close the ua
p->handler_state = HTTP_SM_POST_UA_FAIL;
set_ua_abort(HttpTransact::ABORTED, event);
p->vc->do_io_write(nullptr, 0, nullptr);
p->vc->do_io_shutdown(IO_SHUTDOWN_READ);
tunnel.chain_abort_all(p);
server_session = nullptr;
// the in_tunnel status on both the ua & and
Expand All @@ -3555,6 +3550,11 @@ HttpSM::tunnel_handler_post_ua(int event, HttpTunnelProducer *p)
if (p->consumer_list.head && p->consumer_list.head->vc_type == HT_TRANSFORM) {
hsm_release_assert(post_transform_info.entry->in_tunnel == true);
} // server side may have completed before the user agent side, so it may no longer be in tunnel

// In the error case, start to take down the client session. There should
// be no reuse here
vc_table.remove_entry(this->ua_entry);
ua_txn->do_io_close();
break;

case VC_EVENT_READ_COMPLETE:
Expand All @@ -3571,8 +3571,7 @@ HttpSM::tunnel_handler_post_ua(int event, HttpTunnelProducer *p)
}
}

// Initiate another read to watch catch aborts and
// timeouts
// Initiate another read to catch aborts and timeouts.
ua_entry->vc_handler = &HttpSM::state_watch_for_client_abort;
ua_entry->read_vio = p->vc->do_io_read(this, INT64_MAX, ua_buffer_reader->mbuf);
break;
Expand Down
7 changes: 1 addition & 6 deletions proxy/http2/Http2ClientSession.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -286,7 +286,7 @@ Http2ClientSession::do_io_close(int alerrno)
this->clear_session_active();

// Clean up the write VIO in case of inactivity timeout
this->do_io_write(nullptr, 0, nullptr);
this->do_io_write(this, 0, nullptr);
}

void
Expand Down Expand Up @@ -349,10 +349,6 @@ Http2ClientSession::main_event_handler(int event, void *edata)
Http2SsnDebug("Closing event %d", event);
this->set_dying_event(event);
this->do_io_close();
if (_vc != nullptr) {
_vc->do_io_close();
_vc = nullptr;
}
retval = 0;
break;

Expand Down Expand Up @@ -594,7 +590,6 @@ Http2ClientSession::state_process_frame_read(int event, VIO *vio, bool inside_fr
if (!this->connection_state.is_state_closed()) {
this->connection_state.send_goaway_frame(this->connection_state.get_latest_stream_id_in(), err);
this->set_half_close_local_flag(true);
this->do_io_close();
}
}
return 0;
Expand Down
5 changes: 4 additions & 1 deletion proxy/http2/Http2ConnectionState.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -241,9 +241,12 @@ rcv_headers_frame(Http2ConnectionState &cstate, const Http2Frame &frame)

if (cstate.is_valid_streamid(stream_id)) {
stream = cstate.find_stream(stream_id);
if (stream == nullptr || !stream->has_trailing_header()) {
if (stream == nullptr) {
return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_STREAM_CLOSED,
Copy link
Contributor

@masaori335 masaori335 Jul 9, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this for http2/6.2/2 of h2spec?

5.1. Stream States says below

closed:
An endpoint that receives any frame other than PRIORITY
after receiving a RST_STREAM MUST treat that as a stream error
(Section 5.4.2) of type STREAM_CLOSED.

Probably, we need to break down the conditions in line 244

  • stream == nullptr -> STREAM_CLOSED
  • !stream->has_trailing_header() -> HTTP2_ERROR_PROTOCOL_ERROR

Copy link
Member Author

@shinrich shinrich Jul 9, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was to fix one of the h2spec cases. I'll update to split the cases here to return two different error codes.

Copy link
Member Author

@shinrich shinrich Jul 9, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Specifically it was a problem in the 8 section.

Hypertext Transfer Protocol Version 2 (HTTP/2)
               8. HTTP Message Exchanges
                 8.1. HTTP Request/Response Exchange
                   × 1: Sends a second HEADERS frame without the END_STREAM flag
                     -> The endpoint MUST respond with a stream error of type PROTOCOL_ERROR.
                        Expected: GOAWAY Frame (Error Code: PROTOCOL_ERROR)
                                  RST_STREAM Frame (Error Code: PROTOCOL_ERROR)
                                  Connection closed
                          Actual: Timeout
             
                   8.1.2. HTTP Header Fields
                     8.1.2.1. Pseudo-Header Fields
                       × 3: Sends a HEADERS frame that contains a pseudo-header field as trailers
                         -> The endpoint MUST respond with a stream error of type PROTOCOL_ERROR.
                            Expected: GOAWAY Frame (Error Code: PROTOCOL_ERROR)
                                      RST_STREAM Frame (Error Code: PROTOCOL_ERROR)
                                      Connection closed
                              Actual: Timeout

I assume in earlier version of the PR when the netvc close was in the Http2ClientSession::do_io_close() the "Connection closed" case triggered and addressed these cases.

Splitting the checks as you suggest also solves the issue.

"recv headers cannot find existing stream_id");
} else if (!stream->has_trailing_header()) {
return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_PROTOCOL_ERROR,
"recv headers cannot find existing stream_id");
}
} else {
// Create new stream
Expand Down
4 changes: 3 additions & 1 deletion proxy/http2/Http2Stream.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -652,7 +652,9 @@ Http2Stream::signal_read_event(int event)
void
Http2Stream::signal_write_event(int event)
{
if (this->write_vio.cont == nullptr || this->write_vio.cont->mutex == nullptr || this->write_vio.op == VIO::NONE) {
// Don't signal a write event if in fact nothing was written
if (this->write_vio.cont == nullptr || this->write_vio.cont->mutex == nullptr || this->write_vio.op == VIO::NONE ||
this->write_vio.nbytes == 0) {
return;
}

Expand Down
8 changes: 4 additions & 4 deletions tests/gold_tests/pluginTest/test_hooks/log.gold
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,10 +24,10 @@ Transaction: event=TS_EVENT_HTTP_READ_REQUEST_HDR
Global: event=TS_EVENT_HTTP_TXN_CLOSE
Session: event=TS_EVENT_HTTP_TXN_CLOSE
Transaction: event=TS_EVENT_HTTP_TXN_CLOSE
``
Global: event=TS_EVENT_HTTP_SSN_CLOSE
Session: event=TS_EVENT_HTTP_SSN_CLOSE
Global: event=TS_EVENT_VCONN_CLOSE
Global: ssl flag=1
``
Global: event=TS_EVENT_VCONN_START
Global: ssl flag=1
Global: event=TS_EVENT_SSL_SERVERNAME
Expand All @@ -43,7 +43,7 @@ Transaction: event=TS_EVENT_HTTP_READ_REQUEST_HDR
Global: event=TS_EVENT_HTTP_TXN_CLOSE
Session: event=TS_EVENT_HTTP_TXN_CLOSE
Transaction: event=TS_EVENT_HTTP_TXN_CLOSE
``
Global: event=TS_EVENT_HTTP_SSN_CLOSE
Session: event=TS_EVENT_HTTP_SSN_CLOSE
Global: event=TS_EVENT_VCONN_CLOSE
Global: ssl flag=1
``
1 change: 1 addition & 0 deletions tests/gold_tests/pluginTest/test_hooks/test_hooks.test.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -99,3 +99,4 @@
tr.Processes.Default.ReturnCode = 0
f = tr.Disk.File("log.txt")
f.Content = "log.gold"
f.Content += Testers.ContainsExpression("Global: event=TS_EVENT_VCONN_CLOSE", "VCONN_CLOSE should trigger 2 times")