[SOLVED] Listener Error: notifier_wait_id_result LDAP failed No such object

chris.g · March 23, 2023, 9:12am

Hello,

since the upgrade to UCS 5 one of our memberserver is not syncing anymore.

Listener Log:


23.03.23 10:06:46.757  LISTENER    ( ERROR   ) : notifier.c:132:notifier_wait_id_result LDAP failed No such object (32): id:352931
23.03.23 10:06:46.757  LISTENER    ( ERROR   ) : listener: 32

univention-directory-listener-ctrl status

univention-directory-listener-ctrl status
activating
Listener status:
 auto-restart

Current Notifier ID on "xxxxxx"
 376427

Last Notifier ID processed by local Listener:
 352930

tail: '/var/lib/univention-ldap/notify/transaction' kann nicht zum Lesen geöffnet werden: Datei oder Verzeichnis nicht gefunden
Last transaction processed:

...

Searching around leads to Problem: no change of listener transaction id for last 0 checks but there is no univention-translog.

Any ideas?

Update 1:

univention-translog is only available on UCS Master.

Executing it there shows:


2023-03-23 11:50:17,848:ERROR:/var/lib/univention-ldap/notify/transaction:352931:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00352932 zoneName=xxx.intra,cn=dns,dc=xxx,dc=intra m\n': Binary zeros
2023-03-23 11:50:17,848:ERROR:/var/lib/univention-ldap/notify/transaction:352931:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00352932 zoneName=xxx.intra,cn=dns,dc=xxx,dc=intra m\n': Hole after '352930 cn=printserver01,cn=memberserver,cn=computers,dc=xxx,dc=intra m'

/var/lib/univention-ldap/notify/transaction needs fixing:
- missing transactions in sequence

You can re-run this tool with the option "--fix" in order to try to fix this issue.
See <https://help.univention.com/t/problem-umc-diagnostic-module-complains-about-problems-with-udn-replication/11707/1> for more details.

Running it with --fix throws an error:

2023-03-23 11:44:44,586:ERROR:/var/lib/univention-ldap/notify/transaction:352931:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00352932 zoneName=xxx.intra,cn=dns,dc=xxx,dc=intra m\n': Binary zeros
2023-03-23 11:44:44,587:ERROR:/var/lib/univention-ldap/notify/transaction:352931:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00352932 zoneName=xxx.intra,cn=dns,dc=xxx,dc=intra m\n': Hole after '352930 cn=printserver01,cn=memberserver,cn=computers,dc=xxx,dc=intra m'

/var/lib/univention-ldap/notify/transaction needs fixing:
- missing transactions in sequence
2023-03-23 11:44:50,278:ERROR:/var/lib/univention-ldap/notify/transaction:352931:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00352932 zoneName=xxx.intra,cn=dns,dc=xxx,dc=intra m\n': Binary zeros
2023-03-23 11:44:50,278:ERROR:/var/lib/univention-ldap/notify/transaction:352931:'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00352932 zoneName=xxx.intra,cn=dns,dc=xxx,dc=intra m\n': Hole after '352930 cn=printserver01,cn=memberserver,cn=computers,dc=xxx,dc=intra m'

2023-03-23 11:44:50,278:ERROR:/var/lib/univention-ldap/notify/transaction:352932:'352931 dc=xxx,dc=intra m\n': Repeated line after '352932 zoneName=xxx.intra,cn=dns,dc=xxx,dc=intra m'
Traceback (most recent call last):
  File "/usr/share/univention-directory-notifier/univention-translog", line 1443, in <module>
    exit(main())
  File "/usr/share/univention-directory-notifier/univention-translog", line 417, in main
    return opt.func(opt) or 0
  File "/usr/share/univention-directory-notifier/univention-translog", line 696, in check
    translog.run()
  File "/usr/share/univention-directory-notifier/univention-translog", line 860, in run
    self.fixit()
  File "/usr/share/univention-directory-notifier/univention-translog", line 1119, in fixit
    self.fix_fill()
  File "/usr/share/univention-directory-notifier/univention-translog", line 1037, in fix_fill
    assert not self.needs_fill
AssertionError

Update 2:

After manually fixing /var/lib/univention-ldap/notify/transaction as described here Problem: UMC Diagnostic Module Complains about Problems with UDN Replication no error is reported anymore by univention-translog check but the listener is not working anymore.

systemctl restart univention-directory-notifier.service produces

start-stop-daemon: invalid option -- 'f'
Try 'start-stop-daemon --help' for more information.
23.03.23 12:26:16.042  DEBUG_INIT

in /var/log/univention/notifier.log

UCS Backup reports:

==> /var/log/univention/listener.log <==
23.03.23 12:27:00.413  LISTENER    ( WARN    ) : Notifier/LDAP server is xxx.xxx.intra:7389
23.03.23 12:27:00.413  LDAP        ( PROCESS ) : connecting to ldap://xxx.xxx.intra:7389
23.03.23 12:27:00.422  LISTENER    ( ERROR   ) : failed to connect to any notifier
23.03.23 12:27:00.422  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds

