2.3.11 STARTTLS broken if tls_ca_file is defined

Janne Peltonen janne.peltonen at helsinki.fi
Thu Jan 3 08:34:15 EST 2008 

I don't know whether this is related, but when I tried to upgrade my
frontends to 2.3.11 (from Simon's RPM) yesterday, I ran into quite a
mess. After abt half an hour of normal-looking operation, the imapproxy in my
Webmail server could no longer negotiate starttls:

--clip--
-n  2 17:24:48 pcn5.mappi.helsinki.fi p02/master[23992]: process started 
Jan  2 17:24:48 pcn5.mappi.helsinki.fi p02/ctl_cyrusdb[23993]: recovering cyrus databases 
Jan  2 17:25:04 pcn5.mappi.helsinki.fi p02/ctl_cyrusdb[23993]: skiplist: recovered /var/lib/imap/p02/mailboxes.db (652917 records, 100550228 bytes) in 16 seconds 
Jan  2 17:25:04 pcn5.mappi.helsinki.fi p02/ctl_cyrusdb[23993]: skiplist: recovered /var/lib/imap/p02/annotations.db (0 records, 144 bytes) in 0 seconds 
Jan  2 17:25:11 pcn5.mappi.helsinki.fi p02/ctl_cyrusdb[23993]: done recovering cyrus databases 
Jan  2 17:25:15 pcn5.mappi.helsinki.fi p02/tls_prune[24750]: skiplist: recovered /var/lib/imap/p02/tls_sessions.db (11933 records, 5112508 bytes) in 0 seconds 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/tls_prune[24750]: tls_prune: purged 24 out of 11933 entries 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/master[23992]: ready for work 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/ctl_cyrusdb[24752]: checkpointing cyrus databases 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/lmtpa[24758]: skiplist: recovered /var/lib/imap/p02/deliver.db (0 records, 144 bytes) in 0 seconds 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/mupdate[24759]: successful mupdate connection to im.mappi.helsinki.fi 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/mupdate[24759]: unready for connections 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/mupdate[24759]: synchronizing mailbox list with master mupdate server 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/imap[24753]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:16 pcn5.mappi.helsinki.fi p02/imap[24774]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:17 pcn5.mappi.helsinki.fi p02/ctl_cyrusdb[24752]: done checkpointing cyrus databases 
Jan  2 17:25:17 pcn5.mappi.helsinki.fi p02/imap[24753]: starttls: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits new) no authentication 
Jan  2 17:25:17 pcn5.mappi.helsinki.fi p02/imap[24783]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:17 pcn5.mappi.helsinki.fi p02/imap[24753]: login: homunculus.it.helsinki.fi [128.214.205.36] jicheng plaintext+TLS User logged in 
Jan  2 17:25:17 pcn5.mappi.helsinki.fi p02/imap[24784]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:19 pcn5.mappi.helsinki.fi p02/imap[24769]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:19 pcn5.mappi.helsinki.fi p02/imap[24892]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:20 pcn5.mappi.helsinki.fi p02/imap[24766]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:20 pcn5.mappi.helsinki.fi p02/imap[24763]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:20 pcn5.mappi.helsinki.fi p02/imap[24763]: starttls: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits new) no authentication 
Jan  2 17:25:20 pcn5.mappi.helsinki.fi p02/imap[24763]: login: homunculus.it.helsinki.fi [128.214.205.36] ksotala plaintext+TLS User logged in 
Jan  2 17:25:20 pcn5.mappi.helsinki.fi p02/imap[25225]: imapd:Loading hard-coded DH parameters 
Jan  2 17:25:21 pcn5.mappi.helsinki.fi p02/imap[25226]: imapd:Loading hard-coded DH parameters 
[...]
Jan  2 17:55:16 pcn5.mappi.helsinki.fi p02/imap[24774]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:55:16 pcn5.mappi.helsinki.fi p02/imap[24774]: idle for too long, closing connection 
Jan  2 17:55:17 pcn5.mappi.helsinki.fi p02/imap[24783]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:55:17 pcn5.mappi.helsinki.fi p02/imap[24783]: idle for too long, closing connection 
Jan  2 17:55:17 pcn5.mappi.helsinki.fi p02/imap[24784]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:55:17 pcn5.mappi.helsinki.fi p02/imap[24784]: idle for too long, closing connection 
Jan  2 17:55:19 pcn5.mappi.helsinki.fi p02/imap[24769]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:55:19 pcn5.mappi.helsinki.fi p02/imap[24769]: idle for too long, closing connection 
Jan  2 17:55:19 pcn5.mappi.helsinki.fi p02/imap[24892]: STARTTLS negotiation failed: lemure.it.helsinki.fi [128.214.205.35] 
Jan  2 17:55:19 pcn5.mappi.helsinki.fi p02/imap[24892]: idle for too long, closing connection 
Jan  2 17:55:20 pcn5.mappi.helsinki.fi p02/imap[24766]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:55:20 pcn5.mappi.helsinki.fi p02/imap[24766]: idle for too long, closing connection 
Jan  2 17:55:20 pcn5.mappi.helsinki.fi p02/imap[25225]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:55:20 pcn5.mappi.helsinki.fi p02/imap[25225]: idle for too long, closing connection 
Jan  2 17:55:21 pcn5.mappi.helsinki.fi p02/imap[25226]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:55:21 pcn5.mappi.helsinki.fi p02/imap[25226]: idle for too long, closing connection 
Jan  2 17:55:21 pcn5.mappi.helsinki.fi p02/imap[24762]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:55:21 pcn5.mappi.helsinki.fi p02/imap[24762]: idle for too long, closing connection 
-clip--

