Active Directory: LDAP Sync with STARTTLS is not working

ckd · Mar 24, 2024

My Active Directory is configured to accept STARTTLS connections at Port 389. This works well and is confirmed working as my > 5 years old Kopano, as well as my Sophos XG firewall is using the identical configuration. Anyway, when disabling STARTTLS and restarting NGINX at Grommunio Admin it is working without any problems -- once STARTTLS is enabled again, you cannot login anymore.

I have already copied my domain's CA (file extension *.crt) to
/usr/share/pki/trust/anchors/
and added it to the list of trusted CAs by running
update-ca-certificates
which also means that I can confirm, that STARTTLS is working, since I already can sync Users and import Users with STARTTLS enabled, but none of the users will be able to login to webmail. Disable STARTTLS again and restart NGINX, and it works again!

In Monitoring > ZCore the following log entries are created:
[2024-03-24 20:01:19.453714]: ldap_start_tls_s: Connect error [2024-03-24 20:01:19.454189]: ldap_adaptor: search with base "dc=ads,dc=domain,dc=tld" filter "mail=user@domain.tld": Can't contact LDAP server

Furthermore, every time you hit Save at the LDAP configuration page, the following errors are being displayed, even though the changes are applied correctly:
Configuration updated, but save to disk failed: 1 - Operation not permitted
or
Could not connect to LDAP server: 'NoneType' object has no attribute 'start_tls'

My LDAP configuration: /etc/gromox/ldap_adaptor.cfg
# Configuration automatically generated by grommunio-admin. ldap_disabled=False ldap_host=ldap://dc1.ads.domain.tld:389/ ldap://dc2.ads.domain.tld:389/ ldap_bind_user=CN=query,OU=accounts,DC=ads,DC=domain,DC=tld ldap_bind_pass=pass ldap_start_tls=False ldap_search_base=dc=ads,dc=domain,dc=tld ldap_object_id=objectGUID ldap_mail_attr=mail ldap_user_displayname=displayName ldap_user_filter=(&(objectClass=user)(memberOf=CN=GROMMUNIO Users,OU=groups,DC=ads,DC=domain,DC=tld)) ldap_contact_filter=(&(objectclass=contact)(memberOf=CN=GROMMUNIO Contacts,OU=groups,DC=ads,DC=domain,DC=tld)) ldap_user_search_attrs=mail ldap_user_search_attrs=givenName ldap_user_search_attrs=cn ldap_user_search_attrs=sn ldap_user_search_attrs=name ldap_user_search_attrs=displayName ldap_user_templates=common ldap_user_templates=ActiveDirectory ldap_user_aliases=otherMailbox ldap_group_addr=mail ldap_group_filter=(&(objectclass=group)(memberOf=CN=GROMMUNIO Groups,OU=groups,DC=ads,DC=domain,DC=tld)) ldap_group_name=cn ldap_group_memberof=memberOf

Best regards,
Chris

crpb · Mar 24, 2024

ckd ldap_host=ldap://dc1.ads.domain.tld:389/ ldap://dc2.ads.domain.tld:389/
ldap_bind_user=CN=query,OU=accounts,DC=ads,DC=domain,DC=tld
ldap_bind_pass=pass
ldap_start_tls=False

ahhh missed that after all that text :>

hmm.. have you tried it with openssl ot something just to see which tls versions are available? maybe there is some problem

ckd · Mar 25, 2024

One more thing I noticed. If you haven't synced for several, you are getting this one on first Sync Users:
OperationalError: (MySQLdb._exceptions.OperationalError) (2006, 'MySQL server has gone away')
This appears to be unrelated to STARTTLS though and happens on a fresh installation of the appliance; fully updated. Then simply wait a few seconds, hit Sync Users again and it works!

