Re: timout of 'SSL bumped' connect triggers assert in forward.cc

On 01/13/2013 03:10 PM, Rainer Weikusat wrote:
> Assuming that a client attempted to contact a HTTPS server which is
> actually a 'port 443 blackhole' (meaning, attempts to connect to the
> corresponding address and port 443 don't result in any kind of reply)
> and this request was intercepted by a squid configured to do 'server
> first' SSL bumping, the timeout squid enforces for the asynchronous
> connect requests ultimatively triggers in assert in forward.cc. This
> happens because the ConnOpener::timeout method calls
> ConnOpener::connect which - in turn - calls comm_connect_addr to
> determine the status of the connection attempt. This routine uses
> getsockopt/ SOL_SOCKET/ SO_ERROR to determine if the connect
> succeeded. Because nothing was received from the remote endpoint, at
> least on Linux, the result will be 'no error' which means a 'false
> positive' 'connection sucessfully established' situation
> occurs.

Hi Rainer,

    Nice analysis, thank you! Have you seen the discussion about
ConnOpener problems in the squid-dev thread called "ICAP connections
under heavy loads"? (If you have not, please review -- it is mostly not
about ICAP). I suspect the comprehensive solution sketched out there
solves this problem as well.

Thank you,

Alex.

> Somewhat later, a second timeout will occur for the file
> descriptor in question which leads to the destruction of the
> corresponding FwdState. Because nothing was ever received and no
> 'error status' was set, this triggers the assert on line 217. of
> forward.cc, causing squid to abort.
>
> Below is a (somewhat hackish) patch with a suggested fix for this
> situation which avoids a major code re-shuffling (IMHO, ::timeout
> should call ::connect to begin with ...). It consists of two pieces:
> The timeout checks in ConnOpener::connect are modified to use >=
> instead of > to detect if a timeout occurred. This is necessary
> because the ::timeout timeout happens quickly enough after the timeout
> expired that another second hasn't passed by the time ::connect gets a
> chance to check for it. The second part is a change to
> comm_connect_addr: After 'no error' was returned by the getsockopt
> call, F->write_handler is checked for being still set. If this is the
> case, comm_connect_addr was not called because the descriptor really
> became writeable since the 'I/O multiplexing code' had otherwise
> cleared the write_handler member prior to invoking the corresponding
> function. errno is then set to EINPROGESS, reflecting the actual state
> of the connection. This causes the caller to do its timeout check
> which leads to an 'orderly abort' of failed connection attempt.
>
> The patch applies cleanly to the lasted to the r12450 squid 3.3.0.3
> 'auto-generated' release.
>
> -----------------
> --- mad-squid/src/comm.cc 8 Jan 2013 18:29:41 -0000 1.1.1.2.2.1
> +++ mad-squid/src/comm.cc 13 Jan 2013 21:35:41 -0000 1.1.1.2.2.2
> @@ -887,7 +887,24 @@
>
> #endif
> #endif
> -
> + /* If an 'in progress' connect attempt times out,
> + * this routine will be called (via ConnOpener::connect)
> + * from ConnOpener::timeout. Because errno will be 0 in
> + * this case, it will be confused with successful
> + * establishment of a connection, ultimatively (at least
> + * for 'server first' bumped intercepted HTTPS requests)
> + * triggering an assert in forward.cc when the 'expired'
> + * file descriptor is forcibly closed after a subsequent
> + * timeout occurred.
> + *
> + * F->write_handler will have been cleared in case
> + * this routine was called because the descriptor actually
> + * became writeable so it can be used to detect the situation
> + * describe above and to signal to the caller that the
> + * connection wasn't really established.
> + */
> + if (!errno && F->write_handler)
> + errno = EINPROGRESS;
> }
>
> /* Squid seems to be working fine without this code. With this code,
> --- mad-squid/src/comm/ConnOpener.cc 8 Jan 2013 18:30:27 -0000 1.1.1.1.2.1
> +++ mad-squid/src/comm/ConnOpener.cc 13 Jan 2013 21:36:41 -0000 1.1.1.1.2.3
> @@ -243,7 +243,7 @@
>
> case COMM_INPROGRESS:
> // check for timeout FIRST.
> - if (squid_curtime - connectStart_ > connectTimeout_) {
> + if (squid_curtime - connectStart_ >= connectTimeout_) {
> debugs(5, 5, HERE << conn_ << ": * - ERR took too long already.");
> calls_.earlyAbort_->cancel("Comm::ConnOpener::connect timed out");
> doneConnecting(COMM_TIMEOUT, errno);
> @@ -264,7 +264,7 @@
> ++failRetries_;
>
> // check for timeout FIRST.
> - if (squid_curtime - connectStart_ > connectTimeout_) {
> + if (squid_curtime - connectStart_ >= connectTimeout_) {
> debugs(5, 5, HERE << conn_ << ": * - ERR took too long to receive response.");
> calls_.earlyAbort_->cancel("Comm::ConnOpener::connect timed out");
> doneConnecting(COMM_TIMEOUT, errno);
>
Received on Mon Jan 14 2013 - 04:34:50 MST