There are occasional successful logins from other clients in between:

--clip--
Jan  2 17:56:23 pcn5.mappi.helsinki.fi p02/imap[27608]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:56:23 pcn5.mappi.helsinki.fi p02/imap[27608]: idle for too long, closing connection 
Jan  2 17:56:24 pcn5.mappi.helsinki.fi p02/imaps[15563]: imapd:Loading hard-coded DH parameters 
Jan  2 17:56:24 pcn5.mappi.helsinki.fi p02/imaps[15563]: starttls: TLSv1 with cipher AES128-SHA (128/128 bits new) no authentication 
Jan  2 17:56:25 pcn5.mappi.helsinki.fi p02/imaps[15563]: login: dsl-hkibras-fe27f900-71.dhcp.inet.fi [84.249.39.71] prisberg plaintext+TLS User logged in 
Jan  2 17:56:26 pcn5.mappi.helsinki.fi p02/imap[27695]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:56:26 pcn5.mappi.helsinki.fi p02/imap[27695]: idle for too long, closing connection 
Jan  2 17:56:26 pcn5.mappi.helsinki.fi p02/imap[27625]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:56:26 pcn5.mappi.helsinki.fi p02/imap[27625]: idle for too long, closing connection 
Jan  2 17:56:27 pcn5.mappi.helsinki.fi p02/imap[27708]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:56:27 pcn5.mappi.helsinki.fi p02/imap[27708]: idle for too long, closing connection 
Jan  2 17:56:28 pcn5.mappi.helsinki.fi p02/imap[27690]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:56:28 pcn5.mappi.helsinki.fi p02/imap[27690]: idle for too long, closing connection 
Jan  2 17:56:29 pcn5.mappi.helsinki.fi p02/imap[27625]: starttls: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits new) no authentication 
Jan  2 17:56:29 pcn5.mappi.helsinki.fi p02/imap[27625]: login: homunculus.it.helsinki.fi [128.214.205.36] tanurmi plaintext+TLS User logged in 
Jan  2 17:56:30 pcn5.mappi.helsinki.fi p02/imap[27710]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
Jan  2 17:56:30 pcn5.mappi.helsinki.fi p02/imap[27710]: idle for too long, closing connection 
Jan  2 17:56:47 pcn5.mappi.helsinki.fi p02/imap[19074]: imapd:Loading hard-coded DH parameters 
Jan  2 17:56:49 pcn5.mappi.helsinki.fi p02/imaps[19160]: imapd:Loading hard-coded DH parameters 
Jan  2 17:56:49 pcn5.mappi.helsinki.fi p02/imaps[19160]: starttls: TLSv1 with cipher RC4-MD5 (128/128 bits reused) no authentication 
Jan  2 17:56:49 pcn5.mappi.helsinki.fi p02/imaps[19160]: login: a88-112-37-168.elisa-laajakaista.fi [88.112.37.168] teppo plaintext+TLS User logged in 
Jan  2 17:56:49 pcn5.mappi.helsinki.fi p02/imaps[7449]: starttls: TLSv1 with cipher RC4-MD5 (128/128 bits reused) no authentication 
Jan  2 17:56:49 pcn5.mappi.helsinki.fi p02/imaps[7449]: login: a88-112-37-168.elisa-laajakaista.fi [88.112.37.168] teppo plaintext+TLS User logged in 
Jan  2 17:56:55 pcn5.mappi.helsinki.fi p02/imap[27607]: STARTTLS negotiation failed: homunculus.it.helsinki.fi [128.214.205.36] 
--clip--

