Bug 16098 - univention-directory-listener cache scheint auf Master nicht aktualisiert zu werden
univention-directory-listener cache scheint auf Master nicht aktualisiert zu ...
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: LDAP
UCS 2.2
Other Linux
: P1 normal (vote)
: UCS 2.3-1
Assigned To: Arvid Requate
Philipp Hahn
:
Depends on:
Blocks: 16618
  Show dependency treegraph
 
Reported: 2009-10-26 13:58 CET by Arvid Requate
Modified: 2011-05-11 15:55 CEST (History)
3 users (show)

See Also:
What kind of report is it?: ---
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Attachments
Debug Listener Modul (1.65 KB, text/x-python)
2010-01-11 14:33 CET, Arvid Requate
Details
Test-Skript (5.18 KB, text/plain)
2010-02-02 11:35 CET, Philipp Hahn
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Arvid Requate univentionstaff 2009-10-26 13:58:19 CET
Auf Master Systemen scheinen die Daten im Listener Cache nicht immer aktualisiert zu werden und der Listener scheint unter Umständen den Listener Modulen im 'new' Objekt alte Daten (aus dem Cache?) zu übergeben.

Es ist noch unklar, ob das ggf. durch defekte Einträge in der Cache Datenbank ausgelöst wird.

Ein Anhaltspunkt könnte sein, dass

  univention-directory-listener-verify \
    -D uid=Administrator,cn=users,dc=univention,dc=test\
    -b dc=univention,dc=test -w 'passwort'

auf einem Slave zufrieden über den Zustand des Caches im Vergleich zu den Daten im Verzeichnis ist, auf einem Master aber Inkonsistenzen gemeldet werden.
Comment 1 Arvid Requate univentionstaff 2009-10-27 16:48:19 CET
Tritt auch auf Backup auf.

Ggf. ist das auf die lowercase Änderungen am Listener für Bug #15003 zurückzuführen. Auf den betroffenen Systemen (Master & Backup) zeigt "univention-directory-listener-dump -O /tmp/cache.ldif" folgende Informationen (gekürzt):

( In den folgenden Debug-Auszügen ist ou=<localtion1>,<$ldap/basedn> an den DNs sinngemäss zu ergänzen )

Master:
======
dn: uid=tts,ou=People,
modifyTimestamp: 20090901131127Z
listenerModule: directory_logger
listenerModule: custom_export

dn: uid=tts,ou=people,
quota: 12345                        <- Attribut vorhanden
modifyTimestamp: 20091027132023Z    <- das ist laut ldapsearch aktuell
listenerModule: custom_export
listenerModule: directory_logger

Backup:
======
dn: uid=tts,ou=People,
modifyTimestamp: 20090901131127Z
listenerModule: replication

dn: uid=tts,ou=people,
modifyTimestamp: 20090901131127Z
listenerModule: replication
listenerModule: custom_export

Auf dem Backup liefert der Listener bei einem resync auf das custom_export Modul als 'new' einen Eintrag ohne 'quota' Attribut und kein 'old'.

Auf dem Master wird ebenfalls der alte Eintrag geliefert. Eine künstlich erzeugte Debug Ausgabe im listener.log zeigt kein 'quota' Attribut und den alten mofifyTimestamp (gekürzt):

27.10.09 16:36:29  LISTENER    ( INFO   ) : custom_export: dn: uid=tts,ou=People,
27.10.09 16:36:29  LISTENER    ( INFO   ) : custom_export: new: {'uid': ['tts'], 'objectClass': ['top', 'person', 'univentionPWHistory', 'posixAccount', 'shadowAccount', 'univentionMail', 'sambaSamAccount', 'organizationalPerson', 'inetOrgPerson', 'krb5Principal', 'krb5KDCEntry', 'scalixUserClass'], 'modifyTimestamp': ['20090901131127Z'] }
27.10.09 16:36:29  LISTENER    ( ERROR   ) : custom_export: old: {}
Comment 2 Janis Meybohm univentionstaff 2009-11-12 10:24:57 CET
Das betrifft nicht nur den Resync von Modulen, siehe: 2009111010000247
Comment 3 Arvid Requate univentionstaff 2010-01-11 14:15:14 CET
Der an Ticket#: 2009091610000446 vorgeschlagene Patch,der dafür sorgt, dass nicht mehr alte Cache-Einträge mit Uppercase DN-key aus dem Cache geholt werden, sondern immer erst der lowercase-Key versucht wird, war schonmal ein Anfang, aber nicht ausreichend.
Beim resync eines Moduls werden in change_init_module alle Cache-Einträge sequentiell ausgelesen, das Modul daran entfernt und wieder geschrieben.
Das führt mit dem Patch aus Bug #15003 dazu, dass ein alter Cache-Eintrag mit Uppercase DN-key ausgelesen und dann unter lowercase DN-key geschrieben wird.

