[SOLVED] ZCS 5.0.8 MTA failing with Unable to set STARTTLS

[aromu]

Hi all,

I know this issue has been addressed several times both at the Zimbra Wiki and here at forums and I've tried all the magic including disabling the tls.

Could you please walk me through this one.

Here's what I get to the logs

mail.info

Aug  5 17:50:11 localhost zmmailboxdmgr[26565]: status requested
Aug  5 17:50:11 localhost zmmailboxdmgr[26565]: status OK
Aug  5 17:50:12 localhost postfix/smtpd[11511]: warning: problem talking to service rewrite: Success
Aug  5 17:50:12 localhost postfix/master[5801]: warning: process /opt/zimbra/postfix/libexec/trivial-rewrite pid 26321 exit status 1
Aug  5 17:50:12 localhost postfix/smtpd[11975]: warning: problem talking to service rewrite: Connection reset by peer
Aug  5 17:51:12 localhost postfix/trivial-rewrite[26606]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error
Aug  5 17:51:12 localhost last message repeated 2 times
Aug  5 17:51:12 localhost postfix/trivial-rewrite[26606]: fatal: ldap:/opt/zimbra/conf/ldap-vad.cf(0,lock|fold_fix): table lookup problem
Aug  5 17:51:13 localhost postfix/smtpd[19710]: warning: problem talking to service rewrite: Connection reset by peer
Aug  5 17:51:13 localhost postfix/smtpd[19709]: warning: problem talking to service rewrite: Success
Aug  5 17:51:13 localhost postfix/master[5801]: warning: process /opt/zimbra/postfix/libexec/trivial-rewrite pid 26606 exit status 1
Aug  5 17:51:13 localhost postfix/master[5801]: warning: /opt/zimbra/postfix/libexec/trivial-rewrite: bad command startup -- throttling
Aug  5 17:51:14 localhost postfix/trivial-rewrite[26640]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error
Aug  5 17:51:14 localhost last message repeated 2 times

mail.err

Aug  5 17:52:15 localhost postfix/trivial-rewrite[27280]: fatal: ldap:/opt/zimbra/conf/ldap-vad.cf(0,lock|fold_fix): table lookup problem
Aug  5 17:52:17 localhost postfix/trivial-rewrite[27281]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error
Aug  5 17:52:17 localhost last message repeated 2 times

The ldap seems to be answering correctly:

# ldapsearch -x -ZZ -h "FQDN" -b "" -s base
# extended LDIF
#
# LDAPv3
# base <> with scope baseObject
# filter: (objectclass=*)
# requesting: ALL
#

#
dn:
objectClass: top
objectClass: OpenLDAProotDSE

# search result
search: 3
result: 0 Success

# numResponses: 2
# numEntries: 1

Best regards:
Aapo

[phoenix]

Have you seen this wiki article and you've verified that it and the related certificate articles check out OK?

[aromu]

Hi phoenix and thank you for your answer

There was some information missing from my first post that could help you to pinpoint the problem but first I'll answer to your question:

I started solving the issue with forum thread
[SOLVED] Expired Cert in 5.0GA can cause mail Delivery failure

Then I went through the following articles step by step

Error (MTA): Unable to set STARTTLS - Zimbra :: Wiki
Problem with Certificate can cause MTA Failure - Zimbra :: Wiki
SSL Certificate Problems - Zimbra :: Wiki

I especially paid attention to the last one since it seemed to be the most complete answer. However I tried all of them step by step.

There was also the bug Bug 22468 – new LDAP user testing in menu installer but I wasn't able to get much help out of that.

I forgot to mention that the Zimbra installation I'm trying to get working is a fresh one and the exact package I'm using is: zcs-5.0.8_GA_2462.UBUNTU6_64.20080709205157

The system is Ubuntu Server 7.10 64bit (I used some other threads from forum to get the installer working and to solve the issue with Apache already running on the server)

I'm also thinking if it can be possible that for some reason the Zimbra postfix is not actually using the open LDAP provided by the Zimbra package. The authentication at the server is done with external LDAP server (let's call it ldap.mycompany.com). The system allows also local account information and it is possible to log in using those local accounts.

The reason I'm thinking of this is the messages at /var/log/auth.log (replaced the actual ldap server with fake name)

