Upgrade to 2.2.32 from 2.2.15 failed

Mark Foley mfoley at ohprs.org
Sat Nov 25 07:04:16 EET 2017 

I have a problem. I have been running Dovecot 2.2.15 and I'd like to upgrade. My distro
(Slackware) has dovecot 2.2.32 available. I downloaded and installed that, but it didn't work.
No one was able to get messages from the dovecot server on their workstations. The following is
the entire dovecot log file from startup to the last message generated. No more messages went
into the logfile after line 76, even with clients trying to connect. The 174.233.134.88 IP is
from an external user connecting from his iPhone. The normal successful message from this user
are shown at bottom.

I'm suspecting something to do with line 18 where is says "Auth process broken." If anyone has
any insight I'd deeply appreciate it as I'd love to upgrade.

THX -- Mark

 1  Nov 24 19:22:24 master: Info: Dovecot v2.2.32 (dfbe293d4) starting up for imap (core dumps disabled)
 2  Nov 24 19:22:24 ssl-params: Info: Generating SSL parameters
 3  Nov 24 19:22:26 ssl-params: Info: SSL parameters regeneration completed
 4  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [174.233.134.88]
 5  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [174.233.134.88]
 6  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [174.233.134.88]
 7  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [174.233.134.88]
 8  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [174.233.134.88]
 9  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [174.233.134.88]
10  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [174.233.134.88]
11  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [174.233.134.88]
12  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [174.233.134.88]
13  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [174.233.134.88]
14  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [174.233.134.88]
15  Nov 24 19:23:02 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
16  Nov 24 19:23:02 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
17  Nov 24 19:23:02 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
18  Nov 24 19:23:02 imap-login: Info: Disconnected: Auth process broken (disconnected before auth was ready, waited 0 secs): user=<>, rip=174.233.134.88, lip=98.102.63.107, TLS handshaking, session=<idAcrMNe8xqu6YZY>
19  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [174.233.134.88]
20  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [174.233.134.88]
21  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [174.233.134.88]
22  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [174.233.134.88]
23  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [174.233.134.88]
24  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [174.233.134.88]
25  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [174.233.134.88]
26  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [174.233.134.88]
27  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [174.233.134.88]
28  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [174.233.134.88]
29  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [174.233.134.88]
30  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client key exchange A [174.233.134.88]
31  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read certificate verify A [174.233.134.88]
32  Nov 24 19:23:02 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read finished A [174.233.134.88]
33  Nov 24 19:23:03 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read finished A [174.233.134.88]
34  Nov 24 19:23:03 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write change cipher spec A [174.233.134.88]
35  Nov 24 19:23:03 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write finished A [174.233.134.88]
36  Nov 24 19:23:03 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [174.233.134.88]
37  Nov 24 19:23:03 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [174.233.134.88]
38  Nov 24 19:23:03 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [174.233.134.88]
39  Nov 24 19:23:04 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
40  Nov 24 19:23:04 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
41  Nov 24 19:23:04 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
42  Nov 24 19:23:04 imap-login: Info: Disconnected: Auth process broken (disconnected before auth was ready, waited 2 secs): user=<>, rip=174.233.134.88, lip=98.102.63.107, TLS, session=<YGw7rMNe+Rqu6YZY>
43  Nov 24 19:23:04 imap-login: Debug: SSL alert: close notify [174.233.134.88]
44  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [174.233.134.88]
45  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [174.233.134.88]
46  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [174.233.134.88]
47  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [174.233.134.88]
48  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [174.233.134.88]
49  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [174.233.134.88]
50  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [174.233.134.88]
51  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [174.233.134.88]
52  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [174.233.134.88]
53  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [174.233.134.88]
54  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [174.233.134.88]
55  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client key exchange A [174.233.134.88]
56  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read certificate verify A [174.233.134.88]
57  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read finished A [174.233.134.88]
58  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read finished A [174.233.134.88]
59  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write change cipher spec A [174.233.134.88]
60  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write finished A [174.233.134.88]
61  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [174.233.134.88]
62  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [174.233.134.88]
63  Nov 24 19:23:05 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [174.233.134.88]
64  Nov 24 19:23:08 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
65  Nov 24 19:23:08 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
66  Nov 24 19:23:08 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
67  Nov 24 19:23:08 imap-login: Info: Disconnected: Auth process broken (disconnected before auth was ready, waited 3 secs): user=<>, rip=174.233.134.88, lip=98.102.63.107, TLS, session=<7ZF4rMNe8hqu6YZY>
68  Nov 24 19:23:08 imap-login: Debug: SSL alert: close notify [174.233.134.88]
69  Nov 24 19:23:16 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
70  Nov 24 19:23:16 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
71  Nov 24 19:23:16 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
72  Nov 24 19:23:16 imap-login: Info: Disconnected: Auth process broken (disconnected before auth was ready, waited 0 secs): user=<>, rip=192.168.0.54, lip=192.168.0.2, session=<6bbyrMNeGM/AqAA2>
73  Nov 24 19:24:13 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
74  Nov 24 19:24:13 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
75  Nov 24 19:24:13 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
76  Nov 24 19:24:13 imap-login: Info: Disconnected: Auth process broken (disconnected before auth was ready, waited 0 secs): user=<>, rip=192.168.0.52, lip=192.168.0.2, session=<b75YsMNeb9nAqAA0>

Normal OK messages from dovecot 2.2.15:

Nov 24 23:50:49 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [174.233.134.88]
Nov 24 23:50:49 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [174.233.134.88]
Nov 24 23:50:49 auth: Debug: client in: AUTH    1       PLAIN   service=imap    secured session=vQnEacde6QCu6YZY lip=98.102.63.107        rip=174.233.134.88      lport=993       rport=6889      resp=AG0udGhlbQAhbXRfMTAxOQ== (previous base64 data may contain sensitive data)
Nov 24 23:50:49 auth-worker(17650): Debug: shadow(m.them,174.233.134.88): lookup
Nov 24 23:50:49 auth: Debug: client passdb out: OK      1       user=m.them

Finally, the 2.2.15 doveconf, which I used the same for 2.2.32:

> doveconf -n
# 2.2.15: /usr/local/etc/dovecot/dovecot.conf
# OS: Linux 4.4.88 x86_64 Slackware 14.2
auth_debug = yes
auth_debug_passwords = yes
auth_gssapi_hostname = $ALL
auth_krb5_keytab = /etc/dovecot/dovecot.keytab
auth_mechanisms = plain login gssapi
auth_use_winbind = yes
auth_username_format = %n
auth_verbose = yes
auth_verbose_passwords = plain
disable_plaintext_auth = no
info_log_path = /var/log/dovecot_info
mail_location = maildir:~/Maildir
passdb {
	  driver = shadow
}
protocols = imap
ssl_cert = </etc/ssl/certs/OHPRS/GoDaddy/Apache/2016-08-10/54e789087d419b6e.crt
ssl_key = </etc/ssl/certs/OHPRS/GoDaddy/mail.ohprs.org.key
userdb {
	  driver = passwd
}
verbose_ssl = yes

More information about the dovecot mailing list