Es gibt jetzt die alte cache_update_entry Funktion wieder, die case-Preserving ist. Für das geänderte Verhalten aus Bug #15003 gibt es jetzt eine neue Funktion cache_update_entry_lower, die als wrapper für die alte Funktion implementiert ist. Analog gibt es zwei neue Funktionen cache_entry_get_lower_upper und cache_etnry_delete_lower_upper, die zunächst den lowercase DN-key verwenden und bei DB_NOTFOUND Ergebnis es nochmal mit dem Uppercase DN-key versuchen, falls der übergebene DN mixedCase war.

Ein Testverfahren mit Debug.py Listener Modul wird angehängt. Changelog:

\item Ein Fehler beim Auslesen der Cache-Daten im \ucsName{univention-directory-listener} wurde behoben, der dazu führen konnte, dass bei der Verwendung von Großsbuchstaben in DNs im Falle eines Resync auf ein Listener-Modul veraltete (pre UCS 2.2-2) Daten ausgegeben wurden. Dieser Fehler lag in einer Änderung in UCS 2.2-2 begründet. Ein ähnliches Verhalten bei der Modifikation von solchen Verzeichniseinträgen wurde ebenfalls korrigiert. (Bug 16098)
Comment 4 Arvid Requate univentionstaff 2010-01-11 14:33:00 CET
Created attachment 2206 [details]
Debug Listener Modul

Zum Test ist es sinnvoll, ein Debug Listener Modul zu verwenden und zunächst kurz eine ältere Version des univention-directory-listeners aus UCS 2.2-0 zu installieren, um damit z.B. einen User mit Uppercasse Uid anzulegen. Die alte Version von univention-directory-listener legt Uppercase DNs auch noch so im Cache ab. Ab UCS 2.2-2 schreibt univention-directory-listener solche DNs hingegen als lowercase in den Cache, wobei der alte Cache-Eintrag jedoch im Cache erhalten bleibt.
---
# Debug Listener Modul installieren:
scp debug.py testvm:/usr/lib/univention-directory-listener/system/debug.py
# listener aus UCS 2.2-0 installieren:
apt-get install univention-directory-listener=3.0.2-2.48.200902190935
/etc/init.d/univention-directory-listener restart

# Test User1 anlegen
eval $(ucr shell ldap/base)
udm users/user create --position cn=users,$ldap_base --set username=User1 --set description=Test0 --set password=univention --set lastname=Univention
# Am bestene heier gleich auch User2 und User3 mit anlegen für weitere Tests.

# Cache-Check
/etc/init.d/univention-directory-listener stop
univention-directory-listener-dump |grep -i ^"dn: uid=User1"
/etc/init.d/univention-directory-listener start

# Aktualisierten Listener installieren
apt-get install univention-directory-listener

# Description am User ändern
udm users/user modify --dn uid=User1,cn=users,$ldap_base --set description=Test1
# Cache-Check: zwei Einträge
/etc/init.d/univention-directory-listener stop
univention-directory-listener-dump |grep -i ^"dn: uid=User1"
/etc/init.d/univention-directory-listener start

# Erneut Description am User ändern
udm users/user modify --dn uid=User1,cn=users,$ldap_base --set description=Test2
# Check /var/log/univention/listener.log:
# - Die Änderung muss in 'old' als description 'Test1' und nicht 'Test0' zeigen

# Resync auslösen:
univention-directory-listener-ctrl resync debug
# Check /var/log/univention/listener.log:
# - Die Änderung muss in 'new' als description 'Test2' und nicht 'Test0' zeigen

