Skip to content

Correctly track H2 post vio bytes #6401

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

Closed
shinrich wants to merge 2 commits into from
Closed

Correctly track H2 post vio bytes #6401

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
c0fee68
Correctly track H2 post vio bytes
shinrich Feb 6, 2020
218cd57
Change slow_post test to auto-select port
shinrich Feb 6, 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
53 changes: 39 additions & 14 deletions proxy/http/HttpSM.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2713,7 +2713,9 @@ HttpSM::tunnel_handler_post_or_put(HttpTunnelProducer *p)
// When the ua completed sending it's data we must have
// removed it from the tunnel
ink_release_assert(ua_entry->in_tunnel == false);
server_entry->in_tunnel = false;
if (server_entry) {
server_entry->in_tunnel = false;
}

break;
default:
Expand All @@ -2739,6 +2741,10 @@ HttpSM::tunnel_handler_post(int event, void *data)
switch (event) {
case HTTP_TUNNEL_EVENT_DONE: // Tunnel done.
if (p->handler_state == HTTP_SM_POST_UA_FAIL) {
if (server_entry) {
vc_table.remove_entry(server_entry);
server_entry = nullptr;
}
// post failed
switch (t_state.client_info.state) {
case HttpTransact::ACTIVE_TIMEOUT:
Expand Down Expand Up @@ -2792,6 +2798,8 @@ HttpSM::tunnel_handler_post(int event, void *data)
handle_post_failure();
break;
case HTTP_SM_POST_UA_FAIL:
// Client side failed. Shutdown and go home no need to communicate back to UA
terminate_sm = true;
break;
case HTTP_SM_POST_SUCCESS:
// It's time to start reading the response
Expand Down Expand Up @@ -3108,7 +3116,9 @@ HttpSM::tunnel_handler_server(int event, HttpTunnelProducer *p)
vc_table.remove_entry(server_entry);

if (close_connection) {
p->vc->do_io_close();
if (p->vc) {
p->vc->do_io_close();
}
p->read_vio = nullptr;
/* TS-1424: if we're outbound transparent and using the client
source port for the outbound connection we must effectively
Expand Down Expand Up @@ -3501,15 +3511,8 @@ HttpSM::tunnel_handler_post_ua(int event, HttpTunnelProducer *p)
SMDebug("http_tunnel", "send 408 response to client to vc %p, tunnel vc %p", ua_txn->get_netvc(), p->vc);

tunnel.chain_abort_all(p);
server_session = nullptr;
// Reset the inactivity timeout, otherwise the InactivityCop will callback again in the next second.
ua_txn->set_inactivity_timeout(HRTIME_SECONDS(t_state.txn_conf->transaction_no_activity_timeout_in));
// 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);

// The meta tunnel handler should just kill the SM in this case
return 0;
}
// fall through
Expand Down Expand Up @@ -3574,6 +3577,9 @@ HttpSM::tunnel_handler_for_partial_post(int event, void * /* data ATS_UNUSED */)
STATE_ENTER(&HttpSM::tunnel_handler_for_partial_post, event);
tunnel.deallocate_buffers();
tunnel.reset();
if (server_entry) {
server_entry->in_tunnel = false;
}

t_state.redirect_info.redirect_in_process = false;
is_using_post_buffer = false;
Expand Down Expand Up @@ -3930,7 +3936,9 @@ HttpSM::tunnel_handler_transform_read(int event, HttpTunnelProducer *p)
// transform hasn't detached yet. If it is still alive,
// don't close the transform vc
if (p->self_consumer->alive == false) {
p->vc->do_io_close();
if (p->vc) {
p->vc->do_io_close();
}
}
p->handler_state = HTTP_SM_TRANSFORM_CLOSED;

Expand Down Expand Up @@ -5395,7 +5403,7 @@ HttpSM::handle_post_failure()
STATE_ENTER(&HttpSM::handle_post_failure, VC_EVENT_NONE);

ink_assert(ua_entry->vc == ua_txn);
ink_assert(is_waiting_for_full_body || server_entry->eos == true);
ink_assert(is_waiting_for_full_body || server_entry == nullptr || server_entry->eos == true);

if (is_waiting_for_full_body) {
call_transact_and_set_next_state(HttpTransact::Forbidden);
Expand Down Expand Up @@ -5423,11 +5431,17 @@ HttpSM::handle_post_failure()
if (server_buffer_reader->read_avail() > 0) {
tunnel.deallocate_buffers();
tunnel.reset();
if (server_entry) {
server_entry->in_tunnel = false;
}
// There's data from the server so try to read the header
setup_server_read_response_header();
} else {
tunnel.deallocate_buffers();
tunnel.reset();
if (server_entry) {
server_entry->in_tunnel = false;
}
// Server died
t_state.current.state = HttpTransact::CONNECTION_CLOSED;
call_transact_and_set_next_state(HttpTransact::HandleResponse);
Expand Down Expand Up @@ -5537,6 +5551,9 @@ HttpSM::handle_server_setup_error(int event, void *data)
post_transform_info.entry = nullptr;
tunnel.deallocate_buffers();
tunnel.reset();
if (server_entry) {
server_entry->in_tunnel = false;
}
}
}
}
Expand Down Expand Up @@ -6223,6 +6240,9 @@ HttpSM::setup_100_continue_transfer()
// Clear the decks before we set up new producers. As things stand, we cannot have two static operators
// at once
tunnel.reset();
if (server_entry) {
server_entry->in_tunnel = false;
}

// Setup the tunnel to the client
HttpTunnelProducer *p = tunnel.add_producer(HTTP_TUNNEL_STATIC_PRODUCER, client_response_hdr_bytes, buf_start,
Expand Down Expand Up @@ -6355,6 +6375,9 @@ HttpSM::setup_internal_transfer(HttpSMHandler handler_arg)
// As things stand, we cannot have two static producers operating at
// once
tunnel.reset();
if (server_entry) {
server_entry->in_tunnel = false;
}

// Setup the tunnel to the client
HttpTunnelProducer *p =
Expand Down Expand Up @@ -6860,8 +6883,10 @@ HttpSM::kill_this()
plugin_tunnel = nullptr;
}

server_session = nullptr;

if (server_session && server_entry && !server_entry->in_tunnel && server_entry->vc == server_session) {
release_server_session();
server_session = nullptr;
}
// So we don't try to nuke the state machine
// if the plugin receives event we must reset
// the terminate_flag
Expand Down
8 changes: 5 additions & 3 deletions proxy/http/HttpTunnel.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1385,10 +1385,10 @@ HttpTunnel::chain_abort_all(HttpTunnelProducer *p)
if (c->alive) {
c->alive = false;
c->write_vio = nullptr;
c->vc->do_io_close(EHTTP_ERROR);
update_stats_after_abort(c->vc_type);
c->vc->do_io_close(EHTTP_ERROR);
c->vc = nullptr;
}

if (c->self_producer) {
// Must snip the link before recursively
// freeing to avoid looks introduced by
Expand All @@ -1410,8 +1410,9 @@ HttpTunnel::chain_abort_all(HttpTunnelProducer *p)
p->self_consumer->alive = false;
}
p->read_vio = nullptr;
p->vc->do_io_close(EHTTP_ERROR);
update_stats_after_abort(p->vc_type);
p->vc->do_io_close(EHTTP_ERROR);
p->vc = nullptr;
}
}

