After Patching UCS 4.4-7 to latest errata 966: "failed to contact LDAP server"

Hello,

once again I am writing in this forum, as I am at my wits’ end. After being a bit behind with the patches due to illness, I wanted to bring the UCS from errata910 to errata966 version 4.4-7 the day before yesterday. In the process, a Kopano component was also updated.
The update apparently went through cleanly:

Starting dist-upgrade at Di 4. Mai 08:11:11 CEST 2021
...
The update has been finished successfully at Di 4. Mai 08:15:46 CEST 2021.

Afterwards I restarted the UCS VM because the errata contained a kernel update.

After checking the functionality of UCS, I also deleted the VM snapshot.

This morning there were severe problems with the login of the various devices, which I was able to trace back to the following via SSH research (login WebGUI just as not possible as with other users as “root”):

failed to contact LDAP server: cannot connect with univention-ldapsearch

I tried:
systemctl status slapd.service

which gives:

slapd.service - LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol)
   Loaded: loaded (/etc/init.d/slapd; generated; vendor preset: enabled)
   Active: active (running) since Thu 2021-05-06 09:21:12 CEST; 8h ago
     Docs: man:systemd-sysv-generator(8)
 Main PID: 82300 (slapd)
      CPU: 16min 4.158s
   CGroup: /system.slice/slapd.service
           └─82300 /usr/sbin/slapd -h ldapi:/// ldap://:7389/ ldaps://:7636/

univention-ldapsearch
gives:
ldap_bind: Invalid credentials (49)

However,
/usr/sbin/udm users/user list
seems to be complete.

Checking /var/log/univention/server_password_change.log reveals:

Starting server password change (Tue May  4 01:04:34 CEST 2021)
No server password change scheduled for today, terminating without a change
Starting server password change (Wed May  5 01:09:33 CEST 2021)
No server password change scheduled for today, terminating without a change
Starting server password change (Thu May  6 01:09:56 CEST 2021)
Proceeding with regular server password change scheduled for today
run-parts: executing /usr/lib/univention-server/server_password_change.d/50univention-mail-server prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/70kopano prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/portal-server-password-rotate prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-admin-diary prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-bind prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-dhcp prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-directory-manager-rest prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-libnss-ldap prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-nscd prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-s4-connector prechange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-samba4 prechange
Object modified: cn=ucs,cn=dc,cn=computers,dc=somedomain,dc=local
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-samba4 localchange
Modified 1 records successfully
Changed password OK
Stopping samba-ad-dc (via systemctl): samba-ad-dc.service.
Stopping smbd (via systemctl): smbd.service.
Stopping nmbd (via systemctl): nmbd.service.
Starting nmbd (via systemctl): nmbd.service.
Starting smbd (via systemctl): smbd.service.
Starting samba-ad-dc (via systemctl): samba-ad-dc.service.
run-parts: executing /usr/lib/univention-server/server_password_change.d/50univention-mail-server postchange
File: /etc/listfilter.secret
Multifile: /etc/postfix/ldap.distlist
Multifile: /etc/postfix/ldap.groups
Multifile: /etc/postfix/ldap.external_aliases
Multifile: /etc/postfix/ldap.sharedfolderlocal
Multifile: /etc/postfix/ldap.virtualwithcanonical
Multifile: /etc/postfix/ldap.virtual_mailbox
Multifile: /etc/postfix/ldap.sharedfolderremote
Multifile: /etc/postfix/ldap.sharedfolderlocal_aliases
Multifile: /etc/postfix/ldap.virtual
Multifile: /etc/postfix/ldap.canonicalrecipient
Multifile: /etc/postfix/ldap.transport
Multifile: /etc/postfix/ldap.canonicalsender
Multifile: /etc/postfix/ldap.saslusermapping
Multifile: /etc/postfix/ldap.virtualdomains
run-parts: executing /usr/lib/univention-server/server_password_change.d/70kopano postchange
Setting kopano/cfg/ldap/ldap_bind_passwd
Module: kopano-cfg
dpkg-query: no packages found matching kopano4ucs-multiserver
run-parts: executing /usr/lib/univention-server/server_password_change.d/portal-server-password-rotate postchange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-admin-diary postchange
549eadff-199f-4ae6-8620-2ed68b4ea7c3
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-bind postchange
run-parts: /usr/lib/univention-server/server_password_change.d/univention-bind exited with return code 1
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-dhcp postchange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-directory-manager-rest postchange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-libnss-ldap postchange
File: /etc/libnss-ldap.conf
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-nscd postchange
Restarting nscd (via systemctl): nscd.service.
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-s4-connector postchange
run-parts: executing /usr/lib/univention-server/server_password_change.d/univention-samba4 postchange
done (Thu May  6 01:10:46 CEST 2021)
Starting server password change (Do 6. Mai 08:27:32 CEST 2021)
Proceeding with regular server password change scheduled for today
ldap_bind: Invalid credentials (49)
failed to contact LDAP server: cannot connect with univention-ldapsearch
Starting server password change (Do 6. Mai 18:06:36 CEST 2021)
Proceeding with regular server password change scheduled for today
ldap_bind: Invalid credentials (49)
failed to contact LDAP server: cannot connect with univention-ldapsearch

