UDN Replication Error + S4-Database not updated

Hello,
after renaming a user we noticed, that this user was not able to login. He can still logon to Kopano WebApp, but has no access to the windows logon and file server.
The UCS Systemdianose tells about a S4-Reject and an error within UDN-Replikation.

What i did:

univention-s4connector-list-rejected
UCS rejected
S4 rejected
    1:    S4 DN: CN=Rainer Unsinn,OU=Benutzer,DC=domain,DC=local
         UCS DN: uid=r.unsinn,ou=benutzer,dc=domain,dc=local
	last synced USN: 723449
/usr/share/univention-s4-connector/remove_s4_rejected.py "CN=Rainer Unsinn ,OU=Benutzer,DC=domain,DC=local"
The rejected S4 object CN=Rainer Unsinn,OU=Benutzer,DC=domain,DC=local has been removed.
univention-ldapsearch -b "uid=r.hat-geheiratetk,ou=Benutzer,dc=domain,dc=local"
# extended LDIF
#
# LDAPv3
# base <uid=r.hat-geheiratet,ou=Benutzer,dc=damain,dc=local> with scope subtree
# filter: (objectclass=*)
# requesting: ALL
# r.hat-geheiratet, Benutzer, damin.local
dn: uid=r.hat-geheiratet,ou=Benutzer,dc=domain,dc=local
kopanoAccount: 1
uidNumber: 2039
.....
univention-s4search -b uid=r.hat-geheiratet,ou=Benutzer,dc=domain,dc=local
search error - LDAP error 32 LDAP_NO_SUCH_OBJECT -  <00002030: No such Base DN: uid=r.hat-geheiratet,ou=Benutzer,dc=domain,dc=local>
 /usr/share/univention-s4-connector/resync_object_from_ucs.py --filter uid=r.hat-geheiratat,ou=Benutzer,dc=domain,dc=local
No matching objects.

That’s strange… So i try to figure out, what’s the problem about UDM

/usr/lib/nagios/plugins/check_univentlication
CRITICAL: no change of listener transaction id for last 0 checks (nid=Error: [Errno 111] Connection refused lid=1630663)
systemctl restart univention-directory-notifier
systemctl restart univention-directory-listener

sv status univention-directory-listener | sed -n 's/:.*//p'
run

sv status univention-directory-notifier | sed -n 's/:.*//p'
run
tail -f /var/log/univention/notifier.log
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1406, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 420, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 464, in import_all
    with Index(opt.translog_file) as index, Translog(opt.translog_file, index) as translog, ldapi(opt) as ld:
  File "/usr/share/univention-directory-notifier/univention-translog", line 147, in __enter__
    assert reminder == 0, reminder
AssertionError: 2
usage: univention-translog ldap [-h] tid [tid ...]
univention-translog ldap: error: argument tid: invalid int value: ''
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1406, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 420, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 464, in import_all
    with Index(opt.translog_file) as index, Translog(opt.translog_file, index) as translog, ldapi(opt) as ld:
  File "/usr/share/univention-directory-notifier/univention-translog", line 147, in __enter__
    assert reminder == 0, reminder
AssertionError: 2
usage: univention-translog ldap [-h] tid [tid ...]
univention-translog ldap: error: argument tid: invalid int value: ''
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1406, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 420, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 464, in import_all
    with Index(opt.translog_file) as index, Translog(opt.translog_file, index) as translog, ldapi(opt) as ld:
  File "/usr/share/univention-directory-notifier/univention-translog", line 147, in __enter__
    assert reminder == 0, reminder
AssertionError: 2
usage: univention-translog ldap [-h] tid [tid ...]
univention-translog ldap: error: argument tid: invalid int value: ''
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1406, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 420, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 464, in import_all
    with Index(opt.translog_file) as index, Translog(opt.translog_file, index) as translog, ldapi(opt) as ld:
  File "/usr/share/univention-directory-notifier/univention-translog", line 147, in __enter__
    assert reminder == 0, reminder
AssertionError: 2
usage: univention-translog ldap [-h] tid [tid ...]
univention-translog ldap: error: argument tid: invalid int value: ''
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1406, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 420, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 464, in import_all
    with Index(opt.translog_file) as index, Translog(opt.translog_file, index) as translog, ldapi(opt) as ld:
  File "/usr/share/univention-directory-notifier/univention-translog", line 147, in __enter__
    assert reminder == 0, reminder
AssertionError: 2
usage: univention-translog ldap [-h] tid [tid ...]
univention-translog ldap: error: argument tid: invalid int value: ''
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1406, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 420, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 464, in import_all
    with Index(opt.translog_file) as index, Translog(opt.translog_file, index) as translog, ldapi(opt) as ld:
  File "/usr/share/univention-directory-notifier/univention-translog", line 147, in __enter__
    assert reminder == 0, reminder
AssertionError: 2
usage: univention-translog ldap [-h] tid [tid ...]
univention-translog ldap: error: argument tid: invalid int value: ''
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1406, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 420, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 464, in import_all
    with Index(opt.translog_file) as index, Translog(opt.translog_file, index) as translog, ldapi(opt) as ld:
  File "/usr/share/univention-directory-notifier/univention-translog", line 147, in __enter__
    assert reminder == 0, reminder
AssertionError: 2
usage: univention-translog ldap [-h] tid [tid ...]
univention-translog ldap: error: argument tid: invalid int value: ''
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1406, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 420, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 464, in import_all
    with Index(opt.translog_file) as index, Translog(opt.translog_file, index) as translog, ldapi(opt) as ld:
  File "/usr/share/univention-directory-notifier/univention-translog", line 147, in __enter__
    assert reminder == 0, reminder
