[Dovecot] imap-login hanging when firewall blocks ssl handshaking

[Erik A Johnson]

No, the test to bug out doesn't work because net_geterror(proxy->fd_ssl) returns 0 in the statement

   if (!proxy->client_proxy &&
       net_geterror(proxy->fd_ssl) == ENOTCONN) {

However, errno is indeed ENOTCONN.  Changing the test to

   if (!proxy->client_proxy &&
       errno == ENOTCONN) {

does do the job (i.e., stopping the process with the "syscall failed" error message), though I'm sure I don't understand the ins and outs well enough to know if that is an appropriate test.  The full log line is:

    Nov 29 07:39:14 SERVER dovecot[24362]: imap-login: Disconnected (disconnected before greeting, waited 0 secs): user=<>, rip=CLIENTIP, lip=SERVERIP, TLS handshaking: SSL_accept() syscall failed: Socket is not connected, session=<d5DNFaTP8QAKAAFi>

Thoughts?

On Nov 28, 2012, at 10:18PM PST, Timo Sirainen <tss at iki.fi> wrote:
> This is either OSX bug or OpenSSL bug.. Apparently what happens is:
> 
> 1. Client sends SYN packet to Dovecot
> 2. Dovecot accept()s the connection (sends SYN-ACK) and goes into OpenSSL code
> 3. Client doesn't send ACK to Dovecot. Does it send RST or nothing or something else? I don't know.
> 4. OSX notices anyway that something is wrong with the socket, and kqueue says that the socket is ready for reading
> 5. OpenSSL read()s, which fails with ENOTCONN. But OpenSSL thinks this is a non-fatal error and simply asks to be notified again when something can be read
> 6. goto 4
> 
> So, whose bug is it? OpenSSL's ENOTCONN handling probably makes sense for client connections where connect() hasn't finished yet. But then again, this is accept()ed connection where it typically should fail like that. Except I guess it might be correct behavior if read() is done after SYN-ACK but before receiving ACK.
> 
> While OSX is receiving ACK from the client, it shouldn't say that the fd is readable. It probably doesn't. But after it receives <something> it realizes that the socket is disconnected. So read() probably shouldn't be returning ENOTCONN anymore at this point, but instead ECONNRESET or ETIMEDOUT.
> 
> See if the attached patch helps.
> 
> 
> On 29.11.2012, at 7.45, Erik A Johnson wrote:
>> Here's the log:
>> 
>> Nov 28 21:28:11 macbookpro-e17d.home dovecot[54139]: master: Dovecot v2.1.10 starting up (core dumps disabled)
>> Nov 28 21:30:19 macbookpro-e17d.home dovecot[54141]: imap-login: Debug: ssl_step()
>> Nov 28 21:30:19 macbookpro-e17d.home dovecot[54141]: imap-login: Debug: ssl_handshake: SSL_accept()=-1
>> Nov 28 21:30:19 macbookpro-e17d.home dovecot[54141]: imap-login: Debug: SSL_get_error() = 2
>> Nov 28 21:30:19 macbookpro-e17d.home dovecot[54141]: imap-login: Debug:  - want_read
>> Nov 28 21:30:19 macbookpro-e17d.home dovecot[54141]: imap-login: Debug: ssl_set_io(0)
>> [last 5 lines are repeated until process is killed]
>> 
>> On Nov 26, 2012, as 11:38PM PST, Timo Sirainen <tss at iki.fi> wrote:
>>> 
>>> Could you try with the attached patch, and with only the problematic
>>> client running? What does it log (the beginning of the session until it
>>> starts repeating the same lines)?
>>> 
>>> On 10.11.2012, at 12.44, Erik A Johnson wrote:
>>>> imap-login processes are hanging (using 100% of CPU) when connected from a client that is partially blocked by a firewall.  It appears that imap-login is stuck in a loop trying to complete an ssl handshake.  imap-login is working fine for other clients not blocked by the firewall (including localhost).
>>>> 
>>>> This is dovecot 2.1.10 under Mac OS X 10.8.2 (compiled from sources); the firewall is Little Snitch 3.0.1 blocking port 993, which appears to let the connection initiate but then squashes and disconnects the socket during ssl handshaking.
>>>> 
>>>> gdb backtrace and Activity Monitor's "Sample Process" show that imap-login is stuck calling ioloop-kqueue's io_loop_handler_run -> io_loop_call_io -> ssl_step repeatedly; dtruss shows that it is repeatedly making system calls to kevent and read, the latter returning -1 with errno 57=ENOTCONN="Socket is not connected".  (I also tried ./configure --with-ioloop=poll and --with-iopoll=select instead of the default best = kqueue but the results were the same; --with-iopoll=epoll didn't work because epoll is not available on this machine.)  The client, initiated by the command "openssl s_client -connect SERVER:993", first responds "CONNECTED(00000003)" but then immediately the error "60278:error:140790E5:SSL routines:SSL23_WRITE:ssl handshake failure:/SourceCache/OpenSSL098/OpenSSL098-44/src/ssl/s23_lib.c:182:".  The infinite loop is in src/lib/ioloop.c in the function "io_loop_run" where the statement "while (ioloop->running) io_loop_handler_run(ioloop)" is executed.
> 
>