Zimbra client sometime cannot authentication -- saslauthd

Discuss your pilot or production implementation with other Zimbra admins or our engineers.
NothingCtrl
Posts: 6
Joined: Tue Apr 18, 2017 10:06 am

Zimbra client sometime cannot authentication -- saslauthd

Postby 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
Posts: 6
Joined: Tue Apr 18, 2017 10:06 am

Re: Zimbra client sometime cannot authentication -- saslauthd

Postby 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
Posts: 6
Joined: Tue Apr 18, 2017 10:06 am

Re: Zimbra client sometime cannot authentication -- saslauthd

Postby 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
Posts: 6
Joined: Tue Apr 18, 2017 10:06 am

Re: Zimbra client sometime cannot authentication -- saslauthd

Postby NothingCtrl » Wed Jun 13, 2018 7:26 am

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

Return to “Administrators”

Who is online

Users browsing this forum: sunil_ghimire and 15 guests