Aug  5 21:57:31 localhost postfix/trivial-rewrite[21397]: nss_ldap: could not search LDAP server - Server is unavailable
Aug  5 21:57:51 localhost sudo:   zimbra : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/opt/zimbra/libexec/zmmailboxdmgr status
Aug  5 21:57:51 localhost sudo:   zimbra : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/opt/zimbra/libexec/zmmtastatus
Aug  5 21:57:51 localhost sudo:   zimbra : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/opt/zimbra/libexec/zmmailboxdmgr status
Aug  5 21:58:01 localhost CRON[21820]: pam_unix(cron:session): session opened for user zimbra by (uid=0)
Aug  5 21:58:05 localhost sudo:   zimbra : TTY=unknown ; PWD=/opt/zimbra ; USER=root ; COMMAND=/opt/zimbra/libexec/zmmailboxdmgr status
Aug  5 21:58:05 localhost sudo:   zimbra : TTY=unknown ; PWD=/opt/zimbra ; USER=root ; COMMAND=/opt/zimbra/libexec/zmmtastatus
Aug  5 21:58:06 localhost CRON[21820]: pam_unix(cron:session): session closed for user zimbra
Aug  5 21:58:30 localhost postfix/trivial-rewrite[22076]: nss_ldap: could not connect to any LDAP server as (null) - Can't contact LDAP server
Aug  5 21:58:30 localhost postfix/trivial-rewrite[22076]: nss_ldap: failed to bind to LDAP server ldaps://ldap.mycompany.com/: Can't contact LDAP server
Aug  5 21:58:30 localhost postfix/trivial-rewrite[22076]: nss_ldap: reconnecting to LDAP server...
Aug  5 21:58:30 localhost postfix/trivial-rewrite[22076]: nss_ldap: could not connect to any LDAP server as (null) - Can't contact LDAP server
Aug  5 21:58:30 localhost postfix/trivial-rewrite[22076]: nss_ldap: failed to bind to LDAP server ldaps://ldap.mycompany.com/: Can't contact LDAP server
Aug  5 21:58:30 localhost postfix/trivial-rewrite[22076]: nss_ldap: reconnecting to LDAP server (sleeping 1 seconds)...
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: could not connect to any LDAP server as (null) - Can't contact LDAP server
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: failed to bind to LDAP server ldaps://ldap.mycompany.com/: Can't contact LDAP server
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: could not search LDAP server - Server is unavailable
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: could not connect to any LDAP server as (null) - Can't contact LDAP server
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: failed to bind to LDAP server ldaps://ldap.mycompany.com/: Can't contact LDAP server
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: reconnecting to LDAP server...
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: could not connect to any LDAP server as (null) - Can't contact LDAP server
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: failed to bind to LDAP server ldaps://ldap.mycompany.com/: Can't contact LDAP server
Aug  5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: reconnecting to LDAP server (sleeping 1 seconds)...
Aug  5 21:58:32 localhost postfix/trivial-rewrite[22076]: nss_ldap: could not connect to any LDAP server as (null) - Can't contact LDAP server
Aug  5 21:58:32 localhost postfix/trivial-rewrite[22076]: nss_ldap: failed to bind to LDAP server ldaps://ldap.mycompany.com/: Can't contact LDAP server
Aug  5 21:58:32 localhost postfix/trivial-rewrite[22076]: nss_ldap: could not search LDAP server - Server is unavailable
Aug  5 21:58:32 localhost postfix/trivial-rewrite[22080]: nss_ldap: could not connect to any LDAP server as (null) - Can't contact LDAP server
Aug  5 21:58:32 localhost postfix/trivial-rewrite[22080]: nss_ldap: failed to bind to LDAP server ldaps://ldap.mycompany.com/: Can't contact LDAP server

The zmlocalconfig shows though (replaced the actual domain with mymaildomain.net):