AssertionError: 2
tail -f /var/log/univention/listener.log
27.04.20 11:56:01.369  LISTENER    ( ERROR   ) : failed to connect to any notifier
27.04.20 11:56:01.369  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds
27.04.20 11:56:31.369  LISTENER    ( WARN    ) : Notifier/LDAP server is server.domain.local:7389
27.04.20 11:56:31.369  LDAP        ( PROCESS ) : connecting to ldap://server.domain.local:7389
27.04.20 11:56:31.371  LDAP        ( INFO    ) : simple_bind as cn=admin,dc=domain,dc=local
27.04.20 11:56:31.372  LISTENER    ( INFO    ) : connecting to notifier server.domain.local:6669
27.04.20 11:56:31.372  LISTENER    ( INFO    ) : connection to 192.168.120.87 failed with errorcode 111: Connection refused
27.04.20 11:56:31.372  LISTENER    ( INFO    ) : connection to 192.168.120.87 failed with errorcode 111: Connection refused
27.04.20 11:56:31.372  LISTENER    ( ERROR   ) : failed to connect to any notifier
27.04.20 11:56:31.372  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds

So i set the machine password, as described here: Problem: Unable to (re-)join: 03univention-directory-listener.inst failed

The [MDB_MAP_FULL] is at 72%. But that all, did not fix the problems.
The renamed user can still not login. After changing the password for another user, he also can’t login.

Any suggestions?

Best regards
Andre

Here is my next step:

/usr/share/univention-directory-notifier/univention-translog check
2020-04-27 12:50:07,976:ERROR:/var/lib/univention-ldap/notify/transaction:1630662:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00': Missing newline line
2020-04-27 12:50:07,976:ERROR:/var/lib/univention-ldap/notify/transaction:1630662:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00': Binary zeros
2020-04-27 12:50:07,976:ERROR:/var/lib/univention-ldap/notify/transaction:1630662:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00': Invalid line

/var/lib/univention-ldap/notify/transaction needs fixing:
- contains unparseable lines!

See <https://help.univention.com/t/how-to-reset-listener-notifier-replication/11710> for more details.

I followed the link given in the output and excuted the univention-reset-replication-counters.py script. After that univention-translog check is clean.
But the Systemdiagnose tells now:

Univention Directory Notifier ID und die lokal gespeicherte Version unterscheiden sich.
Dies mag auf einen Fehler oder noch ausstehende Transaktionen hinweisen.

I don’t really know, what to do now…

Here is the actual output of the listener logfile:

27.04.20 13:14:33.784  LISTENER    ( INFO    ) : notifier returned = id:1718687	dn:<LDAP>	cmd:*
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : notifier.c:127:notifier_wait_id_result LDAP returned: id:1708704	dn:cn=r.unsinn,cn=uid,cn=temporary,cn=univention,dc=domain,dc=local	cmd:a
27.04.20 13:14:33.784  LISTENER    ( PROCESS ) : updating 'cn=r.unsinn,cn=uid,cn=temporary,cn=univention,dc=domain,dc=local' command a
27.04.20 13:14:33.784  LISTENER    ( ALL     ) : cache_get_entry: Read Transaction begin
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : dntree_get_id4dn: DN cn=r.unsinn,cn=uid,cn=temporary,cn=univention,dc=domain,dc=local not in id2dn
27.04.20 13:14:33.784  LISTENER    ( ALL     ) : cache_get_entry: Read Transaction abort
27.04.20 13:14:33.784  LISTENER    ( ALL     ) : updating by DN cn=r.unsinn,cn=uid,cn=temporary,cn=univention,dc=domain,dc=local
27.04.20 13:14:33.784  LISTENER    ( ALL     ) : blocking signals (was 0)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : delete handlers for cn=r.unsinn,cn=uid,cn=temporary,cn=univention,dc=domain,dc=local
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: selfservice (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: app_attributes (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: fetchmailrc (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: openid-connect-provider (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: univention-saml-servers (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: samba4-idmap (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: umc-service-providers (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: cups-printers (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: udm_extension (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: s4-connector (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: nagios-client (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: nextcloud-enable-for-classes-and-workgroups (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: selfservice-invitation (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: keytab (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: portal_server (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: gencertificate (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: well-known-sid-name-mapping (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: license_uuid (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: univention-saml-idp-config (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: nagios-server (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: samba-shares (skipped)
27.04.20 13:14:33.784  LISTENER    ( INFO    ) : handler: nss (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: univention-saml-simplesamlphp-configuration (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: nfs-shares (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: hosteddomains (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: portal_groups (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: keytab-member (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: kopano (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: nextcloud-samba-group-share-config (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: univention-admin-diary-backend (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: ad-connector (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: ldap_server (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: pkgdb-watch (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: bind (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: faillog (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: nfs-homes (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: ldap_extension (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: nscd_update (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: dhcp (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : handler: quota (skipped)
27.04.20 13:14:33.785  LISTENER    ( INFO    ) : deleted from cache: cn=r.unsinn,cn=uid,cn=temporary,cn=univention,dc=domain,dc=local
27.04.20 13:14:33.785  LISTENER    ( ALL     ) : unblocking signals (was 1)
27.04.20 13:14:33.785  LISTENER    ( ALL     ) : cache_update_master_entry: Transaction begin
27.04.20 13:14:33.785  LISTENER    ( ALL     ) : cache_update_master_entry: Transaction commit
27.04.20 13:14:33.793  LISTENER    ( INFO    ) : Last Notifier ID: 1708704
27.04.20 13:14:33.793  LISTENER    ( ALL     ) : >>>MSGID: 78043
WAIT_ID 1708705

so after a while evrything works fine now. All users are able to login to all services.
But i don’t understand, what happened and why it happened.

Is there any chance to prevent these errors?

Mastodon