You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@trafficserver.apache.org by "Craig Schomburg (craigs)" <cr...@cisco.com> on 2016/05/27 14:46:02 UTC
SSLNetVConnection IOBufferBlock management issue
Hey folks,
We are encountering a SSLVNetConnection IOBufferBlock buffer management
issue in ATS 6.0.0 that we did not see in the earlier ATS 4.0.1 release
Which we were using.
What we see in ssl_read_from_net() is when we get multiple GET requests on
a single SSL session, as each GET is processed and ACK/NACK’ed that the
buffer is not reset and the space released for reuse. As a result, the
available write_avail() space in the session IOBufferBlock buffer is
reduced with each subsequent packet until we have insufficient space to
buffer the packet.
Also appears that ATS is set up to support a chain of 2 IOBufferBlock
but since only 1 is allocated we bail out of the read loop in
ssl_read_from_net() with a incomplete packet and then drop it.
Request Response Txn-ID VC
---------------------------- ---------------- ------ --------------
GET /call/187972?debug=1 200 OK 4 0x560bb93e6420
b->write_avail()=4096, nread=0
b->write_avail()=4096, nread=1900 (2196 left in buffer)
nread=0 PARSE DONE
GET /call/widget.jsp... 200 OK 5 0x560bb93e6420
b->write_avail()=2196, nread=0
b->write_avail()=2196, nread=2120 ( 76 left in buffer)
nread=0 PARSE DONE
GET /call/js/libs/require.js 304 Not Modified 6 0x560bb93e6420
b->write_avail()=76, nread=0
b->write_avail()=76, nread=76 ( 0 left)
b->next is NULL so ssl_read_from_net() bails on read loop and remainder
of packet is not read
We hacked the ssl_read_from_net() code in the SSL_ERROR_NONE case to
add_block() if b->next == NULL and block_write_avail == 0 and that
“appeared” to get us working again but I am not convinced that was the
correct solution. Concerned because it appears that other areas of the
code assume there will never be more than 2 buffers in the list and we
did not put a limit on the list length.
So my question is when should the IOBufferBlock _end and _start have
been reset() to free the buffer space? I assumed that since we were seeing
a serial Packet(GET), ACK, Packet(GET), ACK, Packet(GET), ACK, that the
Buffer space could/should have been reset after each ACK?
Also curious if this is a known issue with ATS 6.0.0 that has been
addressed or is known/unaddressed?
Continuing to dig through the code in the mean time. Any feedback, insight,
etc. would be appreciated…
Thanks,
Craig S.
Re: SSLNetVConnection IOBufferBlock management issue
Posted by Alan Carroll <so...@yahoo-inc.com.INVALID>.
Ah, that's just a limit on write though. All writing needs to happen at the first available byte so it is naturally constrained. The second block is checked only so that if the first block is full a new block is *not* allocated until it is needed. For this same reason it should never be the case that the chain starting at the writer is longer than 2. Note that the reader(s) can be much further back along the chain. The presumed logic for writing is to write the first block, then check the MIOBuffer write_avail to set up for the next write as that method will add a block if insufficient space is available in the write chain. There's really no advantage to pre-allocating for write any further than 1 block.
On Friday, May 27, 2016 11:08 AM, Craig Schomburg (craigs) <cr...@cisco.com> wrote:
Alan,
Here is the limit I mentioned:
/**
Returns a pointer to the first writable block on the block chain.
Returns NULL if there are not currently any writable blocks on the
block list.
*/
IOBufferBlock *
first_write_block()
{
if (_writer) {
if (_writer->next && !_writer->write_avail())
return _writer->next;
ink_assert(!_writer->next || !_writer->next->read_avail());
return _writer;
} else
return NULL;
}
first_write_block will look at only the first 2 buffer blocks in the list when the pointer to the first buffer block is requested. So if you had a chain of more than 2 buffers in the list and the first 2 were full we do not continue to iterate through the possible list.
Re: SSLNetVConnection IOBufferBlock management issue
Posted by Chao Xu <xu...@gmail.com>.
it is return to net_read_io() from ssl_read_from_net() when the MIOBuffer
is full for write.
and net_read_io will callback to HttpSM with EVENT_READ_READY to consume
the data in MIOBuffer and reenable ReadVIO.
then do readReschedule() after callback return from HttpSM.
Only read at most 2 blocks, it is limit the memory usage and make every
(include slow & fast) connection has a chance to do read operation.
In a loop, every connection has 2 read operation at most and every
connection only keep 2 IOBufferBlocks memory in a time.
2016-05-28 0:06 GMT+08:00 Craig Schomburg (craigs) <cr...@cisco.com>:
> Alan,
>
> Here is the limit I mentioned:
>
> /**
> Returns a pointer to the first writable block on the block chain.
> Returns NULL if there are not currently any writable blocks on the
> block list.
>
> */
> IOBufferBlock *
> first_write_block()
> {
> if (_writer) {
> if (_writer->next && !_writer->write_avail())
> return _writer->next;
> ink_assert(!_writer->next || !_writer->next->read_avail());
> return _writer;
> } else
> return NULL;
> }
>
> first_write_block will look at only the first 2 buffer blocks in the list
> when the pointer to the first buffer block is requested. So if you had a
> chain of more than 2 buffers in the list and the first 2 were full we do
> not continue to iterate through the possible list.
>
> Craig S.
>
>
> From: Alan Carroll <solidwallofcode@yahoo-inc.com<mailto:
> solidwallofcode@yahoo-inc.com>>
> Reply-To: Alan Carroll <solidwallofcode@yahoo-inc.com<mailto:
> solidwallofcode@yahoo-inc.com>>
> Date: Friday, May 27, 2016 at 11:09 AM
> To: "dev@trafficserver.apache.org<ma...@trafficserver.apache.org>" <
> dev@trafficserver.apache.org<ma...@trafficserver.apache.org>>
> Cc: Craig Schomburg <cr...@cisco.com>>
> Subject: Re: SSLNetVConnection IOBufferBlock management issue
>
> The IOBufferBlock _end and _start should never be reset to free the buffer
> space. The block itself should be released and a new one allocated to store
> additional information. The buffer block chain can be of arbitrary length,
> I haven't seen anywhere in the code that a max length is presumed. Could
> you point out that code? The IOBufferBlocks are treated as write once,
> stable blocks of memory so they can be passed along without copying the
> memory as the data flows through.
>
> In general would should happen is MIOBuffer::write_avail() should be
> called and that will add a new block (if needed) to the writer block chain
> (see MIOBuffer::write_avail in iocore/eventsystem/P_IOBuffer.h).
> Unfortunately I don't see where that is being done, but we have run 6.2.x
> in production for testing and the TLS works. I'll see what I can find.
>
>
>
Re: SSLNetVConnection IOBufferBlock management issue
Posted by "Craig Schomburg (craigs)" <cr...@cisco.com>.
Alan,
Here is the limit I mentioned:
/**
Returns a pointer to the first writable block on the block chain.
Returns NULL if there are not currently any writable blocks on the
block list.
*/
IOBufferBlock *
first_write_block()
{
if (_writer) {
if (_writer->next && !_writer->write_avail())
return _writer->next;
ink_assert(!_writer->next || !_writer->next->read_avail());
return _writer;
} else
return NULL;
}
first_write_block will look at only the first 2 buffer blocks in the list when the pointer to the first buffer block is requested. So if you had a chain of more than 2 buffers in the list and the first 2 were full we do not continue to iterate through the possible list.
Craig S.
From: Alan Carroll <so...@yahoo-inc.com>>
Reply-To: Alan Carroll <so...@yahoo-inc.com>>
Date: Friday, May 27, 2016 at 11:09 AM
To: "dev@trafficserver.apache.org<ma...@trafficserver.apache.org>" <de...@trafficserver.apache.org>>
Cc: Craig Schomburg <cr...@cisco.com>>
Subject: Re: SSLNetVConnection IOBufferBlock management issue
The IOBufferBlock _end and _start should never be reset to free the buffer space. The block itself should be released and a new one allocated to store additional information. The buffer block chain can be of arbitrary length, I haven't seen anywhere in the code that a max length is presumed. Could you point out that code? The IOBufferBlocks are treated as write once, stable blocks of memory so they can be passed along without copying the memory as the data flows through.
In general would should happen is MIOBuffer::write_avail() should be called and that will add a new block (if needed) to the writer block chain (see MIOBuffer::write_avail in iocore/eventsystem/P_IOBuffer.h). Unfortunately I don't see where that is being done, but we have run 6.2.x in production for testing and the TLS works. I'll see what I can find.
Re: SSLNetVConnection IOBufferBlock management issue
Posted by Alan Carroll <so...@yahoo-inc.com.INVALID>.
The IOBufferBlock _end and _start should never be reset to free the buffer space. The block itself should be released and a new one allocated to store additional information. The buffer block chain can be of arbitrary length, I haven't seen anywhere in the code that a max length is presumed. Could you point out that code? The IOBufferBlocks are treated as write once, stable blocks of memory so they can be passed along without copying the memory as the data flows through.
In general would should happen is MIOBuffer::write_avail() should be called and that will add a new block (if needed) to the writer block chain (see MIOBuffer::write_avail in iocore/eventsystem/P_IOBuffer.h). Unfortunately I don't see where that is being done, but we have run 6.2.x in production for testing and the TLS works. I'll see what I can find.
Re: SSLNetVConnection IOBufferBlock management issue
Posted by "Craig Schomburg (craigs)" <cr...@cisco.com>.
Thanks all,
Between the info from Alan and Chao I think I understand a bit better why we saw a max of 2 buffer reads (even with my temp tweak). I also was not clear on how the resumption of the read worked. Think I need to go back and look at that part again based on Alan’s comment below. Issue we hit was that we never saw the read resume. MIME posted a PARSE_CONT and then we never saw a resumption of the read operation. In a few cases we also saw SSL_ERROR_ZERO_RETURN. Debug trace below...
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <SSLNetVConnection.cc:205 (ssl_read_from_net)> (ssl) trace=FALSE
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <SSLNetVConnection.cc:210 (ssl_read_from_net)> (ssl) [SSL_NetVConnection::ssl_read_from_net] b->write_avail()=125
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <SSLNetVConnection.cc:217 (ssl_read_from_net)> (ssl) [SSL_NetVConnection::ssl_read_from_net] nread=125
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <SSLNetVConnection.cc:296 (ssl_read_from_net)> (ssl) [SSL_NetVConnection::ssl_read_from_net] bytes_read=125
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpClientSession.cc:409 (state_keep_alive)> (http_cs) [4] [&HttpClientSession::state_keep_alive, VC_EVENT_READ_READY]
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpClientSession.cc:139 (new_transaction)> (http_cs) [4] Starting transaction 3 using sm [8]
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpSM.cc:2535 (main_handler)> (http) [8] [HttpSM::main_handler, VC_EVENT_READ_READY]
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpSM.cc:574 (state_read_client_request_header)> (http) [8] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpSM.cc:625 (state_read_client_request_header)> (http) [8] HOOP calling parse_req.
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HdrTSOnly.cc:74 (parse_req)> (http) HOOP here is the data start[0]: 47 45 54 <<< GET
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HTTP.cc:883 (http_parser_parse_req)> (http) HOOP in http_parser_parse_req.
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HTTP.cc:885 (http_parser_parse_req)> (http) HOOP in if of http_parser_parse_req.
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HTTP.cc:904 (http_parser_parse_req)> (http) craigs http_parser_parse_req start:
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HTTP.cc:921 (http_parser_parse_req)> (http) HOOP in http_parser_parse_req returning PARSE CONT. <<< So above only indicated 125 bytes read? Where is the rest?
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HdrTSOnly.cc:67 (parse_req)> (http) HOOP no more data so breaking
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpSM.cc:629 (state_read_client_request_header)> (http) [8] HOOP after parse_req.
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpSM.cc:639 (state_read_client_request_header)> (http) [8] HOOP before is transparent passthrough allowed.
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpSM.cc:702 (state_read_client_request_header)> (http) [8] HOOP in switch parse cont.
2016-05-25T19:30:48.711+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1b0f700} DEBUG: <HttpSM.cc:716 (state_read_client_request_header)> (http) [8] HOOP in switch parse cont in else.
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <SSLNetVConnection.cc:205 (ssl_read_from_net)> (ssl) trace=FALSE
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <SSLNetVConnection.cc:210 (ssl_read_from_net)> (ssl) [SSL_NetVConnection::ssl_read_from_net] b->write_avail()=4096
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <SSLUtils.cc:1622 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x55db68e492c0 where: 16388 ret: 256
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <SSLNetVConnection.cc:217 (ssl_read_from_net)> (ssl) [SSL_NetVConnection::ssl_read_from_net] nread=0
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <SSLNetVConnection.cc:281 (ssl_read_from_net)> (ssl.error) [SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_ZERO_RETURN <<< tried to read more and got ZERO???
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <HttpSM.cc:2535 (main_handler)> (http) [7] [HttpSM::main_handler, VC_EVENT_EOS]
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <HttpSM.cc:574 (state_read_client_request_header)> (http) [7] [&HttpSM::state_read_client_request_header, VC_EVENT_EOS]
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <HttpSM.cc:586 (state_read_client_request_header)> (http) EOS for ssl vc 0x55db68dffd70 at read_first_btye state
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DEBUG: <HttpClientSession.cc:325 (do_io_close)> (http_cs) [6] session closed
2016-05-25T19:30:53.794+08:00 jabberc-vcse-001 traffic_server[11959]: {0x2b88b1f13700} DIAG: (drop_failed_auth) Session End
Interesting part is we added the following tweak in ssl_read_from_net() and the complete packet was read (provided it fit within 2 buffers) and all was well… We understand that this is not the correct way to address this but it allowed us a workaround while this investigation continues...
case SSL_ERROR_NONE:
#if DEBUG
SSLDebugBufferPrint("ssl_buff", b->end() + offset, nread, "SSL Read");
#endif
ink_assert(nread);
bytes_read += nread;
offset += nread;
block_write_avail -= nread;
ink_assert(block_write_avail >= 0);
// Temp tweak to work around read issue...
if ((block_write_avail == 0) && (b->next == NULL)) {
buf.writer()->add_block();
Debug("ssl", "[SSL_NetVConnection::ssl_read_from_net] add_block() b=%p, b->next=%p", b, bnxt);
}
// End temp tweak
continue;
I will dig further. Please let me know if there are any hints in the debug trace above that I may have overlooked…
One question… Is it worth me trying Susan’s 629 [TS-4309] changes below? We are approaching product release so moving off of 6.0.0 is not a option at the moment as we do not have sufficient time to retest a new ATS release. If I can easily integrate the 629 [TS-4309] changes I am glad to give that a try. How close to commit ready do we believe the 629 [TS-4309] changes are? Are there any other changes TS that TS-4309 is dependent upon?
Thanks,
Craig S.
On 5/27/16, 11:25 AM, "Alan Carroll" <so...@yahoo-inc.com.INVALID> wrote:
>New blocks should be added to the writer chain in SSLNetVConnection::net_read_io with the call to buf.writer()->read_avail (because of the type of buf, MIOBufferAccessor, buf.writer() is MIOBuffer* and its write_avail() should extend the write chain if there is less than the low water mark of space left to write). So after not reading all of the packet in one pass, the socket should still have WRITE signaled and net_read_io should be called again, calling MIOBuffer::write_avail() and then ssl_read_from_net. This code is a bit messed up, Susan's PR is an attempt to make it better (more efficient, robust, and understandable).
>
>
> On Friday, May 27, 2016 10:20 AM, Susan Hinrichs <sh...@network-geographics.com> wrote:
>
>
> There is a PR that uses the buffer interface instead of the block
>interface which results in simpler code. We are running this code
>internally in Yahoo. It fixed a performance problem introduced by a fix
>not yet landed in open source. Since the current code works, I haven't
>pushed this PR. But if debugging anything in this area, I'd suggest
>first moving to the buffer interface.
>
>https://github.com/apache/trafficserver/pull/629/files
>
>Alan just rediscovered how additional blocks are added in the existing
>code. I'll let him respond with details on that.
>
>Also, I'd suggest moving up to 6.1 or 6.2.x rather than 6.0.0. I don't
>think many folks have deployed 6.0. We are starting to deploy 6.2 and
>we tested a bit with 6.1 (and others have deployed 6.1).
>
>
>On 5/27/2016 9:46 AM, Craig Schomburg (craigs) wrote:
>> Hey folks,
>>
>> We are encountering a SSLVNetConnection IOBufferBlock buffer management
>> issue in ATS 6.0.0 that we did not see in the earlier ATS 4.0.1 release
>> Which we were using.
>>
>> What we see in ssl_read_from_net() is when we get multiple GET requests on
>> a single SSL session, as each GET is processed and ACK/NACK’ed that the
>> buffer is not reset and the space released for reuse. As a result, the
>> available write_avail() space in the session IOBufferBlock buffer is
>> reduced with each subsequent packet until we have insufficient space to
>> buffer the packet.
>>
>> Also appears that ATS is set up to support a chain of 2 IOBufferBlock
>> but since only 1 is allocated we bail out of the read loop in
>> ssl_read_from_net() with a incomplete packet and then drop it.
>>
>> Request Response Txn-ID VC
>> ---------------------------- ---------------- ------ --------------
>> GET /call/187972?debug=1 200 OK 4 0x560bb93e6420
>> b->write_avail()=4096, nread=0
>> b->write_avail()=4096, nread=1900 (2196 left in buffer)
>> nread=0 PARSE DONE
>>
>> GET /call/widget.jsp... 200 OK 5 0x560bb93e6420
>> b->write_avail()=2196, nread=0
>> b->write_avail()=2196, nread=2120 ( 76 left in buffer)
>> nread=0 PARSE DONE
>>
>> GET /call/js/libs/require.js 304 Not Modified 6 0x560bb93e6420
>> b->write_avail()=76, nread=0
>> b->write_avail()=76, nread=76 ( 0 left)
>> b->next is NULL so ssl_read_from_net() bails on read loop and remainder
>> of packet is not read
>>
>> We hacked the ssl_read_from_net() code in the SSL_ERROR_NONE case to
>> add_block() if b->next == NULL and block_write_avail == 0 and that
>> “appeared” to get us working again but I am not convinced that was the
>> correct solution. Concerned because it appears that other areas of the
>> code assume there will never be more than 2 buffers in the list and we
>> did not put a limit on the list length.
>>
>> So my question is when should the IOBufferBlock _end and _start have
>> been reset() to free the buffer space? I assumed that since we were seeing
>> a serial Packet(GET), ACK, Packet(GET), ACK, Packet(GET), ACK, that the
>> Buffer space could/should have been reset after each ACK?
>>
>> Also curious if this is a known issue with ATS 6.0.0 that has been
>> addressed or is known/unaddressed?
>>
>> Continuing to dig through the code in the mean time. Any feedback, insight,
>> etc. would be appreciated…
>>
>> Thanks,
>>
>> Craig S.
>>
>
>
>
>
Re: SSLNetVConnection IOBufferBlock management issue
Posted by Alan Carroll <so...@yahoo-inc.com.INVALID>.
New blocks should be added to the writer chain in SSLNetVConnection::net_read_io with the call to buf.writer()->read_avail (because of the type of buf, MIOBufferAccessor, buf.writer() is MIOBuffer* and its write_avail() should extend the write chain if there is less than the low water mark of space left to write). So after not reading all of the packet in one pass, the socket should still have WRITE signaled and net_read_io should be called again, calling MIOBuffer::write_avail() and then ssl_read_from_net. This code is a bit messed up, Susan's PR is an attempt to make it better (more efficient, robust, and understandable).
On Friday, May 27, 2016 10:20 AM, Susan Hinrichs <sh...@network-geographics.com> wrote:
There is a PR that uses the buffer interface instead of the block
interface which results in simpler code. We are running this code
internally in Yahoo. It fixed a performance problem introduced by a fix
not yet landed in open source. Since the current code works, I haven't
pushed this PR. But if debugging anything in this area, I'd suggest
first moving to the buffer interface.
https://github.com/apache/trafficserver/pull/629/files
Alan just rediscovered how additional blocks are added in the existing
code. I'll let him respond with details on that.
Also, I'd suggest moving up to 6.1 or 6.2.x rather than 6.0.0. I don't
think many folks have deployed 6.0. We are starting to deploy 6.2 and
we tested a bit with 6.1 (and others have deployed 6.1).
On 5/27/2016 9:46 AM, Craig Schomburg (craigs) wrote:
> Hey folks,
>
> We are encountering a SSLVNetConnection IOBufferBlock buffer management
> issue in ATS 6.0.0 that we did not see in the earlier ATS 4.0.1 release
> Which we were using.
>
> What we see in ssl_read_from_net() is when we get multiple GET requests on
> a single SSL session, as each GET is processed and ACK/NACK’ed that the
> buffer is not reset and the space released for reuse. As a result, the
> available write_avail() space in the session IOBufferBlock buffer is
> reduced with each subsequent packet until we have insufficient space to
> buffer the packet.
>
> Also appears that ATS is set up to support a chain of 2 IOBufferBlock
> but since only 1 is allocated we bail out of the read loop in
> ssl_read_from_net() with a incomplete packet and then drop it.
>
> Request Response Txn-ID VC
> ---------------------------- ---------------- ------ --------------
> GET /call/187972?debug=1 200 OK 4 0x560bb93e6420
> b->write_avail()=4096, nread=0
> b->write_avail()=4096, nread=1900 (2196 left in buffer)
> nread=0 PARSE DONE
>
> GET /call/widget.jsp... 200 OK 5 0x560bb93e6420
> b->write_avail()=2196, nread=0
> b->write_avail()=2196, nread=2120 ( 76 left in buffer)
> nread=0 PARSE DONE
>
> GET /call/js/libs/require.js 304 Not Modified 6 0x560bb93e6420
> b->write_avail()=76, nread=0
> b->write_avail()=76, nread=76 ( 0 left)
> b->next is NULL so ssl_read_from_net() bails on read loop and remainder
> of packet is not read
>
> We hacked the ssl_read_from_net() code in the SSL_ERROR_NONE case to
> add_block() if b->next == NULL and block_write_avail == 0 and that
> “appeared” to get us working again but I am not convinced that was the
> correct solution. Concerned because it appears that other areas of the
> code assume there will never be more than 2 buffers in the list and we
> did not put a limit on the list length.
>
> So my question is when should the IOBufferBlock _end and _start have
> been reset() to free the buffer space? I assumed that since we were seeing
> a serial Packet(GET), ACK, Packet(GET), ACK, Packet(GET), ACK, that the
> Buffer space could/should have been reset after each ACK?
>
> Also curious if this is a known issue with ATS 6.0.0 that has been
> addressed or is known/unaddressed?
>
> Continuing to dig through the code in the mean time. Any feedback, insight,
> etc. would be appreciated…
>
> Thanks,
>
> Craig S.
>
Re: SSLNetVConnection IOBufferBlock management issue
Posted by "Craig Schomburg (craigs)" <cr...@cisco.com>.
On 5/31/16, 11:22 AM, "Susan Hinrichs" <sh...@network-geographics.com> wrote:
>Craig,
>
>Of the bugs you listed below, I'd only look at TS-4309. There are still
>some issues there that oknet points out. But that might be easier to
>debug. If nothing else, your initial read shouldn't be limited to 125
>bytes.
The initial read is simply limited to 125 based on how many bytes were
remaining in the IOBufferBlock after the 2 previous writes from the
preceding packets on the same SSL session.
>Looked more closely at your debug output again. Is this the first HTTP
>request after the SSL handshake? Or another request after previous
>requests on the connection?
In this case it was the 3rd read on the connection...
>Is this just HTTP1.1 over SSL or HTTP2/SPDY?
HTTP1.1
>Does your HTTP client perhaps spit out parts of the HTTP
>request in separate packets?
In the case of the 3rd packet it may have been split across two
packets (Wireshark indicated 2 packets).
>Is this normally generated client
>traffic? Or some sort of client test-harness generated traffic? Would
>be interesting to reproduce this behavior outside of your environment.
This is a normal Client request, not a test harness. They were checking
in a live environment comparing our same product release using ATS 4.1.0
and then again using 6.0.0 after our recent upgrade.
>
>It might be interesting to turn on "Wire tracing" to see the contents of
>processed SSL data. Look at the documentation for the
>proxy.config.ssl.wire_trace_enabled config element and related config
>items. This will place the traced data in error.log.
Thanks I’ll check this out…
More news to follow...
Craig S.
>
>Susan
>
>On 5/31/2016 9:11 AM, Craig Schomburg (craigs) wrote:
>> Susan,
>>
>> Have a few questions in trying to determine what direction we need to go from our end on our issue.
>>
>> Due to our pre-release test cycle time we are currently prepared to ship our next product update using the ATS 6.0.0 code base. Unfortunately we do not have the test window to move to a later release at this time.
>>
>> So based on your apparent intimate knowledge in this area as well as your knowledge of the changes that have been made over the past months and changes in the queue, were we to stick with ATS 6.0.0 what changes in this area do you recommend we try and pick up once committed and ready? I saw the following TS cases mentioned in various threads and all seemed to have dependancies of some sorts on TS-4309. So what of these should we potentially target trying to pick up/patch into our ATS 6.0.0 based release?
>>
>> - TS-4309 Reduced SSL upload/download speed after event loop change (TS-4260)
>> - TS-4487 Don't reschedule read depend on needs & did not check the change of lock at the return callback with wbe.
>> - TS-4260 Change event loop to always stall on waiting for I/O.
>> - TS-4424 ASAN: heap-buffer-overflow in 6.2.x branch
>>
>> We did a temporary hack to get around the read issue we were hitting in 6.0.0 but based on internal testing we realize it is not the proper solution (i.e. Was not the root cause fix but rather a temporary bandaid while we continue our investigation). I am now digging into the previous ATS release we had working (4.1.0) to try and identify what changed that is leading to the issue we are now hitting (PARSE_CONT on incomplete read but read does not continue to read the remaining data). Hope to have more/better data to work with on this issue later this week.
>>
>> Any insight or words of wisdom from the experts in this area is greatly appreciated!
>>
>> Thanks,
>>
>> Craig S.
>>
>>
>>
>>
>>
>> On 5/27/16, 11:19 AM, "Susan Hinrichs" <sh...@network-geographics.com> wrote:
>>
>>> There is a PR that uses the buffer interface instead of the block
>>> interface which results in simpler code. We are running this code
>>> internally in Yahoo. It fixed a performance problem introduced by a fix
>>> not yet landed in open source. Since the current code works, I haven't
>>> pushed this PR. But if debugging anything in this area, I'd suggest
>>> first moving to the buffer interface.
>>>
>>> https://github.com/apache/trafficserver/pull/629/files
>>>
>>> Alan just rediscovered how additional blocks are added in the existing
>>> code. I'll let him respond with details on that.
>>>
>>> Also, I'd suggest moving up to 6.1 or 6.2.x rather than 6.0.0. I don't
>>> think many folks have deployed 6.0. We are starting to deploy 6.2 and
>>> we tested a bit with 6.1 (and others have deployed 6.1).
>>>
>>>
>>> On 5/27/2016 9:46 AM, Craig Schomburg (craigs) wrote:
>>>> Hey folks,
>>>>
>>>> We are encountering a SSLVNetConnection IOBufferBlock buffer management
>>>> issue in ATS 6.0.0 that we did not see in the earlier ATS 4.0.1 release
>>>> Which we were using.
>>>>
>>>> What we see in ssl_read_from_net() is when we get multiple GET requests on
>>>> a single SSL session, as each GET is processed and ACK/NACK’ed that the
>>>> buffer is not reset and the space released for reuse. As a result, the
>>>> available write_avail() space in the session IOBufferBlock buffer is
>>>> reduced with each subsequent packet until we have insufficient space to
>>>> buffer the packet.
>>>>
>>>> Also appears that ATS is set up to support a chain of 2 IOBufferBlock
>>>> but since only 1 is allocated we bail out of the read loop in
>>>> ssl_read_from_net() with a incomplete packet and then drop it.
>>>>
>>>> Request Response Txn-ID VC
>>>> ---------------------------- ---------------- ------ --------------
>>>> GET /call/187972?debug=1 200 OK 4 0x560bb93e6420
>>>> b->write_avail()=4096, nread=0
>>>> b->write_avail()=4096, nread=1900 (2196 left in buffer)
>>>> nread=0 PARSE DONE
>>>>
>>>> GET /call/widget.jsp... 200 OK 5 0x560bb93e6420
>>>> b->write_avail()=2196, nread=0
>>>> b->write_avail()=2196, nread=2120 ( 76 left in buffer)
>>>> nread=0 PARSE DONE
>>>>
>>>> GET /call/js/libs/require.js 304 Not Modified 6 0x560bb93e6420
>>>> b->write_avail()=76, nread=0
>>>> b->write_avail()=76, nread=76 ( 0 left)
>>>> b->next is NULL so ssl_read_from_net() bails on read loop and remainder
>>>> of packet is not read
>>>>
>>>> We hacked the ssl_read_from_net() code in the SSL_ERROR_NONE case to
>>>> add_block() if b->next == NULL and block_write_avail == 0 and that
>>>> “appeared” to get us working again but I am not convinced that was the
>>>> correct solution. Concerned because it appears that other areas of the
>>>> code assume there will never be more than 2 buffers in the list and we
>>>> did not put a limit on the list length.
>>>>
>>>> So my question is when should the IOBufferBlock _end and _start have
>>>> been reset() to free the buffer space? I assumed that since we were seeing
>>>> a serial Packet(GET), ACK, Packet(GET), ACK, Packet(GET), ACK, that the
>>>> Buffer space could/should have been reset after each ACK?
>>>>
>>>> Also curious if this is a known issue with ATS 6.0.0 that has been
>>>> addressed or is known/unaddressed?
>>>>
>>>> Continuing to dig through the code in the mean time. Any feedback, insight,
>>>> etc. would be appreciated…
>>>>
>>>> Thanks,
>>>>
>>>> Craig S.
>>>>
>
Re: SSLNetVConnection IOBufferBlock management issue
Posted by Susan Hinrichs <sh...@network-geographics.com>.
Craig,
Of the bugs you listed below, I'd only look at TS-4309. There are still
some issues there that oknet points out. But that might be easier to
debug. If nothing else, your initial read shouldn't be limited to 125
bytes.
Looked more closely at your debug output again. Is this the first HTTP
request after the SSL handshake? Or another request after previous
requests on the connection? Is this just HTTP1.1 over SSL or
HTTP2/SPDY? Does your HTTP client perhaps spit out parts of the HTTP
request in separate packets? Is this normally generated client
traffic? Or some sort of client test-harness generated traffic? Would
be interesting to reproduce this behavior outside of your environment.
It might be interesting to turn on "Wire tracing" to see the contents of
processed SSL data. Look at the documentation for the
proxy.config.ssl.wire_trace_enabled config element and related config
items. This will place the traced data in error.log.
Susan
On 5/31/2016 9:11 AM, Craig Schomburg (craigs) wrote:
> Susan,
>
> Have a few questions in trying to determine what direction we need to go from our end on our issue.
>
> Due to our pre-release test cycle time we are currently prepared to ship our next product update using the ATS 6.0.0 code base. Unfortunately we do not have the test window to move to a later release at this time.
>
> So based on your apparent intimate knowledge in this area as well as your knowledge of the changes that have been made over the past months and changes in the queue, were we to stick with ATS 6.0.0 what changes in this area do you recommend we try and pick up once committed and ready? I saw the following TS cases mentioned in various threads and all seemed to have dependancies of some sorts on TS-4309. So what of these should we potentially target trying to pick up/patch into our ATS 6.0.0 based release?
>
> - TS-4309 Reduced SSL upload/download speed after event loop change (TS-4260)
> - TS-4487 Don't reschedule read depend on needs & did not check the change of lock at the return callback with wbe.
> - TS-4260 Change event loop to always stall on waiting for I/O.
> - TS-4424 ASAN: heap-buffer-overflow in 6.2.x branch
>
> We did a temporary hack to get around the read issue we were hitting in 6.0.0 but based on internal testing we realize it is not the proper solution (i.e. Was not the root cause fix but rather a temporary bandaid while we continue our investigation). I am now digging into the previous ATS release we had working (4.1.0) to try and identify what changed that is leading to the issue we are now hitting (PARSE_CONT on incomplete read but read does not continue to read the remaining data). Hope to have more/better data to work with on this issue later this week.
>
> Any insight or words of wisdom from the experts in this area is greatly appreciated!
>
> Thanks,
>
> Craig S.
>
>
>
>
>
> On 5/27/16, 11:19 AM, "Susan Hinrichs" <sh...@network-geographics.com> wrote:
>
>> There is a PR that uses the buffer interface instead of the block
>> interface which results in simpler code. We are running this code
>> internally in Yahoo. It fixed a performance problem introduced by a fix
>> not yet landed in open source. Since the current code works, I haven't
>> pushed this PR. But if debugging anything in this area, I'd suggest
>> first moving to the buffer interface.
>>
>> https://github.com/apache/trafficserver/pull/629/files
>>
>> Alan just rediscovered how additional blocks are added in the existing
>> code. I'll let him respond with details on that.
>>
>> Also, I'd suggest moving up to 6.1 or 6.2.x rather than 6.0.0. I don't
>> think many folks have deployed 6.0. We are starting to deploy 6.2 and
>> we tested a bit with 6.1 (and others have deployed 6.1).
>>
>>
>> On 5/27/2016 9:46 AM, Craig Schomburg (craigs) wrote:
>>> Hey folks,
>>>
>>> We are encountering a SSLVNetConnection IOBufferBlock buffer management
>>> issue in ATS 6.0.0 that we did not see in the earlier ATS 4.0.1 release
>>> Which we were using.
>>>
>>> What we see in ssl_read_from_net() is when we get multiple GET requests on
>>> a single SSL session, as each GET is processed and ACK/NACK\u2019ed that the
>>> buffer is not reset and the space released for reuse. As a result, the
>>> available write_avail() space in the session IOBufferBlock buffer is
>>> reduced with each subsequent packet until we have insufficient space to
>>> buffer the packet.
>>>
>>> Also appears that ATS is set up to support a chain of 2 IOBufferBlock
>>> but since only 1 is allocated we bail out of the read loop in
>>> ssl_read_from_net() with a incomplete packet and then drop it.
>>>
>>> Request Response Txn-ID VC
>>> ---------------------------- ---------------- ------ --------------
>>> GET /call/187972?debug=1 200 OK 4 0x560bb93e6420
>>> b->write_avail()=4096, nread=0
>>> b->write_avail()=4096, nread=1900 (2196 left in buffer)
>>> nread=0 PARSE DONE
>>>
>>> GET /call/widget.jsp... 200 OK 5 0x560bb93e6420
>>> b->write_avail()=2196, nread=0
>>> b->write_avail()=2196, nread=2120 ( 76 left in buffer)
>>> nread=0 PARSE DONE
>>>
>>> GET /call/js/libs/require.js 304 Not Modified 6 0x560bb93e6420
>>> b->write_avail()=76, nread=0
>>> b->write_avail()=76, nread=76 ( 0 left)
>>> b->next is NULL so ssl_read_from_net() bails on read loop and remainder
>>> of packet is not read
>>>
>>> We hacked the ssl_read_from_net() code in the SSL_ERROR_NONE case to
>>> add_block() if b->next == NULL and block_write_avail == 0 and that
>>> \u201cappeared\u201d to get us working again but I am not convinced that was the
>>> correct solution. Concerned because it appears that other areas of the
>>> code assume there will never be more than 2 buffers in the list and we
>>> did not put a limit on the list length.
>>>
>>> So my question is when should the IOBufferBlock _end and _start have
>>> been reset() to free the buffer space? I assumed that since we were seeing
>>> a serial Packet(GET), ACK, Packet(GET), ACK, Packet(GET), ACK, that the
>>> Buffer space could/should have been reset after each ACK?
>>>
>>> Also curious if this is a known issue with ATS 6.0.0 that has been
>>> addressed or is known/unaddressed?
>>>
>>> Continuing to dig through the code in the mean time. Any feedback, insight,
>>> etc. would be appreciated\u2026
>>>
>>> Thanks,
>>>
>>> Craig S.
>>>
Re: SSLNetVConnection IOBufferBlock management issue
Posted by Alan Carroll <so...@yahoo-inc.com.INVALID>.
TS-4260 isn't ready to ship yet, so you don't want that. TS-4309 is useful but only fixes an issue that arises due to timing changes from TS-4260. I'm not sure about the other two.
On Tuesday, May 31, 2016 9:12 AM, Craig Schomburg (craigs) <cr...@cisco.com> wrote:
Susan,
- TS-4309 Reduced SSL upload/download speed after event loop change (TS-4260)
- TS-4487 Don't reschedule read depend on needs & did not check the change of lock at the return callback with wbe.
- TS-4260 Change event loop to always stall on waiting for I/O.
- TS-4424 ASAN: heap-buffer-overflow in 6.2.x branch
Re: SSLNetVConnection IOBufferBlock management issue
Posted by "Craig Schomburg (craigs)" <cr...@cisco.com>.
Susan,
Have a few questions in trying to determine what direction we need to go from our end on our issue.
Due to our pre-release test cycle time we are currently prepared to ship our next product update using the ATS 6.0.0 code base. Unfortunately we do not have the test window to move to a later release at this time.
So based on your apparent intimate knowledge in this area as well as your knowledge of the changes that have been made over the past months and changes in the queue, were we to stick with ATS 6.0.0 what changes in this area do you recommend we try and pick up once committed and ready? I saw the following TS cases mentioned in various threads and all seemed to have dependancies of some sorts on TS-4309. So what of these should we potentially target trying to pick up/patch into our ATS 6.0.0 based release?
- TS-4309 Reduced SSL upload/download speed after event loop change (TS-4260)
- TS-4487 Don't reschedule read depend on needs & did not check the change of lock at the return callback with wbe.
- TS-4260 Change event loop to always stall on waiting for I/O.
- TS-4424 ASAN: heap-buffer-overflow in 6.2.x branch
We did a temporary hack to get around the read issue we were hitting in 6.0.0 but based on internal testing we realize it is not the proper solution (i.e. Was not the root cause fix but rather a temporary bandaid while we continue our investigation). I am now digging into the previous ATS release we had working (4.1.0) to try and identify what changed that is leading to the issue we are now hitting (PARSE_CONT on incomplete read but read does not continue to read the remaining data). Hope to have more/better data to work with on this issue later this week.
Any insight or words of wisdom from the experts in this area is greatly appreciated!
Thanks,
Craig S.
On 5/27/16, 11:19 AM, "Susan Hinrichs" <sh...@network-geographics.com> wrote:
>There is a PR that uses the buffer interface instead of the block
>interface which results in simpler code. We are running this code
>internally in Yahoo. It fixed a performance problem introduced by a fix
>not yet landed in open source. Since the current code works, I haven't
>pushed this PR. But if debugging anything in this area, I'd suggest
>first moving to the buffer interface.
>
>https://github.com/apache/trafficserver/pull/629/files
>
>Alan just rediscovered how additional blocks are added in the existing
>code. I'll let him respond with details on that.
>
>Also, I'd suggest moving up to 6.1 or 6.2.x rather than 6.0.0. I don't
>think many folks have deployed 6.0. We are starting to deploy 6.2 and
>we tested a bit with 6.1 (and others have deployed 6.1).
>
>
>On 5/27/2016 9:46 AM, Craig Schomburg (craigs) wrote:
>> Hey folks,
>>
>> We are encountering a SSLVNetConnection IOBufferBlock buffer management
>> issue in ATS 6.0.0 that we did not see in the earlier ATS 4.0.1 release
>> Which we were using.
>>
>> What we see in ssl_read_from_net() is when we get multiple GET requests on
>> a single SSL session, as each GET is processed and ACK/NACK’ed that the
>> buffer is not reset and the space released for reuse. As a result, the
>> available write_avail() space in the session IOBufferBlock buffer is
>> reduced with each subsequent packet until we have insufficient space to
>> buffer the packet.
>>
>> Also appears that ATS is set up to support a chain of 2 IOBufferBlock
>> but since only 1 is allocated we bail out of the read loop in
>> ssl_read_from_net() with a incomplete packet and then drop it.
>>
>> Request Response Txn-ID VC
>> ---------------------------- ---------------- ------ --------------
>> GET /call/187972?debug=1 200 OK 4 0x560bb93e6420
>> b->write_avail()=4096, nread=0
>> b->write_avail()=4096, nread=1900 (2196 left in buffer)
>> nread=0 PARSE DONE
>>
>> GET /call/widget.jsp... 200 OK 5 0x560bb93e6420
>> b->write_avail()=2196, nread=0
>> b->write_avail()=2196, nread=2120 ( 76 left in buffer)
>> nread=0 PARSE DONE
>>
>> GET /call/js/libs/require.js 304 Not Modified 6 0x560bb93e6420
>> b->write_avail()=76, nread=0
>> b->write_avail()=76, nread=76 ( 0 left)
>> b->next is NULL so ssl_read_from_net() bails on read loop and remainder
>> of packet is not read
>>
>> We hacked the ssl_read_from_net() code in the SSL_ERROR_NONE case to
>> add_block() if b->next == NULL and block_write_avail == 0 and that
>> “appeared” to get us working again but I am not convinced that was the
>> correct solution. Concerned because it appears that other areas of the
>> code assume there will never be more than 2 buffers in the list and we
>> did not put a limit on the list length.
>>
>> So my question is when should the IOBufferBlock _end and _start have
>> been reset() to free the buffer space? I assumed that since we were seeing
>> a serial Packet(GET), ACK, Packet(GET), ACK, Packet(GET), ACK, that the
>> Buffer space could/should have been reset after each ACK?
>>
>> Also curious if this is a known issue with ATS 6.0.0 that has been
>> addressed or is known/unaddressed?
>>
>> Continuing to dig through the code in the mean time. Any feedback, insight,
>> etc. would be appreciated…
>>
>> Thanks,
>>
>> Craig S.
>>
>
Re: SSLNetVConnection IOBufferBlock management issue
Posted by Susan Hinrichs <sh...@network-geographics.com>.
There is a PR that uses the buffer interface instead of the block
interface which results in simpler code. We are running this code
internally in Yahoo. It fixed a performance problem introduced by a fix
not yet landed in open source. Since the current code works, I haven't
pushed this PR. But if debugging anything in this area, I'd suggest
first moving to the buffer interface.
https://github.com/apache/trafficserver/pull/629/files
Alan just rediscovered how additional blocks are added in the existing
code. I'll let him respond with details on that.
Also, I'd suggest moving up to 6.1 or 6.2.x rather than 6.0.0. I don't
think many folks have deployed 6.0. We are starting to deploy 6.2 and
we tested a bit with 6.1 (and others have deployed 6.1).
On 5/27/2016 9:46 AM, Craig Schomburg (craigs) wrote:
> Hey folks,
>
> We are encountering a SSLVNetConnection IOBufferBlock buffer management
> issue in ATS 6.0.0 that we did not see in the earlier ATS 4.0.1 release
> Which we were using.
>
> What we see in ssl_read_from_net() is when we get multiple GET requests on
> a single SSL session, as each GET is processed and ACK/NACK\u2019ed that the
> buffer is not reset and the space released for reuse. As a result, the
> available write_avail() space in the session IOBufferBlock buffer is
> reduced with each subsequent packet until we have insufficient space to
> buffer the packet.
>
> Also appears that ATS is set up to support a chain of 2 IOBufferBlock
> but since only 1 is allocated we bail out of the read loop in
> ssl_read_from_net() with a incomplete packet and then drop it.
>
> Request Response Txn-ID VC
> ---------------------------- ---------------- ------ --------------
> GET /call/187972?debug=1 200 OK 4 0x560bb93e6420
> b->write_avail()=4096, nread=0
> b->write_avail()=4096, nread=1900 (2196 left in buffer)
> nread=0 PARSE DONE
>
> GET /call/widget.jsp... 200 OK 5 0x560bb93e6420
> b->write_avail()=2196, nread=0
> b->write_avail()=2196, nread=2120 ( 76 left in buffer)
> nread=0 PARSE DONE
>
> GET /call/js/libs/require.js 304 Not Modified 6 0x560bb93e6420
> b->write_avail()=76, nread=0
> b->write_avail()=76, nread=76 ( 0 left)
> b->next is NULL so ssl_read_from_net() bails on read loop and remainder
> of packet is not read
>
> We hacked the ssl_read_from_net() code in the SSL_ERROR_NONE case to
> add_block() if b->next == NULL and block_write_avail == 0 and that
> \u201cappeared\u201d to get us working again but I am not convinced that was the
> correct solution. Concerned because it appears that other areas of the
> code assume there will never be more than 2 buffers in the list and we
> did not put a limit on the list length.
>
> So my question is when should the IOBufferBlock _end and _start have
> been reset() to free the buffer space? I assumed that since we were seeing
> a serial Packet(GET), ACK, Packet(GET), ACK, Packet(GET), ACK, that the
> Buffer space could/should have been reset after each ACK?
>
> Also curious if this is a known issue with ATS 6.0.0 that has been
> addressed or is known/unaddressed?
>
> Continuing to dig through the code in the mean time. Any feedback, insight,
> etc. would be appreciated\u2026
>
> Thanks,
>
> Craig S.
>