$ zmlocalconfig | grep ldap
ldap_amavis_password = *
ldap_bind_url = 
ldap_cache_account_maxage = 15
ldap_cache_account_maxsize = 20000
ldap_cache_cos_maxage = 15
ldap_cache_cos_maxsize = 100
ldap_cache_domain_maxage = 15
ldap_cache_domain_maxsize = 100
ldap_cache_group_maxage = 15
ldap_cache_group_maxsize = 200
ldap_cache_server_maxage = 15
ldap_cache_server_maxsize = 100
ldap_cache_timezone_maxsize = 100
ldap_cache_zimlet_maxage = 15
ldap_cache_zimlet_maxsize = 100
ldap_connect_pool_debug = false
ldap_connect_pool_initsize = 1
ldap_connect_pool_master = false
ldap_connect_pool_maxsize = 50
ldap_connect_pool_prefsize = 0
ldap_connect_pool_timeout = 120000
ldap_connect_timeout = 30000
ldap_deref_aliases = always
ldap_host = mail.mymaildomain.net
ldap_is_master = true
ldap_log_level = 49152
ldap_master_url = ldap://mail.mymaildomain.net:389
ldap_port = 389
ldap_postfix_password = *
ldap_read_timeout = 30000
ldap_replication_password = *
ldap_require_tls = false
ldap_root_password = *
ldap_starttls_supported = 1
ldap_url = ldap://mail.mymaildomain.net:389
postfix_sender_canonical_maps = ldap:${zimbra_home}/conf/ldap-scm.cf
postfix_transport_maps = ldap:${zimbra_home}/conf/ldap-transport.cf
postfix_virtual_alias_domains = ldap:${zimbra_home}/conf/ldap-vad.cf
postfix_virtual_alias_maps = ldap:${zimbra_home}/conf/ldap-vam.cf
postfix_virtual_mailbox_domains = ldap:${zimbra_home}/conf/ldap-vmd.cf
postfix_virtual_mailbox_maps = ldap:${zimbra_home}/conf/ldap-vmm.cf
zimbra_class_provisioning = com.zimbra.cs.account.ldap.LdapProvisioning
zimbra_ldap_password = *
zimbra_ldap_user = zimbra
zimbra_ldap_userdn = uid=zimbra,cn=admins,cn=zimbra
zimbra_zmprov_default_to_ldap = FALSE

Best regards:
Aapo

[aromu]

Hi phoenix.

There seems to be some weird behavior on this forum system. The answers I try to send you are displaying and then disappearing.

I'll try to post the correct answer again tomorrow if this system will then work. I'll already tried ten times tonight. Using new reply and quick reply and making web pages of the answer to you. They all vanished from this forum.

BR:
Aapo

[aromu]

I double checked that the start_tls = no was correctly set in files

:~/conf$ ls -al ldap*
-rw-r----- 1 zimbra zimbra 441 Aug 5 23:12 ldap-scm.cf
-rw-r----- 1 zimbra zimbra 369 Aug 5 23:12 ldap-transport.cf
-rw-r----- 1 zimbra zimbra 357 Aug 5 23:12 ldap-vad.cf
-rw-r----- 1 zimbra zimbra 500 Aug 5 23:12 ldap-vam.cf
-rw-r----- 1 zimbra zimbra 357 Aug 5 23:12 ldap-vmd.cf
-rw-r----- 1 zimbra zimbra 351 Aug 5 23:12 ldap-vmm.cf

it actually was not but fixing it and restart did not help. The mail.err still displays:

Aug 5 23:12:28 localhost postfix/cleanup[29941]: fatal: too many errors - program terminated
Aug 5 23:12:34 localhost postfix/trivial-rewrite[29991]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error
Aug 5 23:12:34 localhost postfix/trivial-rewrite[29991]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error
Aug 5 23:12:34 localhost postfix/cleanup[29943]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error
Aug 5 23:12:34 localhost last message repeated 12 times

[aromu]

Hi,

Would you have any suggestion / thoughts about the postfix ldap configuration since it really seems that for some reason postfix is trying to contact wrong ldap server as indicated by the auth.log

Aug 5 21:58:31 localhost postfix/trivial-rewrite[22076]: nss_ldap: failed to bind to LDAP server ldaps://ldap.mycompany.com/: Can't contact LDAP server

The ldap configurations at /opt/zimbra/conf however point to ldap://mail.mymaildomain.net:389

BR:
Aapo

[aromu]

Hi,

In the meanwhile waiting for your comments for my posts I corrected the problem of the antispam not running (commented ldap entry out from the /etc/nssswitch.conf shadow: row)

