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

[Erik A Johnson]

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.

While I think the firewall is not doing the right thing (i.e., it lets a connection start but then kills it), it seems that imap-login should fail gracefully when the socket is no longer connected.

Ideas?  Thanks.


-----------------------------------

/usr/local/sbin/dovecot -n

# 2.1.10: /usr/local/etc/dovecot/dovecot.conf
# OS: Darwin 12.2.0 x86_64  
default_internal_user = _dovecot
default_login_user = _dovenull
namespace {
  hidden = no
  list = yes
  location = mbox:/Users/%u/Documents/Mailboxes
  prefix = mbox/
  separator = /
  type = private
}
namespace {
  inbox = yes
  location = maildir:/Users/%u/Documents/Maildir
  mailbox Drafts {
    special_use = \Drafts
  }
  mailbox Junk {
    special_use = \Junk
  }
  mailbox Sent {
    special_use = \Sent
  }
  mailbox Trash {
    special_use = \Trash
  }
  prefix = 
  separator = /
  type = private
}
passdb {
  driver = pam
}
protocols = imap lmtp
ssl = required
ssl_cert = </usr/local/etc/dovecot/dovecot.pem
ssl_key = </usr/local/etc/dovecot/dovecot.pem
userdb {
  driver = passwd
}
protocol imap {
  mail_plugins = " zlib imap_zlib"
}

-----------------------------------

gdb's "bt full" gives various results depending on where in the loop, but they are they same from ssl23_accept on down.

(gdb) bt full
#0  0x00007fff92d19f63 in sha1_block_data_order ()
#1  0x00007fff92d1a4ae in SHA1_Final ()
#2  0x00007fff92d45430 in EVP_DigestFinal_ex ()
#3  0x00007fff92d17d7a in ssleay_rand_add ()
#4  0x00007fff974529be in ssl23_accept ()
#5  0x000000010cac0729 in ssl_handshake [inlined] () at /private/tmp/johnsone/dovecot-2.1.10/src/login-common/ssl-proxy-openssl.c:465
	ret = -949939536
#6  0x000000010cac0729 in ssl_step (proxy=0x7fff53152b90) at ssl-proxy-openssl.c:528
	ret = -949939536
#7  0x000000010cb11bd1 in io_loop_call_io (io=0x7f7fa0c1c240) at ioloop.c:379
	ioloop = (struct ioloop *) 0x7f7fa0c03b00
	t_id = 2
#8  0x000000010cb12c69 in io_loop_handler_run (ioloop=0x0) at ioloop-kqueue.c:148
	tv = {
  tv_sec = 130, 
  tv_usec = 124797
}
	ctx = (struct ioloop_handler_context *) 0x7f7fa0c1a890
	ret = 1
	ts = {
  tv_sec = 130, 
  tv_nsec = 124797000
}
	events = (struct kevent *) 0x10cb4ee78
#9  0x000000010cb11b88 in io_loop_run (ioloop=0x7fff53152b90) at ioloop.c:398
No locals.
#10 0x000000010cafde9b in master_service_run (service=0x7f7fa0c039f0, callback=0x7f7fa0c1c2d8) at master-service.c:543
No locals.
#11 0x000000010cabdcd1 in main_deinit [inlined] () at /private/tmp/johnsone/dovecot-2.1.10/src/login-common/main.c:406
	set_pool = (pool_t) 0x7f7fa100b420
	login_socket = 0x10cb4f7f8 "?9??"
#12 0x000000010cabdcd1 in login_binary_run (argc=1, argv=0x7f7fa0c037c0, binary=0x7fff53152b90) at main.c:407
	set_pool = (pool_t) 0x7f7fa100b420
	login_socket = 0x10cb4f7f8 "?9??"
#13 0x00007fff8ac847e1 in start ()


(gdb) bt full
#0  0x00007fff96e4c110 in malloc_zone_malloc ()
#1  0x00007fff96e4cba7 in malloc ()
#2  0x00007fff92d2c9e2 in CRYPTO_malloc ()
#3  0x00007fff92d4535f in EVP_DigestInit_ex ()
#4  0x00007fff92d17caa in ssleay_rand_add ()
#5  0x00007fff974529be in ssl23_accept ()
...

#0  0x00007fff94775ffa in read ()
#1  0x00007fff92cf41e6 in sock_read ()
#2  0x00007fff92d15598 in BIO_read ()
#3  0x00007fff9745294a in ssl23_read_bytes ()
#4  0x00007fff97452c3e in ssl23_get_client_hello ()
#5  0x00007fff97452b4d in ssl23_accept ()
...

-----------------------------------