[squid-users] RE Peek and Splice error SSL_accept failed

[Amos Jeffries]

On 25/07/2015 12:09 a.m., Sebastian Kirschner wrote:
> Hi ,
> 
> I minimized the configuration a little bit(you could see it at the bottom of these message).
> 
> Also I still try to understand why these error happen ,

Lets be clear. "error" are not happening. If errors happend Squid logs
them with a huge "ERROR:" or "FATAL:" log entry.

Specific things trying to happen can fail, or not. That is normal and
hapens all the time when trying to interpret externally generated
information such as the bytes arriving in over network socket.

In this case Squid is trying to figure out of the connection is actually
a TLS connection *or something else*.

> I increased the Debug level and saw that squid tried 48 times to peek but failed.
> At the end It says that it got an "Hello", does it mean that squid received after 48 tries the "Hello" ?
> 
> If yes why it does need so many tries ?

Depends on what a "try" is, and why it was tried.

> 
> -> Part of debug log <-
> 2015/07/24 11:05:42.866 kid1| client_side.cc(4242) clientPeekAndSpliceSSL: Start peek and splice on FD 11
> 2015/07/24 11:05:42.866 kid1| bio.cc(120) read: FD 11 read 11 <= 11
> 2015/07/24 11:05:42.866 kid1| bio.cc(146) readAndBuffer: read 11 out of 11 bytes
> 2015/07/24 11:05:42.866 kid1| bio.cc(150) readAndBuffer: recorded 11 bytes of TLS client Hello
> 2015/07/24 11:05:42.866 kid1| ModEpoll.cc(116) SetSelect: FD 11, type=1, handler=1, client_data=0x7effbd078458, timeout=0
> 2015/07/24 11:05:42.866 kid1| client_side.cc(4245) clientPeekAndSpliceSSL: SSL_accept failed.

Could be 11 bytes of anything.

Squid believes the 11 bytes maybe are a clientHello (which is 11 bytes
in size). Sends them to processing which fails to parse a clientHello
out of it.
Squid goes back to read(2) to see if anything else arrives.


> .
> 2015/07/24 11:05:42.874 kid1| client_side.cc(4242) clientPeekAndSpliceSSL: Start peek and splice on FD 11
> 2015/07/24 11:05:42.874 kid1| bio.cc(120) read: FD 11 read 6 <= 11
> 2015/07/24 11:05:42.874 kid1| bio.cc(146) readAndBuffer: read 6 out of 11 bytes
> 2015/07/24 11:05:42.874 kid1| bio.cc(150) readAndBuffer: recorded 6 bytes of TLS client Hello


This is a bit obscure. 6 *more* bytes arrive from FD 11.

Now we probably have 17 bytes in the I/O buffer. The bio.c code knows
that 6 bytes alone is not enough for clientHello. But it seems to be
ignoring or forgotten about the previous read.


> 2015/07/24 11:05:42.875 kid1| SBuf.cc(152) assign: SBuf2040 from c-string, n=0)
> 2015/07/24 11:05:42.875 kid1| SBuf.cc(152) assign: SBuf2038 from c-string, n=13)

The buffer says 13 bytes to be processed. Note that 13 >= 11 for the
clientHello.

I have no idea what the first 4 bytes were or went. Guess maybe some SSL
alert notice the SSL_accept() code absorbed and adjusted the context to
use later? But not part of a clientHello either way.


> 2015/07/24 11:05:42.875 kid1| ModEpoll.cc(116) SetSelect: FD 11, type=1, handler=1, client_data=0x7effbd078458, timeout=0
> 2015/07/24 11:05:42.875 kid1| client_side.cc(4245) clientPeekAndSpliceSSL: SSL_accept failed.
> 2015/07/24 11:05:42.875 kid1| SBuf.cc(152) assign: SBuf2025 from c-string, n=4294967295)
> 2015/07/24 11:05:42.875 kid1| client_side.cc(4259) clientPeekAndSpliceSSL: I got hello. Start forwarding the request!!!


Thus Squid believes the 13 bytes has in bufer are a clientHello (which
is 11? bytes). Sends them to processing which succeeds to parse it as a
clientHello. SSL-Bump "peek" at stage 1 completed.

In Summary:
 Looks like normal network operations to me. No errors. Just a temporary
failure to have the whole thing in memory on first parse attempt.


Take that with a grain of salt though. Squid is event driven and there
is no guarantee that any two adjacent log lines are even reporting about
the same transaction. These could be two entirely separate TCP
connections independently arriving and being assigned to FD 11. One
having non-TLS protocol delivered and rejected, one having TLS started.
I assumed that the '...' added dont omit any other FD 11 lines.

I/we would have to see the input data analysis by wireshark and
cross-check it against the Squid code to be sure of the above. But I've
~80% confident thats correct interpretation of the log.


Amos