## Gut wäre es, auch kurz das Löschen von Einträgen zu testen:
# a) Upercase Cache-Eintrag erzeugen (User2) und dann direkt nach Installation des neuen listeners löschen. Erwartung: Uppercase Cache-Eintrag sollte entfernt werden.
# b) Upercase Cache-Eintrag erzeugen (User2) und dann direkt nach Installation des neuen listeners modifizieren. Danach löschen. Erwartung: lowercase Cache-Eintrag sollte entfernt werden, Uppercase Cache-Eintrag bleibt erhalten (das ist ok).
Comment 5 Tobias Scherer univentionstaff 2010-01-27 09:12:03 CET
An Ticket#: 2010012510000413 hat dieser Bug vermutlich das cups-printers Modul auf den Printservern(DC Backup) mit alten Daten versorgt, was zu erheblichen Schwierigkeiten beim Anlegen von ca. 400 Druckern führte. Es lagen nach dem resync Skripte mit falschen/alten Daten unter /var/cache/univention-printserver welche beim Cupsneustart versucht wurden auszuführen und fehlschlugen. Auch nach dem Ändern von fast allen Druckern im LDAP per udm cli, hat ein resync auf cups-printers die Werte von vor der Änderung verwendet.
Bitte bei der QA berücksichtigen.
Comment 6 Philipp Hahn univentionstaff 2010-02-02 09:41:47 CET
(In reply to comment #4)
> # b) Upercase Cache-Eintrag erzeugen (User2) und dann direkt nach Installation
> des neuen listeners modifizieren. Danach löschen. Erwartung: lowercase
> Cache-Eintrag sollte entfernt werden, Uppercase Cache-Eintrag bleibt erhalten
> (das ist ok).

Das ist ein Problem:
2.2-0: create User2
2.3-0: modify User2 -> user2
2.3-0: remove user2
2.3-0: create user2 <-- hier wird in 'old' der ursprüngliche User2 aus dem Cache übergeben, d.h. das wird als 'modify' und nicht als 'create' gewertet! In Bug #16618 trat genau so ein Problem auf, daß sowohl 'old' alsauch 'new' übergeben wurden, so daß kein bind-Zonendatei-Eintrag hinzugefügt wurde.

Vermutlich ist es geschickter, bei einem 'delete' alle Groß-/Klein-Schreibweisen aus dem Cache zu löschen.
Comment 7 Philipp Hahn univentionstaff 2010-02-02 11:35:32 CET
Created attachment 2259 [details]
Test-Skript

Das Skript läuft mit dem derzeitig _fehlerhaften_ Verhalten auf einem Master durch.
Das _gewünschte_ Verhalten ist in den FIXME-Kommentaren angegeben.

Auf einem Slave scheitert am Ende das Löschen der angelegten Testbenutzer, da die Daten nicht aus dem Cache entfernt werden (können?):
02.02.10 11:15:16  LISTENER    ( ERROR   ) : DEBUG(modify): old: ['uid=User1,cn=users,dc=univention,dc=qa'] ['Test2']
02.02.10 11:15:16  LISTENER    ( ERROR   ) : DEBUG(modify): new: ['uid=User1,cn=users,dc=univention,dc=qa'] ['Test3']
02.02.10 11:15:26  LISTENER    ( ERROR   ) : DEBUG(delete): old: ['uid=User1,cn=users,dc=univention,dc=qa'] ['Test3']
02.02.10 11:15:26  LISTENER    ( ERROR   ) : DEBUG(delete): new:
02.02.10 11:15:26  LISTENER    ( WARN    ) : listener does not have value for key entryCSN
02.02.10 11:15:26  LISTENER    ( WARN    ) : memberUid: LDAP values and listener values diff
02.02.10 11:15:26  LISTENER    ( WARN    ) : replication: old entries from LDAP server and Listener do not match
02.02.10 11:15:27  LISTENER    ( WARN    ) : listener does not have value for key krb5Key
02.02.10 11:15:27  LISTENER    ( WARN    ) : replication: old entries from LDAP server and Listener do not match

univention-directory-listener-dump:
 dn: uid=User1,cn=users,dc=univention,dc=qa
 ...
 listenerModule: replication
 listenerModule: custom_export
 listenerModule: debug
Comment 8 Arvid Requate univentionstaff 2010-02-02 18:51:02 CET
Der univention-directory-listener versucht jetzt bei mixedcase DNs auch immer nicht nur den lowercase-Eintrag zu löschen, sondern auch den mixedcase-Eintrag.
Das Test-Script lief erfolgreich durch.
Comment 9 Philipp Hahn univentionstaff 2010-02-09 14:24:49 CET
Mein Test-Skript läuft jetzt auch erwartungsgemäß ohne anzuecken durch.

Bezüglich der Druckertreiber sollte das Problem auch behoben sein: Die CUPS-Druckertreiber benutzen gemischte Groß-/Kleinschreibung in den DNs, was beim Modifizieren zu Doppeleintragungen (mixed- & lower-case) geführt hat. Mit der neusten Version in 2.3-1 sollte das jetzt behoben sein.

ChangeLog-Eintrag ist vorhanden -> VERIFIED
Comment 10 Arvid Requate univentionstaff 2010-02-18 14:32:37 CET
UCS 2.3-1 wurde veröffentlicht. Sollte der hier beschriebene Bug mit einer
neueren Version von UCS erneut auftreten, so sollte der Bug dupliziert werden:
"Clone This Bug".