Zimbra client sometime cannot authentication -- saslauthd

NothingCtrl · Post by **NothingCtrl** » Tue Jun 05, 2018 7:16 am

Mail server info:

Zimbra 8.7.7_GA_1787.FOSS
Server authentication using Active Directory (2003)
HTTPS / SSL using wilcard certificate

Recently, sometime user cannot send email using email client (Android Gmail App, Ms Outlook...), the client pop-up authentication error, but user can login to webmail to send email.

Postfix and zmcontrol status seem ok:

Code: Select all

root@mail:~/server-schedule# netstat -tulpn
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 127.0.0.1:389           0.0.0.0:*               LISTEN      1585/slapd      
tcp        0      0 0.0.0.0:5222            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:7110            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:7143            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 127.0.0.1:10663         0.0.0.0:*               LISTEN      3547/zmlogger: zmrr
tcp        0      0 127.0.0.1:10024         0.0.0.0:*               LISTEN      1795/amavisd (ch18-
tcp        0      0 127.0.0.1:10025         0.0.0.0:*               LISTEN      4771/master     
tcp        0      0 127.0.0.1:10026         0.0.0.0:*               LISTEN      1795/amavisd (ch18-
tcp        0      0 127.0.0.1:7306          0.0.0.0:*               LISTEN      3467/mysqld     
tcp        0      0 127.0.0.1:10027         0.0.0.0:*               LISTEN      4771/master     
tcp        0      0 0.0.0.0:587             0.0.0.0:*               LISTEN      4771/master     
tcp        0      0 0.0.0.0:11211           0.0.0.0:*               LISTEN      3974/memcached  
tcp        0      0 127.0.0.1:10028         0.0.0.0:*               LISTEN      4771/master     
tcp        0      0 127.0.0.1:10029         0.0.0.0:*               LISTEN      4771/master     
tcp        0      0 127.0.0.1:10030         0.0.0.0:*               LISTEN      4771/master     
tcp        0      0 127.0.0.1:3310          0.0.0.0:*               LISTEN      4366/clamd      
tcp        0      0 0.0.0.0:110             0.0.0.0:*               LISTEN      3999/nginx.conf 
tcp        0      0 0.0.0.0:143             0.0.0.0:*               LISTEN      3999/nginx.conf 
tcp        0      0 127.0.0.1:10032         0.0.0.0:*               LISTEN      1795/amavisd (ch18-
tcp        0      0 127.0.0.1:8080          0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:465             0.0.0.0:*               LISTEN      4771/master     
tcp        0      0 127.0.0.1:8465          0.0.0.0:*               LISTEN      4389/opendkim   
tcp        0      0 0.0.0.0:7025            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:7026            0.0.0.0:*               LISTEN      4592/java       
tcp        0      0 0.0.0.0:5269            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:53              0.0.0.0:*               LISTEN      1311/dnsmasq    
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      1421/sshd       
tcp        0      0 0.0.0.0:25              0.0.0.0:*               LISTEN      4771/master     
tcp        0      0 0.0.0.0:7993            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:443             0.0.0.0:*               LISTEN      3999/nginx.conf 
tcp        0      0 0.0.0.0:7995            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:8443            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:7071            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 127.0.0.1:23232         0.0.0.0:*               LISTEN      4023/perl       
tcp        0      0 0.0.0.0:7072            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 127.0.0.1:23233         0.0.0.0:*               LISTEN      4025/perl       
tcp        0      0 0.0.0.0:993             0.0.0.0:*               LISTEN      3999/nginx.conf 
tcp        0      0 0.0.0.0:7073            0.0.0.0:*               LISTEN      3692/java       
tcp        0      0 0.0.0.0:10050           0.0.0.0:*               LISTEN      1439/zabbix_agentd
tcp        0      0 0.0.0.0:995             0.0.0.0:*               LISTEN      3999/nginx.conf 
tcp        0      0 127.0.0.1:7171          0.0.0.0:*               LISTEN      1612/java       
tcp6       0      0 ::1:10024               :::*                    LISTEN      1795/amavisd (ch18-
tcp6       0      0 ::1:10026               :::*                    LISTEN      1795/amavisd (ch18-
tcp6       0      0 :::11211                :::*                    LISTEN      3974/memcached  
tcp6       0      0 ::1:3310                :::*                    LISTEN      4366/clamd      
tcp6       0      0 ::1:10032               :::*                    LISTEN      1795/amavisd (ch18-
tcp6       0      0 :::53                   :::*                    LISTEN      1311/dnsmasq    
tcp6       0      0 :::22                   :::*                    LISTEN      1421/sshd       
tcp6       0      0 :::10050                :::*                    LISTEN      1439/zabbix_agentd
tcp6       0      0 :::7780                 :::*                    LISTEN      4418/httpd      
udp        0      0 0.0.0.0:34265           0.0.0.0:*                           3692/java       
udp        0      0 0.0.0.0:11211           0.0.0.0:*                           3974/memcached  
udp        0      0 0.0.0.0:60899           0.0.0.0:*                           1612/java       
udp        0      0 0.0.0.0:53              0.0.0.0:*                           1311/dnsmasq    
udp6       0      0 :::11211                :::*                                3974/memcached  
udp6       0      0 :::53                   :::*                                1311/dnsmasq

zimbra@mail:~$ zmcontrol status
Host mail.xxx.xxx
amavis Running
antispam Running
antivirus Running
ldap Running
logger Running
mailbox Running
memcached Running
mta Running
opendkim Running
proxy Running
service webapp Running
snmp Running
spell Running
stats Running
zimbra webapp Running
zimbraAdmin webapp Running
zimlet webapp Running
zmconfigd Running

I can telnet to mail server port 465, 587, 7073 (so service is listening).

The zimbra.log when error:

Code: Select all

Jun  4 23:28:16 mail postfix/smtps/smtpd[19548]: Anonymous TLS connection established from unknown[118.69.xxx.7]: TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)
Jun  4 23:28:16 mail saslauthd[9201]: zmauth: authenticating against elected url 'https://mail.xxx.xxx:7073/service/admin/soap/' ...
Jun  4 23:28:16 mail saslauthd[9201]: authentication against url 'https://mail.xxx.xxx:7073/service/admin/soap/' caused error 'curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused'
Jun  4 23:28:16 mail saslauthd[9201]: url 'https://mail.xxx.xxx:7073/service/admin/soap/' will not be used for (at least) 600 seconds
Jun  4 23:28:16 mail saslauthd[9201]: Authentication cycle re-elected url https://mail.xxx.xxx:7073/service/admin/soap/, giving up ...
Jun  4 23:28:16 mail saslauthd[9201]: auth_zimbra: Vietdh auth failed: curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused
Jun  4 23:28:16 mail saslauthd[9201]: do_auth         : auth failure: [user=Vietdh] [service=smtp] [realm=] [mech=zimbra] [reason=Unknown]
Jun  4 23:28:16 mail postfix/smtps/smtpd[19548]: warning: unknown[118.69.xxx.7]: SASL LOGIN authentication failed: authentication failure
Jun  4 23:28:16 mail postfix/smtps/smtpd[19548]: lost connection after AUTH from unknown[118.69.xxx.7]
Jun  4 23:28:16 mail postfix/smtps/smtpd[19548]: disconnect from unknown[118.69.xxx.7] ehlo=1 auth=0/1 commands=1/2
Jun  4 23:28:16 mail postfix/smtps/smtpd[18531]: Anonymous TLS connection established from unknown[118.69.xxx.7]: TLSv1 with cipher ECDHE-RSA-AES256-SHA (256/256 bits)
Jun  4 23:28:17 mail saslauthd[9197]: zmauth: authenticating against elected url 'https://mail.xxx.xxx:7073/service/admin/soap/' ...
Jun  4 23:28:17 mail saslauthd[9197]: authentication against url 'https://mail.xxx.xxx:7073/service/admin/soap/' caused error 'curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused'
Jun  4 23:28:17 mail saslauthd[9197]: url 'https://mail.xxx.xxx:7073/service/admin/soap/' will not be used for (at least) 600 seconds
Jun  4 23:28:17 mail saslauthd[9197]: Authentication cycle re-elected url https://mail.xxx.xxx:7073/service/admin/soap/, giving up ...
Jun  4 23:28:17 mail saslauthd[9197]: auth_zimbra: quynhnn auth failed: curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused
Jun  4 23:28:17 mail saslauthd[9197]: do_auth         : auth failure: [user=quynhnn] [service=smtp] [realm=] [mech=zimbra] [reason=Unknown]
Jun  4 23:28:17 mail postfix/smtps/smtpd[18531]: warning: unknown[118.69.xxx.7]: SASL LOGIN authentication failed: authentication failure
Jun  4 23:28:17 mail postfix/smtps/smtpd[18531]: lost connection after AUTH from unknown[118.69.xxx.7]
Jun  4 23:28:17 mail postfix/smtps/smtpd[18531]: disconnect from unknown[118.69.xxx.7] ehlo=1 auth=0/1 commands=1/2
Jun  4 23:28:19 mail postfix/postscreen[18544]: CONNECT from [91.234.99.217]:51824 to [192.168.xxx.11]:25
Jun  4 23:28:19 mail postfix/postscreen[18544]: PASS OLD [91.234.99.217]:51824
Jun  4 23:28:19 mail postfix/smtpd[18564]: connect from unknown[91.234.99.217]
Jun  4 23:28:19 mail postfix/smtpd[18564]: lost connection after AUTH from unknown[91.234.99.217]
Jun  4 23:28:19 mail postfix/smtpd[18564]: disconnect from unknown[91.234.99.217] ehlo=1 auth=0/1 commands=1/2
Jun  4 23:28:19 mail zmmailboxdmgr[8092]: mailboxd/JVM process exited (waitpid expected 8094 got 8094)
Jun  4 23:28:19 mail zmmailboxdmgr[8092]: manager woke up from wait on mailboxd/JVM with pid 8094
Jun  4 23:28:20 mail zmmailboxdmgr[19792]: manager process 8092 died, shutdown completed
Jun  4 23:28:20 mail postfix/submission/smtpd[18536]: connect from unknown[118.69.xxx.7]
Jun  4 23:28:20 mail postfix/submission/smtpd[18536]: Anonymous TLS connection established from unknown[118.69.xxx.7]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jun  4 23:28:20 mail saslauthd[9188]: zmauth: authenticating against elected url 'https://mail.xxx.xxx:7073/service/admin/soap/' ...
Jun  4 23:28:20 mail saslauthd[9188]: authentication against url 'https://mail.xxx.xxx:7073/service/admin/soap/' caused error 'curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused'
Jun  4 23:28:20 mail saslauthd[9188]: url 'https://mail.xxx.xxx:7073/service/admin/soap/' will not be used for (at least) 600 seconds
Jun  4 23:28:20 mail saslauthd[9188]: Authentication cycle re-elected url https://mail.xxx.xxx:7073/service/admin/soap/, giving up ...
Jun  4 23:28:20 mail saslauthd[9188]: auth_zimbra: dungnc auth failed: curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused
Jun  4 23:28:20 mail saslauthd[9188]: do_auth         : auth failure: [user=dungnc] [service=smtp] [realm=] [mech=zimbra] [reason=Unknown]
Jun  4 23:28:20 mail postfix/submission/smtpd[18536]: warning: unknown[118.69.xxx.7]: SASL LOGIN authentication failed: authentication failure
Jun  4 23:28:20 mail postfix/submission/smtpd[18536]: lost connection after AUTH from unknown[118.69.xxx.7]
Jun  4 23:28:20 mail postfix/submission/smtpd[18536]: disconnect from unknown[118.69.xxx.7] ehlo=2 starttls=1 auth=0/1 commands=3/4
Jun  4 23:28:21 mail postfix/submission/smtpd[18536]: connect from unknown[118.69.xxx.7]
Jun  4 23:28:21 mail postfix/submission/smtpd[18536]: Anonymous TLS connection established from unknown[118.69.xxx.7]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jun  4 23:28:21 mail saslauthd[9204]: zmauth: authenticating against elected url 'https://mail.xxx.xxx:7073/service/admin/soap/' ...
Jun  4 23:28:21 mail saslauthd[9204]: authentication against url 'https://mail.xxx.xxx:7073/service/admin/soap/' caused error 'curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused'
Jun  4 23:28:21 mail saslauthd[9204]: url 'https://mail.xxx.xxx:7073/service/admin/soap/' will not be used for (at least) 600 seconds
Jun  4 23:28:21 mail saslauthd[9204]: Authentication cycle re-elected url https://mail.xxx.xxx:7073/service/admin/soap/, giving up ...
Jun  4 23:28:21 mail saslauthd[9204]: auth_zimbra: dungnc auth failed: curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused
Jun  4 23:28:21 mail saslauthd[9204]: do_auth         : auth failure: [user=dungnc] [service=smtp] [realm=] [mech=zimbra] [reason=Unknown]
Jun  4 23:28:21 mail postfix/submission/smtpd[18536]: warning: unknown[118.69.xxx.7]: SASL LOGIN authentication failed: authentication failure
Jun  4 23:28:21 mail postfix/submission/smtpd[18536]: lost connection after AUTH from unknown[118.69.xxx.7]

It seen problem with error: caused error 'curl_easy_perform: error(7): Failed to connect to mail.xxx.xxx port 7073: Connection refused'

Restart postfix not solve the problem.
Restart zimbra service with command "zmcontrol restart" solve the problem, but this may comeback anytime.

Does it the root cause? how can I fix it / prevent it.

Thanks for your help.

NothingCtrl · Post by **NothingCtrl** » Tue Jun 05, 2018 10:34 am

Update: I think this problem cause by auto provisioning failed, the log data in mailbox.log show that, after provision fail then error happen.

Code: Select all

2018-06-04 23:28:14,840 INFO  [AutoProvision] [] autoprov - Auto provision thread was interrupted.
2018-06-04 23:28:14,840 INFO  [AutoProvision] [] autoprov - Shutting down auto provision thread.
2018-06-04 23:28:14,840 INFO  [Thread-12] [] TcpServer/7025 - LmtpServer initiating shutdown
2018-06-04 23:28:14,841 INFO  [Thread-12] [] TcpServer/7025 - LmtpServer shutting down idle thread pool
2018-06-04 23:28:14,841 INFO  [LmtpServer] [] TcpServer/7025 - finished accept loop
2018-06-04 23:28:14,841 INFO  [Thread-12] [] pop - Initiating shutdown
2018-06-04 23:28:14,843 INFO  [Thread-12] [] pop - Initiating shutdown
2018-06-04 23:28:14,843 INFO  [Thread-12] [] pop - Closing session = (0x00000F00: nio socket, server, /127.0.0.1:34480 =/127.0.0.1:7995)
2018-06-04 23:28:14,843 INFO  [Thread-12] [] pop - Closing session = (0x00000EFC: nio socket, server, /127.0.0.1:34446 =/127.0.0.1:7995)

NothingCtrl · Post by **NothingCtrl** » Thu Jun 07, 2018 6:34 am

Update: after change auto provisioning from EAGER to LAZY mode, service still dying silenly (rarely), when it died, a message log in zmmailboxd.out:

Code: Select all

zmthrdump: Requested thread dump [PID 22191] at Tue Jun  5 19:12:30 2018
2018-06-05 19:12:30.819:INFO:oejs.ServerConnector:Thread-12: Stopped ServerConnector@33b37288{HTTP/1.1,[http/1.1]}{localhost:8080}
2018-06-05 19:12:30.826:INFO:oejs.ServerConnector:Thread-12: Stopped ServerConnector@45afc369{SSL,[ssl, http/1.1]}{0.0.0.0:8443}
2018-06-05 19:12:30.828:INFO:oejs.ServerConnector:Thread-12: Stopped ServerConnector@799d4f69{SSL,[ssl, http/1.1]}{0.0.0.0:7071}
2018-06-05 19:12:30.830:INFO:oejs.ServerConnector:Thread-12: Stopped ServerConnector@49c43f4e{SSL,[ssl, http/1.1]}{0.0.0.0:7073}
2018-06-05 19:12:30.831:INFO:oejs.ServerConnector:Thread-12: Stopped ServerConnector@290dbf45{SSL,[ssl, http/1.1]}{0.0.0.0:7072}

NothingCtrl · Post by **NothingCtrl** » Wed Jun 13, 2018 7:26 am

After all, the problem solved by modify DOS FILTER to fit with my system.

Zimbra Forums

Zimbra client sometime cannot authentication -- saslauthd

Zimbra client sometime cannot authentication -- saslauthd

Re: Zimbra client sometime cannot authentication -- saslauthd

Re: Zimbra client sometime cannot authentication -- saslauthd

Re: Zimbra client sometime cannot authentication -- saslauthd