Not good!

Trying manually with:

ucr set server/password/interval=-1
/usr/lib/univention-server/server_password_change
ucr set server/password/interval=21 (default)

also does not work, again:
failed to contact LDAP server: cannot connect with univention-ldapsearch

univention-run-join-scripts
does not help either, it fails at first at
20univention-directory-policy.inst
with

ldap.INVALID_CREDENTIALS: {'desc': 'Invalid credentials'}

Can someone please help me get the credentials back in sync?

BR,
TP

Hmmm… :face_with_monocle:

root@ucs:~# systemctl status slapd.service
● slapd.service - LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol)
   Loaded: loaded (/etc/init.d/slapd; generated; vendor preset: enabled)
   Active: active (running) since Thu 2021-05-06 09:21:12 CEST; 9h ago
     Docs: man:systemd-sysv-generator(8)
 Main PID: 82300 (slapd)
      CPU: 18min 21.939s
   CGroup: /system.slice/slapd.service
           └─82300 /usr/sbin/slapd -h ldapi:/// ldap://:7389/ ldaps://:7636/

Mai 06 09:54:59 ucs slapd[82300]: connection_read(14): no connection!
Mai 06 10:15:02 ucs slapd[82300]: connection_read(22): no connection!
Mai 06 10:57:35 ucs slapd[82300]: connection_read(14): no connection!
Mai 06 11:00:03 ucs slapd[82300]: connection_read(14): no connection!
Mai 06 11:08:14 ucs slapd[82300]: connection_read(14): no connection!
Mai 06 13:21:38 ucs slapd[82300]: connection_read(14): no connection!
Mai 06 16:05:08 ucs slapd[82300]: connection_read(14): no connection!
Mai 06 17:14:01 ucs slapd[82300]: connection_read(14): no connection!
Mai 06 18:00:03 ucs slapd[82300]: connection_read(24): no connection!
Mai 06 18:15:05 ucs slapd[82300]: connection_read(14): no connection!
root@ucs:~#
root@ucs:~#
root@ucs:~# netstat -tlpen | grep slapd
tcp        0      0 0.0.0.0:7636            0.0.0.0:*               LISTEN      0          486099     82300/slapd
tcp        0      0 0.0.0.0:7389            0.0.0.0:*               LISTEN      0          486095     82300/slapd
tcp6       0      0 :::7636                 :::*                    LISTEN      0          486100     82300/slapd
tcp6       0      0 :::7389                 :::*                    LISTEN      0          486096     82300/slapd

:face_with_raised_eyebrow:

Hello,

in the meantime our whole domain is in tilt. The user profiles can’t be accessed anymore, DHCP is of course also dead, only local user accounts work and all shares are inaccessible. I.e. working is currently no longer possible.
If someone offers remote support (also for a fee), offers are welcome!

Just to make this clear, because I forgot it above:

echo $(date +%y%m%d%H%M)': '$(cat /etc/machine.secret) >> /etc/machine.secret.old

NEWPW=$( pwgen -s 20 1 )

udm computers/domaincontroller_master modify --dn "$(ucr get ldap/hostdn)" --set password=$NEWPW

echo -n $NEWPW > /etc/machine.secret

unset NEWPW

systemctl daemon-reload

/usr/lib/univention-server/server_password_change

It seems to run cleanly, but the result is always the same:
failed to contact LDAP server: cannot connect with univention-ldapsearch

As a very last resort, I could import the VM backup from the day before, but then I would have to retrieve a complete workday from the remaining backups for mail, etc. That would again be a considerable effort and risky.