journalctl -f
Mar 25 08:28:30 srv uwsgi[22859]: [ERROR] (tasq) <worker> Traceback (most recent call last): Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 749, in _rollback_impl Mar 25 08:28:30 srv uwsgi[22859]: self.engine.dialect.do_rollback(self.connection) Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/dialects/mysql/base.py", line 2501, in do_rollback Mar 25 08:28:30 srv uwsgi[22859]: dbapi_connection.rollback() Mar 25 08:28:30 srv uwsgi[22859]: MySQLdb._exceptions.OperationalError: (2006, 'MySQL server has gone away') Mar 25 08:28:30 srv uwsgi[22859]: The above exception was the direct cause of the following exception: Mar 25 08:28:30 srv uwsgi[22859]: Traceback (most recent call last): Mar 25 08:28:30 srv uwsgi[22859]: File "./tools/tasq.py", line 83, in dispatch Mar 25 08:28:30 srv uwsgi[22859]: func(self, task) Mar 25 08:28:30 srv uwsgi[22859]: File "./tools/tasq.py", line 215, in ldapSync Mar 25 08:28:30 srv uwsgi[22859]: DB.session.rollback() Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/scoping.py", line 163, in do Mar 25 08:28:30 srv uwsgi[22859]: return getattr(self.registry(), name)(*args, **kwargs) Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 1010, in rollback Mar 25 08:28:30 srv uwsgi[22859]: self.transaction.rollback() Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 574, in rollback Mar 25 08:28:30 srv uwsgi[22859]: util.raise_(rollback_err[1], with_traceback=rollback_err[2]) Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 182, in raise_ Mar 25 08:28:30 srv uwsgi[22859]: raise exception Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 534, in rollback Mar 25 08:28:30 srv uwsgi[22859]: t[1].rollback() Mar 25 08:28:30 srv uwsgi[22859]: sqlalchemy.exc.OperationalError: (MySQLdb._exceptions.OperationalError) (2006, 'MySQL server has gone away') Mar 25 08:28:30 srv uwsgi[22859]: (Background on this error at: http://sqlalche.me/e/13/e3q8) Mar 25 08:28:30 srv uwsgi[22859]: [WARNING] (flask.app) POST /api/v1/domains/ldap/downsync?import=false from 203.0.113.2 -> 500 '{"message":"Synchronization failed: OperationalError: (MySQLdb._exceptions.OperationalError) (2006, \'MySQL server has gone away\')"}\n' Mar 25 08:28:34 srv uwsgi[22859]: Mon Mar 25 08:28:34 2024 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) !!! Mar 25 08:28:57 srv rspamd[1731]: (controller) rdns; rdns_parse_reply: DNS request with id 24449 is for different query, ignoring Mar 25 08:29:15 srv uwsgi[22859]: [WARNING] (flask.app) PUT /api/v1/system/mconf/authmgr? from 203.0.113.2 -> 500 '{"message":"Configuration updated, but save to disk failed: 1 - Operation not permitted"}\n' Mar 25 08:29:15 srv uwsgi[22859]: [WARNING] (flask.app) PUT /api/v1/system/mconf/ldap?force=false from 203.0.113.2 -> 500 '{"message":"Configuration updated, but save to disk failed: 1 - Operation not permitted"}\n'

ckd · Mar 25, 2024

crpb
Yeah sure thing! Works without any problems.

Command:
ldapsearch -x -D "query@ads.domain.tld" -b "ou=accounts,dc=ads,dc=domains,dc=tld" -H ldap://dc1.ads.domain.tld:389/ -W sAMAccountName=query -Z

Result:
Enter LDAP Password: extended LDIF LDAPv3 base <ou=accounts,dc=ads,dc=domain,dc=tld> with scope subtree filter: sAMAccountName=query requesting: ALL query, accounts, ads.domain.tld dn: CN=query,OU=accounts,DC=ads,DC=domain,DC=tld objectClass: top objectClass: person objectClass: organizationalPerson objectClass: user cn: query description: LDAP Bind givenName: query distinguishedName: CN=query,OU=accounts,DC=ads,DC=domain,DC=tld instanceType: 4 whenCreated: 20221023200607.0Z whenChanged: 20240316175606.0Z displayName: query uSNCreated: 22196 uSNChanged: 2376659 name: query objectGUID:: 46mztJAdykuXiQ+3fdxchA== userAccountControl: 66048 badPwdCount: 0 codePage: 0 countryCode: 0 badPasswordTime: 133553352062739353 lastLogoff: 0 lastLogon: 133553352219140328 pwdLastSet: 133111034892756837 primaryGroupID: 513 objectSid:: AQUAAAAAAAUVAAAAtJSUVcrtAV3lgemOWgQAAA== accountExpires: 9223372036854775807 logonCount: 2 sAMAccountName: query sAMAccountType: 805306368 userPrincipalName: query@ads.domain.tld lockoutTime: 0 objectCategory: CN=Person,CN=Schema,CN=Configuration,DC=ads,DC=domain,DC=tld dSCorePropagationData: 20221024145334.0Z dSCorePropagationData: 16010101000000.0Z lastLogonTimestamp: 133550853665748559 mail: query@domain.tld search result search: 3 result: 0 Success numResponses: 2 numEntries: 1

ckd · Mar 25, 2024

I guess Grommunio Admin can be special sometimes... after restaring NGINX it now works perfectly. Sorry guys.

However, some problems still remain, I will summarize them in this post.

I
If you haven't synced for several hours, you are getting this one on first Sync Users:
OperationalError: (MySQLdb._exceptions.OperationalError) (2006, 'MySQL server has gone away')

Then simply wait a few seconds, hit Sync Users again and it works again!

journalctl -f

Mar 25 08:28:30 srv uwsgi[22859]: [ERROR] (tasq) <worker> Traceback (most recent call last):
Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 749, in _rollback_impl
Mar 25 08:28:30 srv uwsgi[22859]: self.engine.dialect.do_rollback(self.connection)
Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/dialects/mysql/base.py", line 2501, in do_rollback
Mar 25 08:28:30 srv uwsgi[22859]: dbapi_connection.rollback()
Mar 25 08:28:30 srv uwsgi[22859]: MySQLdb._exceptions.OperationalError: (2006, 'MySQL server has gone away')
Mar 25 08:28:30 srv uwsgi[22859]: The above exception was the direct cause of the following exception:
Mar 25 08:28:30 srv uwsgi[22859]: Traceback (most recent call last):
Mar 25 08:28:30 srv uwsgi[22859]: File "./tools/tasq.py", line 83, in dispatch
Mar 25 08:28:30 srv uwsgi[22859]: func(self, task)
Mar 25 08:28:30 srv uwsgi[22859]: File "./tools/tasq.py", line 215, in ldapSync
Mar 25 08:28:30 srv uwsgi[22859]: DB.session.rollback()
Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/scoping.py", line 163, in do
Mar 25 08:28:30 srv uwsgi[22859]: return getattr(self.registry(), name)(*args, **kwargs)
Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 1010, in rollback
Mar 25 08:28:30 srv uwsgi[22859]: self.transaction.rollback()
Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 574, in rollback
Mar 25 08:28:30 srv uwsgi[22859]: util.raise_(rollback_err[1], with_traceback=rollback_err[2])
Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
Mar 25 08:28:30 srv uwsgi[22859]: raise exception
Mar 25 08:28:30 srv uwsgi[22859]: File "/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 534, in rollback
Mar 25 08:28:30 srv uwsgi[22859]: t[1].rollback()
Mar 25 08:28:30 srv uwsgi[22859]: sqlalchemy.exc.OperationalError: (MySQLdb._exceptions.OperationalError) (2006, 'MySQL server has gone away')
Mar 25 08:28:30 srv uwsgi[22859]: (Background on this error at: http://sqlalche.me/e/13/e3q8)
Mar 25 08:28:30 srv uwsgi[22859]: [WARNING] (flask.app) POST /api/v1/domains/ldap/downsync?import=false from 203.0.113.2 -> 500 '{"message":"Synchronization failed: OperationalError: (MySQLdb._exceptions.OperationalError) (2006, \'MySQL server has gone away\')"}\n'
Mar 25 08:28:34 srv uwsgi[22859]: Mon Mar 25 08:28:34 2024 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) !!!
Mar 25 08:28:57 srv rspamd[1731]: (controller) rdns; rdns_parse_reply: DNS request with id 24449 is for different query, ignoring
Mar 25 08:29:15 srv uwsgi[22859]: [WARNING] (flask.app) PUT /api/v1/system/mconf/authmgr? from 203.0.113.2 -> 500 '{"message":"Configuration updated, but save to disk failed: 1 - Operation not permitted"}\n'
Mar 25 08:29:15 srv uwsgi[22859]: [WARNING] (flask.app) PUT /api/v1/system/mconf/ldap?force=false from 203.0.113.2 -> 500 '{"message":"Configuration updated, but save to disk failed: 1 - Operation not permitted"}\n'

II
Eevery time you hit Save at the LDAP configuration page, the following errors are being displayed, even though the changes are applied correctly:
Configuration updated, but save to disk failed: 1 - Operation not permitted
or
Could not connect to LDAP server: 'NoneType' object has no attribute 'start_tls'