Now all the services are running as reported by zmcontrol status

antispam                Running
	antivirus               Running
	ldap                    Running
	logger                  Running
	mailbox                 Running
	mta                     Running
	snmp                    Running
	spell                   Running
	stats                   Running

I also tried the suggested wiki document again with procedure below. It did not help.

Workaround [5.0.1_GA or later]

For Single-server and Multi-server ldap masters

   (a) Run as root: /opt/zimbra/bin/zmcertmgr createca -new
   (b) Run as root: /opt/zimbra/bin/zmcertmgr deployca
   (c) Run as root: /opt/zimbra/bin/zmcertmgr deploycrt self -new
   (d) Run as root: su - zimbra zmcontrol stop; su - zimbra zmcontrol start

    * Note, for zcs version 5.0.6 (c) should be Run as root: /opt/zimbra/bin/zmcertmgr deploycrt self

BR:
Aapo

[aromu]

Hi,

I installed ZCS 5.0.6 because I thought it could make a difference. The symptoms are the same. I also tried instructions on the mentioned wiki page without any success. I also tried the instructions for 5.0.0 with the ldapmodify commands. No go.

However there is a lot more output from ldap in the zimbra log. Perhaps it helps you to figure out what is the actual problem.

I would really appreciate if anyone would help me on this one.

Aug  6 22:27:50 localhost postfix/pickup[13849]: 9B1541E880E5: uid=50033 from=
Aug  6 22:27:51 localhost slapd[11477]: conn=63 fd=15 ACCEPT from IP=127.0.0.1:43108 (IP=127.0.0.1:389) 
Aug  6 22:27:51 localhost slapd[11477]: conn=63 op=0 BIND dn="uid=zimbra,cn=admins,cn=zimbra" method=128 
Aug  6 22:27:51 localhost slapd[11477]: conn=63 op=0 BIND dn="uid=zimbra,cn=admins,cn=zimbra" mech=SIMPLE ssf=0 
Aug  6 22:27:51 localhost slapd[11477]: conn=63 op=0 RESULT tag=97 err=0 text= 
Aug  6 22:27:51 localhost slapd[11477]: conn=63 op=1 SRCH base="cn=config,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Aug  6 22:27:51 localhost slapd[11477]: conn=63 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Aug  6 22:27:52 localhost slapd[11477]: conn=64 fd=18 ACCEPT from IP=127.0.0.1:43110 (IP=127.0.0.1:389) 
Aug  6 22:27:52 localhost slapd[11477]: conn=64 op=0 STARTTLS 
Aug  6 22:27:52 localhost slapd[11477]: conn=64 op=0 RESULT oid= err=0 text= 
Aug  6 22:27:52 localhost postfix/trivial-rewrite[14164]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error
Aug  6 22:27:52 localhost slapd[11477]: conn=64 fd=18 closed (TLS negotiation failure) 
Aug  6 22:27:52 localhost slapd[11477]: conn=65 fd=18 ACCEPT from IP=127.0.0.1:43111 (IP=127.0.0.1:389) 
Aug  6 22:27:52 localhost slapd[11477]: conn=65 op=0 STARTTLS 
Aug  6 22:27:52 localhost slapd[11477]: conn=65 op=0 RESULT oid= err=0 text= 
Aug  6 22:27:52 localhost slapd[11477]: conn=65 fd=18 closed (TLS negotiation failure) 
Aug  6 22:27:52 localhost slapd[11477]: conn=66 fd=18 ACCEPT from IP=127.0.0.1:43112 (IP=127.0.0.1:389) 
Aug  6 22:27:52 localhost slapd[11477]: conn=66 op=0 STARTTLS 
Aug  6 22:27:52 localhost slapd[11477]: conn=66 op=0 RESULT oid= err=0 text= 
Aug  6 22:27:52 localhost postfix/trivial-rewrite[14164]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error
Aug  6 22:27:52 localhost postfix/cleanup[13873]: error: dict_ldap_connect: Unable to set STARTTLS: -11: Connect error

[aromu]

Hi all,

Since I don't have the choice of operating system on the original host I requested for a new public ip, installed Debian 4 under the VMWare and ZCS 5.0.8 for Debian 4 worked right out of the box.

-Aapo