Expand Down Expand Up @@ -1480,6 +1481,7 @@ HttpTunnel::finish_all_internal(HttpTunnelProducer *p, bool chain)
}
}
}
// p->vc = nullptr;

while (c) {
if (c->alive) {
Expand Down
8 changes: 5 additions & 3 deletions proxy/http2/Http2ConnectionState.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,12 +180,14 @@ rcv_data_frame(Http2ConnectionState &cstate, const Http2Frame &frame)
if (nbytes + read_len > unpadded_length) {
read_len -= nbytes + read_len - unpadded_length;
}
nbytes += writer->write(myreader, read_len);
myreader->consume(nbytes);
int num_written = writer->write(myreader, read_len);
nbytes += num_written;
myreader->consume(num_written);
stream->update_read(num_written);
}
myreader->writer()->dealloc_reader(myreader);

if (frame.header().flags & HTTP2_FLAGS_DATA_END_STREAM) {
if (frame.header().flags & HTTP2_FLAGS_DATA_END_STREAM || stream->read_vio_done()) {
Copy link
Contributor

@masaori335 masaori335 Feb 6, 2020

Choose a reason for hiding this comment

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

This looks what we need 👍 ( Checking read_vio.ntodo() and signal VC_EVENT_READ_COMPLETE event )

Copy link
Member

@maskit maskit Feb 7, 2020

Choose a reason for hiding this comment

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

What does this VC_EVENT_READ_COMPLETE mean exactly? I'm a bit worried about trailing header, we don't support trailing header now though.

What we really need to do might be scheduling READ_COMPLETE on END_STREAM carried by second HEADERS frame. This may explain a case we somehow miss READ_COMPLETE.

https://tools.ietf.org/html/rfc7540#section-8.1.3

   Trailing header fields are sent as a header block after both the
   request or response header block and all the DATA frames have been
   sent.  The HEADERS frame starting the trailers header block has the
   END_STREAM flag set.

   The following example includes both a 100 (Continue) status code,
   which is sent in response to a request containing a "100-continue"
   token in the Expect header field, and trailing header fields:

     HTTP/1.1 100 Continue            HEADERS
     Extension-Field: bar       ==>     - END_STREAM
                                        + END_HEADERS
                                          :status = 100
                                          extension-field = bar

     HTTP/1.1 200 OK                  HEADERS
     Content-Type: image/jpeg   ==>     - END_STREAM
     Transfer-Encoding: chunked         + END_HEADERS
     Trailer: Foo                         :status = 200
                                          content-length = 123
     123                                  content-type = image/jpeg
     {binary data}                        trailer = Foo
     0
     Foo: bar                         DATA
                                        - END_STREAM
                                      {binary data}

                                      HEADERS
                                        + END_STREAM
                                        + END_HEADERS
                                          foo = bar

Copy link
Contributor

@masaori335 masaori335 Feb 7, 2020

Choose a reason for hiding this comment

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

Good point. ATS just set Http2Stream::recv_end_stream flag and ignore trailing header.

Copy link
Contributor

@masaori335 masaori335 Feb 7, 2020

Choose a reason for hiding this comment

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

I could reproduce the crash (what we saw on the docs) with a trailing header & setting transaction_active_timeout_out.

Process 16485 stopped
* thread #2, name = '[ET_NET 0]', stop reason = EXC_BAD_ACCESS (code=EXC_I386_GPFLT)
    frame #0: 0x0000000100010829 traffic_server`Continuation::handleEvent(this=0x000000000ad7a3f0, event=106, data=0x000000000ad9be00) at I_Continuation.h:189:5
   186    handleEvent(int event = CONTINUATION_EVENT_NONE, void *data = nullptr)
   187    {
   188      // If there is a lock, we must be holding it on entry
-> 189      ink_release_assert(!mutex || mutex->thread_holding == this_ethread());
   190      return (this->*handler)(event, data);
   191    }
   192
(lldb) bt
* thread #2, name = '[ET_NET 0]', stop reason = EXC_BAD_ACCESS (code=EXC_I386_GPFLT)
  * frame #0: 0x0000000100010829 traffic_server`Continuation::handleEvent(this=0x000000000ad7a3f0, event=106, data=0x000000000ad9be00) at I_Continuation.h:189:5
    frame #1: 0x00000001004e14af traffic_server`read_signal_and_update(event=106, vc=0x000000000ad9bc20) at UnixNetVConnection.cc:83:24
    frame #2: 0x00000001004e236f traffic_server`UnixNetVConnection::mainEvent(this=0x000000000ad9bc20, event=106, e=0x00000000010263a0) at UnixNetVConnection.cc:1153:9
    frame #3: 0x00000001000108d1 traffic_server`Continuation::handleEvent(this=0x000000000ad9bc20, event=106, data=0x00000000010263a0) at I_Continuation.h:190:12
    frame #4: 0x000000010049684e traffic_server`UnixNetVConnection::callback(this=0x000000000ad9bc20, event=106, data=0x00000000010263a0) at P_UnixNetVConnection.h:244:18
    frame #5: 0x00000001004d1c46 traffic_server`InactivityCop::check_inactivity(this=0x0000000006600060, event=2, e=0x00000000010263a0) at UnixNet.cc:85:13
    frame #6: 0x00000001000108d1 traffic_server`Continuation::handleEvent(this=0x0000000006600060, event=2, data=0x00000000010263a0) at I_Continuation.h:190:12
    frame #7: 0x0000000100519c8c traffic_server`EThread::process_event(this=0x0000000005000000, e=0x00000000010263a0, calling_code=2) at UnixEThread.cc:126:22
    frame #8: 0x000000010051a5bd traffic_server`EThread::execute_regular(this=0x0000000005000000) at UnixEThread.cc:239:11
    frame #9: 0x000000010051abc8 traffic_server`EThread::execute(this=0x0000000005000000) at UnixEThread.cc:330:11
    frame #10: 0x0000000100518d62 traffic_server`spawn_thread_internal(a=0x0000000003f160c0) at Thread.cc:92:12
    frame #11: 0x00007fff6d482e65 libsystem_pthread.dylib`_pthread_start + 148
    frame #12: 0x00007fff6d47e83b libsystem_pthread.dylib`thread_start + 15
(lldb) p this
(Continuation *) $0 = 0x000000000ad7a3f0
(lldb) p *this
(Continuation) $1 = {
  handler = de ad be ef de ad be ef de ad be ef de ad be ef
  handler_name = 0xefbeaddeefbeadde ""
  mutex = {
    m_ptr = 0xefbeaddeefbeadde
  }
  link = {
    SLink<Continuation> = {
      next = 0xefbeaddeefbeadde
    }
    prev = 0xefbeaddeefbeadde
  }
  control_flags = (raw_flags = 4022250974)
  thread_affinity = 0xefbeaddeefbeadde
}

Copy link
Contributor

@masaori335 masaori335 Feb 7, 2020

Choose a reason for hiding this comment

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

The crash is gone when I revert c55001b.
@shinrich Could you check your case is bad handling of trailing header too?

// TODO: set total written size to read_vio.nbytes
Copy link
Member

@maskit maskit Feb 7, 2020

Choose a reason for hiding this comment

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

Is this still a todo?

Copy link
Member Author

@shinrich shinrich Feb 7, 2020

Choose a reason for hiding this comment

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

Eventually, yes, still to do. As it stands with the origin needing to be chunked if nbytes is MAXINT on the H2 producer, the HttpTunnel logic updates the consumer write vio nbytes to the appropriate chunked size and as long as the EOS is set on the last data frame it is all ok.

stream->signal_read_event(VC_EVENT_READ_COMPLETE);
} else {
Expand Down
2 changes: 1 addition & 1 deletion proxy/http2/Http2Stream.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -213,7 +213,7 @@ Http2Stream::send_request(Http2ConnectionState &cstate)
return;
}

if (this->recv_end_stream) {
if (this->recv_end_stream || this->read_vio.ntodo() == 0) {
this->read_vio.nbytes = bufindex;
this->signal_read_event(VC_EVENT_READ_COMPLETE);
} else {
Expand Down
14 changes: 14 additions & 0 deletions proxy/http2/Http2Stream.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -124,6 +124,8 @@ class Http2Stream : public ProxyTransaction
bool has_trailing_header() const;
void set_request_headers(HTTPHdr &h2_headers);
MIOBuffer *read_vio_writer() const;
bool read_vio_done() const;
void update_read(int num_written);

//////////////////
// Variables
Expand Down Expand Up @@ -326,3 +328,15 @@ Http2Stream::read_vio_writer() const
{
return this->read_vio.get_writer();
}

inline void
Http2Stream::update_read(int num_written)
{
read_vio.ndone += num_written;
}

inline bool
Http2Stream::read_vio_done() const
{
return read_vio.ntodo() == 0;
}
2 changes: 1 addition & 1 deletion tests/gold_tests/slow_post/slow_post.test.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,7 @@ def setupOriginServer(self):
self._server.addResponse("sessionlog.json", request_header2, response_header2)

def setupTS(self):
self._ts = Test.MakeATSProcess("ts", select_ports=False)
self._ts = Test.MakeATSProcess("ts", select_ports=True)
self._ts.Disk.remap_config.AddLine(
'map / http://127.0.0.1:{0}'.format(self._server.Variables.Port)
)
Expand Down