IMAP over SSL (only) handshake hangs

[Helder Guerreiro]

Hi all

I'm having this exact same problem. Once the daemon is up it takes a 
while (a random while) to get to this state.

I'm on Debian 9.11 (stretch) which still is on Cyrus imap 2.5.10.

Any help would be very much appreciated.

/Helder

On 13/01/2015 10.22, Niels Dettenbach wrote:
> Hi all,
> 
> today i've runned into a very suspicious problem never seen before:
> 
> While any other IMAP and POP3 ports with and without SSL / TLS are working -
> connects to imaps (993) just hangs, there is nothing in the logs and a
> 
> 	openssl s_client -connect mail.myhost.abc:993
> 
> just brings out:
> 
> 	CONNECTED(00000003)
> 
> what times out after minutes. Connection to 995 (POP3s) works perfectly.
> 
> A imtest -v -s against the IP of the machine hangs on:
> 
> starting TLS engine
> setting up TLS connection
> SSL_connect:before/connect initialization
> write to 7F185DDB6480 [7F185DDC48F3] (216 bytes => 216 (0xD8))
> 0000 16 03 01 00 d3 01 00 00|cf 03 01 da 39 78 63 50
> 0010 b3 95 c8 e9 2f 11 4c 6c|de 39 e2 01 d1 e5 da 34
> 0020 61 e7 8d a5 85 68 6d 7a|14 e0 59 00 00 5c c0 14
> 0030 c0 0a 00 39 00 38 00 88|00 87 c0 0f c0 05 00 35
> 0040 00 84 c0 13 c0 09 00 33|00 32 00 9a 00 99 00 45
> 0050 00 44 c0 0e c0 04 00 2f|00 96 00 41 00 07 c0 11
> 0060 c0 07 c0 0c c0 02 00 05|00 04 c0 12 c0 08 00 16
> 0070 00 13 c0 0d c0 03 00 0a|00 15 00 12 00 09 00 14
> 0080 00 11 00 08 00 06 00 03|00 ff 02 01 00 00 49 00
> 0090 0b 00 04 03 00 01 02 00|0a 00 34 00 32 00 0e 00
> 00a0 0d 00 19 00 0b 00 0c 00|18 00 09 00 0a 00 16 00
> 00b0 17 00 08 00 06 00 07 00|14 00 15 00 04 00 05 00
> 00c0 12 00 13 00 01 00 02 00|03 00 0f 00 10 00 11 00
> 00d0 23 00 00 00 0f 00 01 01|
> SSL_connect:SSLv3 write client hello A
> 
> I tried to delete tls_sessions and even connecting to localhost (where it is
> bound too). netstat shows ESTABLISHED on such connections too.
> 
> The service is configured (and worked until tonight!):
> 
>    imaps         cmd="imapd -s" listen="imaps" prefork=0 maxchild=150
>    pop3s         cmd="pop3d -s" listen="pop3s" prefork=0 maxchild=50
> 
> A crazy thing is, that connections to "localhost" seems to work as soon as it
> uses the IPv6 adress of the localhost (::):
> 
> 	imtest -v -s localhost
> 
> while the IPv4 variant doesnt seem to work:
> 
> 	imtest -v -s 127.0.0.1
> 
> Because we did not use any IPv6 on that Gentoo machine i've disabled any IPv6
> stuff now which doesnt seem to help.
> 
> cyrus-imap is compiled
> 
> 	with:
> 	berkdb nntp pam sieve snmp sqlite ssl tcpd
> 
> 	without:
> 	-afs -kerberos -mysql -postgres -replication
> 
> dev-libs/openssl is 1.0.1k compiled
> 
> 	with:
> 	sse2 tls-heartbeat zlib
> 
> 	without:
> 	-bindist -gmp -kerberos -rfc3779 -static-libs -test -vanilla
> 
> anything under Intel Xeon (bare metal).
> 
> 
> 
> many thanks for any help or ideas where to look further?
> 
> 
> Some logs:
> 
> startup:
> Jan 13 11:06:41 blade4 master[12565]: about to exec
> /usr/lib64/cyrus/ctl_cyrusdb
> Jan 13 11:06:41 blade4 ctl_cyrusdb[12565]: SQL backend defaulting to engine
> 'sqlite'
> Jan 13 11:06:41 blade4 ctl_cyrusdb[12565]: recovering cyrus databases
> Jan 13 11:06:41 blade4 ctl_cyrusdb[12565]: skiplist: checkpointed
> /email/lib/cyrus/mailboxes.db (477 records, 60868 bytes) in 0 seconds
> Jan 13 11:06:41 blade4 ctl_cyrusdb[12565]: skiplist: checkpointed
> /email/lib/cyrus/annotations.db (0 records, 144 bytes) in 0 seconds
> Jan 13 11:06:42 blade4 ctl_cyrusdb[12565]: done recovering cyrus databases
> Jan 13 11:06:42 blade4 master[12595]: about to exec /usr/lib64/cyrus/idled
> Jan 13 11:06:42 blade4 master[12598]: about to exec
> /usr/lib64/cyrus/ctl_deliver
> Jan 13 11:06:42 blade4 master[12599]: about to exec
> /usr/lib64/cyrus/ctl_cyrusdb
> Jan 13 11:06:42 blade4 master[12597]: about to exec /usr/lib64/cyrus/tls_prune
> Jan 13 11:06:42 blade4 ctl_cyrusdb[12599]: SQL backend defaulting to engine
> 'sqlite'
> Jan 13 11:06:42 blade4 ctl_cyrusdb[12599]: checkpointing cyrus databases
> Jan 13 11:06:42 blade4 ctl_cyrusdb[12599]: archiving database file:
> /email/lib/cyrus/mailboxes.db
> Jan 13 11:06:42 blade4 ctl_cyrusdb[12599]: archiving database file:
> /email/lib/cyrus/annotations.db
> Jan 13 11:06:42 blade4 ctl_cyrusdb[12599]: done checkpointing cyrus databases
> Jan 13 11:06:42 blade4 tls_prune[12597]: skiplist: checkpointed
> /email/lib/cyrus/tls_sessions.db (1 record, 324 bytes) in 0 seconds
> Jan 13 11:06:42 blade4 cyr_expire[12598]: skiplist: checkpointed
> /email/lib/cyrus/deliver.db (804 records, 121348 bytes) in 0 seconds
> 
> and:
> 
> Jan 13 11:07:54 blade4 master[12559]: exiting on SIGTERM/SIGINT
> Jan 13 11:07:54 blade4 master[25695]: setrlimit: Unable to set file
> descriptors limit to -1: Operation not permitted
> Jan 13 11:07:54 blade4 master[25695]: retrying with 4096 (current max)
> Jan 13 11:07:54 blade4 master[25695]: process started
> Jan 13 11:07:54 blade4 master[25699]: about to exec
> /usr/lib64/cyrus/ctl_cyrusdb
> Jan 13 11:07:55 blade4 ctl_cyrusdb[25699]: SQL backend defaulting to engine
> 'sqlite'
> Jan 13 11:07:55 blade4 ctl_cyrusdb[25699]: recovering cyrus databases
> Jan 13 11:07:55 blade4 ctl_cyrusdb[25699]: skiplist: checkpointed
> /email/lib/cyrus/mailboxes.db (477 records, 60868 bytes) in 0 seconds
> Jan 13 11:07:55 blade4 ctl_cyrusdb[25699]: skiplist: checkpointed
> /email/lib/cyrus/annotations.db (0 records, 144 bytes) in 0 seconds
> Jan 13 11:07:55 blade4 ctl_cyrusdb[25699]: done recovering cyrus databases
> Jan 13 11:07:55 blade4 master[26043]: about to exec /usr/lib64/cyrus/idled
> Jan 13 11:07:55 blade4 master[25695]: unable to setsocketopt(IP_TOS):
> Operation not supported
> Jan 13 11:07:55 blade4 master[25695]: ready for work
> Jan 13 11:07:55 blade4 master[26046]: about to exec
> /usr/lib64/cyrus/ctl_deliver
> Jan 13 11:07:55 blade4 master[26047]: about to exec
> /usr/lib64/cyrus/ctl_cyrusdb
> Jan 13 11:07:55 blade4 master[26045]: about to exec /usr/lib64/cyrus/tls_prune
> Jan 13 11:07:56 blade4 cyr_expire[26046]: SQL backend defaulting to engine
> 'sqlite'
> Jan 13 11:07:56 blade4 ctl_cyrusdb[26047]: SQL backend defaulting to engine
> 'sqlite'
> Jan 13 11:07:56 blade4 ctl_cyrusdb[26047]: checkpointing cyrus databases
> Jan 13 11:07:56 blade4 ctl_cyrusdb[26047]: archiving database file:
> /email/lib/cyrus/mailboxes.db
> Jan 13 11:07:56 blade4 tls_prune[26045]: SQL backend defaulting to engine
> 'sqlite'
> Jan 13 11:07:56 blade4 idled[26044]: SQL backend defaulting to engine 'sqlite'
> Jan 13 11:07:56 blade4 ctl_cyrusdb[26047]: archiving database file:
> /email/lib/cyrus/annotations.db
> Jan 13 11:07:56 blade4 ctl_cyrusdb[26047]: done checkpointing cyrus databases
> Jan 13 11:07:56 blade4 master[25695]: process 26047 exited, status 0
> Jan 13 11:07:56 blade4 tls_prune[26045]: skiplist: checkpointed
> /email/lib/cyrus/tls_sessions.db (1 record, 324 bytes) in 0 seconds
> Jan 13 11:07:56 blade4 tls_prune[26045]: tls_prune: purged 0 out of 1 entries
> Jan 13 11:07:56 blade4 master[25695]: process 26045 exited, status 0
> Jan 13 11:07:56 blade4 cyr_expire[26046]: skiplist: checkpointed
> /email/lib/cyrus/deliver.db (800 records, 120752 bytes) in 0 seconds
> Jan 13 11:07:59 blade4 cyr_expire[26046]: Expunged 0 out of 475379 messages
> from 477 mailboxes
> Jan 13 11:07:59 blade4 cyr_expire[26046]: duplicate_prune: pruning back 3.00
> days
> Jan 13 11:07:59 blade4 cyr_expire[26046]: duplicate_prune: purged 0 out of 800
> entries
> Jan 13 11:07:59 blade4 cyr_expire[26046]: DIGEST-MD5 common mech free
> Jan 13 11:07:59 blade4 master[25695]: process 26046 exited, status 0