Of course, I would have to deactivate the automatic password rotation until further notice, so that the whole thing doesn’t start all over again overnight…

Please, anybody?

After I wanted to exclude that I screwed up the system too much by my interventions, I restored the backup from shortly after the fateful password rotation in the meantime.

Since I came across some Kopano errors while searching for further correlations, I’ll post those as well, maybe there is a connection.

From here on it seems to go wrong:

(maybe unrelated) Server.log:

Thu May  6 01:10:28 2021: [warning] K-1244: Your database does not support storing 4-byte UTF-8! The content of some mails may be truncated. The DB should be upgraded with `kopano-dbadm usmp` and kopano-server be restarted.

...

Thu May  6 01:10:29 2021: [warning] Config warning: Option "ldap_protocol" is recognized but obsolete, and will be removed in a future release.
Thu May  6 01:10:29 2021: [warning] LDAP (simple) bind on cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld failed: Invalid credentials
Thu May  6 01:10:29 2021: [warning] Previous message logged 2 times

syslog:

May  6 01:10:02 ucs CRON[118052]: (root) CMD (if [ -x /usr/bin/mrtg ] && [ -r /etc/mrtg.cfg ] && [ -d "$(grep '^[[:space:]]*[^#]*[[:space:]]*WorkDir' /etc/mrtg.cfg | awk '{ print $NF }')" ]; then mkdir -p /var/log/mrtg ; env LANG=C /usr/bin/mrtg /etc/mrtg.cfg 2>&1 | tee -a /var/log/mrtg/mrtg.log ; fi)
May  6 01:10:02 ucs CRON[118059]: (root) CMD (/usr/sbin/jitter 60 /usr/share/univention-samba4/scripts/sysvol-sync.sh >>/var/log/univention/sysvol-sync.log 2>&1)
May  6 01:10:02 ucs CRON[118062]: (root) CMD (  if [ -x /usr/sbin/univention-umount-homedirs ]; then /usr/sbin/univention-umount-homedirs; fi)
May  6 01:10:03 ucs ADMINDIARY: {"username": "ucs", "args": {"name": "ucs", "module": "computers/domaincontroller_master"}, "tags": [], "context_id": "someuid", "timestamp": "2021-05-06 01:10:03", "message": {"de": "DC Master {name} bearbeitet", "en": "DC Master {name} modified"}, "hostname": "ucs", "type": "Entry v1", "event": "UDM_COMPUTERS_DOMAINCONTROLLER_MASTER_MODIFIED"}
May  6 01:10:03 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:03#012New Hash=somehash
May  6 01:10:04 ucs systemd[1]: Stopping LSB: Univention Directory Listener Daemon...
May  6 01:10:05 ucs systemd[1]: Reloading Univention Portal server.
May  6 01:10:05 ucs systemd[1]: Reloaded Univention Portal server.
May  6 01:10:05 ucs univention-portal-server[906]: refreshing cache
May  6 01:10:05 ucs univention-portal-server[906]: INFO:univention.portal.cache:refreshing cache
May  6 01:10:05 ucs slapd[2091]: <= mdb_equality_candidates: (univentionComputerPortal) not indexed
May  6 01:10:05 ucs univention-portal-server[906]: No CSS code available
May  6 01:10:05 ucs univention-portal-server[906]: INFO:univention.portal.css:No CSS code available
May  6 01:10:05 ucs univention-portal-server[906]: Writing CSS file /var/www/univention/portal/portal.css
May  6 01:10:05 ucs univention-portal-server[906]: INFO:univention.portal.css:Writing CSS file /var/www/univention/portal/portal.css
May  6 01:10:05 ucs slapd[2091]: <= mdb_equality_candidates: (univentionPortalEntryPortal) not indexed
May  6 01:10:10 ucs univention-directory-listener[118088]: Stopping Univention Directory Listener Daemon: univention-directory-listener.
May  6 01:10:10 ucs systemd[1]: Stopped LSB: Univention Directory Listener Daemon.
May  6 01:10:10 ucs systemd[1]: Starting LSB: Univention Directory Listener Daemon...
May  6 01:10:10 ucs univention-directory-listener[118111]: Starting Univention Directory Listener Daemon: univention-directory-listener.
May  6 01:10:10 ucs systemd[1]: Started LSB: Univention Directory Listener Daemon.
May  6 01:10:14 ucs systemd[1]: Stopping LSB: Samba daemons for the AD DC...
May  6 01:10:14 ucs samba-ad-dc[118149]: Stopping Samba AD DC daemon: samba.
May  6 01:10:14 ucs systemd[1]: Stopped LSB: Samba daemons for the AD DC.
May  6 01:10:14 ucs systemd[1]: Stopping LSB: Samba SMB/CIFS daemon (smbd)...
May  6 01:10:14 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=admin,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:06#012New Hash=somehash
May  6 01:10:15 ucs smbd[118171]: Samba is configured as AD DC, service smbd is controlled by the main samba daemon.
May  6 01:10:15 ucs systemd[1]: Stopped LSB: Samba SMB/CIFS daemon (smbd).
May  6 01:10:15 ucs systemd[1]: Stopping LSB: Samba NetBIOS nameserver (nmbd)...
May  6 01:10:16 ucs nmbd[118185]: Stopping NetBIOS name server: nmbd.
May  6 01:10:16 ucs systemd[1]: Stopped LSB: Samba NetBIOS nameserver (nmbd).
May  6 01:10:17 ucs systemd[1]: Starting LSB: Samba NetBIOS nameserver (nmbd)...
May  6 01:10:17 ucs nmbd[118202]: Starting NetBIOS name server: nmbd.
May  6 01:10:17 ucs systemd[1]: Started LSB: Samba NetBIOS nameserver (nmbd).
May  6 01:10:17 ucs systemd[1]: Starting LSB: Samba SMB/CIFS daemon (smbd)...
May  6 01:10:18 ucs smbd[118221]: Samba is configured as AD DC, service smbd is controlled by the main samba daemon.
May  6 01:10:18 ucs systemd[1]: Started LSB: Samba SMB/CIFS daemon (smbd).
May  6 01:10:18 ucs systemd[1]: Starting LSB: Samba daemons for the AD DC...
May  6 01:10:19 ucs samba-ad-dc[118234]: Starting Samba AD DC daemon: samba.
May  6 01:10:19 ucs systemd[1]: Started LSB: Samba daemons for the AD DC.
May  6 01:10:20 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=admin,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:20#012New Hash=somehash
May  6 01:10:21 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=admin,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:21#012New Hash=somehash
May  6 01:10:22 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=admin,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:22#012New Hash=somehash
May  6 01:10:23 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=admin,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:23#012New Hash=somehash
May  6 01:10:23 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=admin,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:23#012New Hash=somehash
May  6 01:10:23 ucs slapd[2091]: ppolicy udm_lock_account failed: <class 'univention.admin.uexceptions.wrongObjectType'>
May  6 01:10:23 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=admin,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:23#012New Hash=somehash
May  6 01:10:23 ucs systemd[1]: Stopping Kopano Groupware Core Storage Server...
May  6 01:10:24 ucs directory_logger: DN=cn=ucs,cn=dc,cn=computers,dc=somename,dc=sometld#0XXID=XXXXX#0XXModifier=cn=admin,dc=somename,dc=sometld#012Timestamp=05.05.2021 23:10:24#012New Hash=somehash
May  6 01:10:28 ucs kopano-server[1938]: Error in my_thread_global_end(): 2 threads didn't exit
May  6 01:10:28 ucs systemd[1]: Stopped Kopano Groupware Core Storage Server.
May  6 01:10:28 ucs systemd[1]: Started Kopano Groupware Core Storage Server.
May  6 01:10:28 ucs systemd[1]: Reloading Univention Portal server.
May  6 01:10:28 ucs systemd[1]: Reloaded Univention Portal server.
May  6 01:10:28 ucs univention-portal-server[906]: refreshing cache
May  6 01:10:28 ucs univention-portal-server[906]: INFO:univention.portal.cache:refreshing cache
May  6 01:10:28 ucs slapd[2091]: <= mdb_equality_candidates: (univentionComputerPortal) not indexed
May  6 01:10:28 ucs univention-portal-server[906]: No CSS code available
May  6 01:10:28 ucs univention-portal-server[906]: INFO:univention.portal.css:No CSS code available
May  6 01:10:28 ucs univention-portal-server[906]: Writing CSS file /var/www/univention/portal/portal.css
May  6 01:10:28 ucs univention-portal-server[906]: INFO:univention.portal.css:Writing CSS file /var/www/univention/portal/portal.css
May  6 01:10:28 ucs slapd[2091]: <= mdb_equality_candidates: (univentionPortalEntryPortal) not indexed
May  6 01:10:28 ucs ADMINDIARY: {"username": "root", "args": {"hostname": "ucs"}, "tags": [], "context_id": "someuid", "timestamp": "2021-05-06 01:10:28", "message": {"de": "Maschinenpasswort von {hostname} erfolgreich ge\u00e4ndert", "en": "Machine account password of {hostname} changed successfully"}, "hostname": "ucs", "type": "Entry v1", "event": "SERVER_PASSWORD_CHANGED"}
May  6 01:10:29 ucs systemd[1]: Stopping LSB: DHCP server...
May  6 01:10:34 ucs check_nrpe: Remote 192.168.78.3 accepted a Version 3 Packet
May  6 01:10:35 ucs univention-dhcp[118403]: Stopping DHCP server: dhcpdok: down: univention-dhcp: 1s
May  6 01:10:35 ucs univention-dhcp[118403]: .
May  6 01:10:35 ucs systemd[1]: Stopped LSB: DHCP server.
May  6 01:10:35 ucs systemd[1]: Starting LSB: DHCP server...
May  6 01:10:35 ucs dhcpd[118437]: Internet Systems Consortium DHCP Server 4.3.5
May  6 01:10:35 ucs dhcpd[118437]: Copyright 2004-2016 Internet Systems Consortium.
May  6 01:10:35 ucs dhcpd[118437]: All rights reserved.
May  6 01:10:35 ucs dhcpd[118437]: For info, please visit https://www.isc.org/software/dhcp/
May  6 01:10:35 ucs dhcpd[118437]: Error: Cannot login into ldap server ucs.somename.sometld:7389: Invalid credentials
May  6 01:10:35 ucs dhcpd[118437]: Configuration file errors encountered -- exiting
May  6 01:10:35 ucs dhcpd[118437]: 
May  6 01:10:35 ucs dhcpd[118437]: If you think you have received this message due to a bug rather
May  6 01:10:35 ucs dhcpd[118437]: than a configuration issue please read the section on submitting
May  6 01:10:35 ucs dhcpd[118437]: bugs on either our web page at www.isc.org or in the README file
May  6 01:10:35 ucs dhcpd[118437]: before submitting a bug.  These pages explain the proper
May  6 01:10:35 ucs dhcpd[118437]: process and the information we find helpful for debugging..
May  6 01:10:35 ucs dhcpd[118437]: 
May  6 01:10:35 ucs univention-dhcp[118428]: dhcpd self-test failed with 1. Check /etc/dhcp/dhcpd.conf.
May  6 01:10:35 ucs univention-dhcp[118428]: The error was:
May  6 01:10:35 ucs univention-dhcp[118428]: Internet Systems Consortium DHCP Server 4.3.5
May  6 01:10:35 ucs univention-dhcp[118428]: Copyright 2004-2016 Internet Systems Consortium.
May  6 01:10:35 ucs univention-dhcp[118428]: All rights reserved.
May  6 01:10:35 ucs univention-dhcp[118428]: For info, please visit https://www.isc.org/software/dhcp/
May  6 01:10:35 ucs univention-dhcp[118428]: Error: Cannot login into ldap server ucs.somename.sometld:7389: Invalid credentials
May  6 01:10:35 ucs univention-dhcp[118428]: Configuration file errors encountered -- exiting
May  6 01:10:35 ucs univention-dhcp[118428]: If you think you have received this message due to a bug rather
May  6 01:10:35 ucs univention-dhcp[118428]: than a configuration issue please read the section on submitting
May  6 01:10:35 ucs univention-dhcp[118428]: bugs on either our web page at www.isc.org or in the README file
May  6 01:10:35 ucs univention-dhcp[118428]: before submitting a bug.  These pages explain the proper
May  6 01:10:35 ucs univention-dhcp[118428]: process and the information we find helpful for debugging..
May  6 01:10:35 ucs univention-dhcp[118428]: exiting.

Following @DirkS 's hint via e-mail (many thanks and sorry Mr. Schnick, I first had to awkwardly extract the credentials to our email provider, as we’ve been using fetchmail for years and manage the passwords for direct access in a password manager, which was also no longer accessible…):

“Have you configured faillog or ppolicy lockout?”

I was sent in the right direction and followed the howto to disable the lockouts and now at least “univention-ldapsearch” works again…

This is already the second time that this howto gets us into big trouble.

I was absolutely not aware that this setting can cause such problems for the whole domain and according to me it is not mentioned or at least not clearly enough.

2 Likes
Mastodon