(homunculus and lemure are the webmail/imapproxy servers).

So I was forced to downgrade the frontends back to the previously-used version
(2.3.8-8 from Simon, with the proxyd-disable-referral patch added locally).

Any ideas what might be wrong? Something seems to get full and stop working...
(I have the tls_ca_file defined, too.) I'm not even sure whether this is really
a bug in Cyrus or Imapproxy.


--Janne

On Mon, Dec 17, 2007 at 12:56:46PM +0100, Sebastian Hagedorn wrote:
> --On 16. Dezember 2007 15:08:46 +0100 Wolfgang Breyha <wbreyha at gmx.net> 
> wrote:
> 
> >I always had
> >tls_ca_file: /etc/pki/tls/certs/ca-bundle.crt
> >defined in my imapd.conf.
> 
> FWIW: I have a tls_ca_file defined as well.
> 
> >Since I updated to 2.3.11 yesterday STARTTLS didn't work anymore because
> >negotiation failed and timed out. $CLIENT was waiting for more packets
> >from server AFAIS in a tcpdump, where $CLIENT is Thunderbird, gnutls-cli,
> >apple-mail.
> 
> Hm, I don't run 2.3.11 proper, but my locally built version contains the 
> modified tls.c etc. So I would think that it should behave the same way as 
> 2.3.11, but of course I can't be sure. And here STARTTLS works fine.
> 
> >IMAPS always worked...so I searched for differences in the code and found
> >the "client cert verfication" code triggered by askcert == 1 in tls.c:738
> 
> Hm, do you use client certificates? We don't ...
> 
> >Log always showed:
> >00:00 imap[8508]: accepted connection
> >  +02 imap[8508]: SSL_accept() incomplete -> wait <- here the client waits
> >  +23 imap[8508]: EOF in SSL_accept() -> fail     <- here client sent FIN
> 
> That code is where all the changes were made. It's conceivable that there 
> are cases where the new approach breaks.
> -- 
>     .:.Sebastian Hagedorn - RZKR-R1 (Gebäude 52), Zimmer 18.:.
> Zentrum für angewandte Informatik - Universitätsweiter Service RRZK
> .:.Universität zu Köln / Cologne University - ✆ +49-221-478-5587.:.
>                   .:.:.:.Skype: shagedorn.:.:.:.



> ----
> Cyrus Home Page: http://cyrusimap.web.cmu.edu/
> Cyrus Wiki/FAQ: http://cyrusimap.web.cmu.edu/twiki
> List Archives/Info: http://asg.web.cmu.edu/cyrus/mailing-list.html

-- 
Janne Peltonen <janne.peltonen at helsinki.fi>

More information about the Info-cyrus mailing list