netstat in UCS Master:

# netstat -nlp | grep 7389
tcp        0      0 0.0.0.0:7389            0.0.0.0:*               LISTEN      11754/slapd
tcp6       0      0 :::7389                 :::*                    LISTEN      11754/slapd

# systemctl status univention-directory-notifier.service
● univention-directory-notifier.service - Univention Directory Notifier Daemon
   Loaded: loaded (/lib/systemd/system/univention-directory-notifier.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2023-03-23 12:26:16 CET; 2min 6s ago
  Process: 2473 ExecStartPre=/usr/share/univention-directory-notifier/import_translog.sh (code=exited, status=0/SUCCESS)
 Main PID: 2475 (univention-dire)
    Tasks: 1 (limit: 4915)
   Memory: 816.0K
   CGroup: /system.slice/univention-directory-notifier.service
           └─2475 /usr/sbin/univention-directory-notifier -F -d 1 -v 3

Mär 23 12:26:16 udc02 systemd[1]: Starting Univention Directory Notifier Daemon...
Mär 23 12:26:16 udc02 systemd[1]: Started Univention Directory Notifier Daemon.

Update 3:

last_id doesn’t match last transaction

# cat /var/lib/univention-ldap/last_id
376496

# tail -n 1 /var/lib/univention-ldap/notify/transaction
376492 xxxxx m

Might this be the source of the notifier not working correctly? If yes, how to fix this?

Update 4:

After increasing the notifier loglevel to 4 ucr set notifier/debug/level=4 and tailing the log tail -F /var/log/univention/notifier.log it looks like the notifier is trying to catch up as it’s logging older IDs. Maybe that’s why no listener can connect. I will report back after it reaches the current IDs.

Update 5:

Alright, notifier is back. But i’m back to the first problem.
The memberserver still complains about the missing ID.

notifier.c:132:notifier_wait_id_result LDAP failed No such object (32): id:352931

But it’s in the transaction file on UCS Master now:

# grep 352931 /var/lib/univention-ldap/notify/transaction
352931 dc=xxx,dc=intra m

I’m running out of ideas now.

Any hints?

Update 6:

The missing piece was to load the transaction on UCS master after adding the dummy entry

/usr/share/univention-directory-notifier/univention-translog load 352931

Now everything looks fine.

requate · March 23, 2023, 4:57pm

Great to hear that you were able to debug it with persistence and that you got it to work again.

chris.g:

systemctl restart univention-directory-notifier.service produces
start-stop-daemon: invalid option -- 'f'
Try 'start-stop-daemon --help' for more information.
23.03.23 12:26:16.042  DEBUG_INIT

This sounded scary to me. Glad you where able to get it running.

chris.g · March 24, 2023, 7:27am

I still would suggest to look into why /usr/share/univention-directory-notifier/univention-translog wasn’t able to fix it by itself. The Error thrown by the script indicates that it wasn’t able to detect the gap in the IDs, which it should.

The notifier startup error is still there

start-stop-daemon: invalid option -- 'f'
Try 'start-stop-daemon --help' for more information.
23.03.23 12:26:16.042  DEBUG_INIT

Investigating a bit more shows that it must be coming from /usr/share/univention-directory-notifier/import_translog.sh where it calls start-stop-daemon with slapd and paramater -f but isn’t handling the arguments correctly.

set -e

t='/var/lib/univention-ldap/notify/transaction'
if [ -s "$t" ] &&
    [ -f /var/univention-join/joined ] &&
    start-stop-daemon --status --pidfile /var/run/slapd/slapd.pid -x /usr/sbin/slapd -f /etc/ldap/slapd.conf &&
    last="$(awk 'END{print $1}' "$t")" &&
    ! /usr/share/univention-directory-notifier/univention-translog ldap "$last" >/dev/null
then
    /usr/share/univention-directory-notifier/univention-translog --lenient import
fi

If i’m not wrong, the correct way would be:

start-stop-daemon --status --pidfile /var/run/slapd/slapd.pid -x /usr/sbin/slapd -- "-f /etc/ldap/slapd.conf" &&

chris.g · April 12, 2023, 7:36am

@requate can you please bring these 2 bugs to the attention of the dev team?

univention-translog not detecting gap
wrong call to start-stop-daemon in import_translog.sh

Thank you.

requate · April 12, 2023, 11:50am

Thanks for the heads up, I’ve created Bug 55957 – systemctl restart univention-directory-notifier: start-stop-daemon: invalid option -- 'f' for the second issue and a merge request to fix it.

I also was able tor reproduce the first issue and created Bug 55958 – univention-translog check --fix throws "self.needs_fill" AssertionError traceback in certain cases .

chris.g · April 12, 2023, 12:08pm

Regarding the reply from a dev on BUG 55957

He is wrong and should inspect the unit file instead of just saying “works for me”!

/lib/systemd/system/univention-directory-notifier.service has:

And in ExecStartPre=/usr/share/univention-directory-notifier/import_translog.sh one can clearly see it:

I added a comment to the bug report.