Univention Bugzilla – Bug 22594
UMC maximum recursion depth reached
Last modified: 2012-02-17 10:20:55 CET
Dieser Bug wird auch durch den Code in den DVS-Modulen getriggert und scheint seine Ursache in einem Kommunikationsproblem zwischen UMC event loop und UVMM zu haben. Ausgelöst wird der Bug anscheinend unter anderem dadurch, dass ein Benutzer in einem UMC-Modul eine UVMM-Anfrage auslöst (z.B. Maschine Clonen) und nebenbei dann in einem zweiten UMC Modul eine weitere UVMM-Anfrage auslöst. Im konkreten Fall verbraucht der Prozess root 6354 31754 46 08:42 ? 00:20:00 /usr/bin/python2.4 /usr/sbin/univention-management-console-module -m dvs_templates -s /var/run/univention-management-console/31754-1306219366585.socket -i web -d 4 -l de_DE.utf8 dann ca. 90% CPU und looped im strace: -------------------------------------- gettimeofday({1306221660, 138522}, NULL) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 write(2, "2011-05-24 09:21:00,138: notifier: ERROR : maximum recursion depth reached\nNone\n"..., 82) = 82 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 write(8, "2011-05-24 09:21:00,138: notifier: ERROR : maximum recursion depth reached\nNone\n"..., 82) = 82 gettimeofday({1306221660, 139368}, NULL) = 0 -------------------------------------- In /var/log/univention/management-console-web.log stehen viele Meldungen folgender Art: -------------------------------------- 24.05.11 09:28:34 DEBUG_INIT 24.05.11 09:28:34 ADMIN ( ERROR ) : AJAX: EXCEPTION: [Errno 2] No such file or directory: '/tmp/webui/ffe604e17938c464caefb607da9b3c84/socket_filename' 24.05.11 09:28:34 ADMIN ( ERROR ) : AJAX: DATA = FieldStorage(None, None, [MiniFieldStorage('session_id', 'ffe604e17938c464caefb607da9b3c84'), MiniFieldStorage('umcpcmd', 'dvs/instance/state'), MiniFieldStorage('instance', 'qemu://xen13.dvs10.local/system#9902f9b7-2951-44a9-9e9e-1155e22e94f5'), MiniFieldStorage('dojo.preventCache', '1306222113769')]) 24.05.11 09:28:34 ADMIN ( ERROR ) : Traceback (most recent call last): File "/var/www/univention-management-console/ajax.py", line 87, in main fn = open('/tmp/webui/%s/socket_filename' % session_id).read() IOError: [Errno 2] No such file or directory: '/tmp/webui/ffe604e17938c464caefb607da9b3c84/socket_filename' -------------------------------------- Endresultat ist, dass die Logmeldungen die Platte fluten. Vermutlich ist das das gleiche Problem wie der Ursprungsbug: +++ This bug was initially created as a clone of Bug #21616 +++
Siehe auch Bug #21616 Comment 1
Das Problem kann eigentlich nur auftreten, wenn die parallel Anfragen innerhalb einer Sitzung eines Benutzers durchgeführt werden, da nur dann der selbe UMC-Modul diese Anfragen bearbeitet (so soll es zumindest sein). Das Problem wird in dem Fall wahrscheinlich durch ungefähr folgendes Verhalten hervorgerufen: Die Abfrage-Implementierung, die über mehrere Module kopiert wurde, arbeitet so, dass die Anfrage an UVMMd geschickt wird an anschließend auf die Antwort gewartet wird. Dabei wird aber weiterhin über eine "Mainloop in der Mainloop" auf weitere Anfrage gelauscht. Kommt in dem Zeitpunkt eine weitere Anfrage an wird diese ebenfalls an den UVMMd geschickt (über die gleiche Verbindung) und auf dieselbe Art und Weise auf die Antwort gewartet. Kommt eine Antwort rein kann nicht entschieden werden für welche der Anfragen die Antwort ist (Unzulänglichkeit des UVMM-Protokolls). Dadurch holt die der eine Wartende evtl. beide Antworten aus der Socket und der zweite "verhungert" Hier gibt es mehrere Möglichkeiten - Es wird immer nur eine Anfrge zur Zeit an den UVMMd geschickt. Alle anderen werden in eine Queue gehängt bis sie dran sind. Finde ich persönlich nicht so gut - Für jede Anfrage wird eine neue Verbindung geöffnet - Das UVMM-Protokoll wird um Request-IDs erweitert. So können Antworten den entsprechenden Anfragen zugeordnet werden. Der Code der UMC-Module muss dann auch angepasst werden. Wenn ich die Implementierung von univention.uvmm.client.UVMM_ClientSocket.receive richtig interpretiere werden Antworten auch "verschluckt", wenn an der Socket gerade zwei oder mehr liegen wenn die Funktion aufgerufen wird.
(In reply to comment #2) > Hier gibt es mehrere Möglichkeiten Ggf. sind hier auch einige meiner Annahmen falsch, was die Frontend- und Backend-UMC-Prozesse angeht, denn dadurch ergibt sich, welche Daten wo gehalten werden müssen: Im Request-Objekt oder z.B. in der/einer Wizard-Instanz. > - Es wird immer nur eine Anfrage zur Zeit an den UVMMd geschickt. Alle anderen > werden in eine Queue gehängt bis sie dran sind. Finde ich persönlich nicht so > gut > > - Für jede Anfrage wird eine neue Verbindung geöffnet Die momentane Implementierung versucht das derzeit so zu machen: Für die AJAX-Statusabfragen wird eine neue Verbindung geöffnet. > - Das UVMM-Protokoll wird um Request-IDs erweitert. So können Antworten den > entsprechenden Anfragen zugeordnet werden. Der Code der UMC-Module muss dann > auch angepasst werden. > > Wenn ich die Implementierung von > univention.uvmm.client.UVMM_ClientSocket.receive richtig interpretiere werden > Antworten auch "verschluckt", wenn an der Socket gerade zwei oder mehr liegen > wenn die Funktion aufgerufen wird. Das UVMM-Protokoll war nie für mehr als eine parallele Anfrage gleichzeigt entworfen. Deswegen enthält die u.uvmm.Client auch nur eine synchrone send+receive Implementierung, die asynchrone Implementierung ist erst durch UMC notwendig geworden, um das dort mit der Event-Loop zu verheiraten.
Ok, wenn die Ursachenbehebung nicht so einfach ist, könnte der UMC-Prozess den Fehlerzustand erkennen und darauf sinnvoll (ggf durch beenden) reagieren?
(In reply to comment #4) > Ok, wenn die Ursachenbehebung nicht so einfach ist, könnte der UMC-Prozess den > Fehlerzustand erkennen und darauf sinnvoll (ggf durch beenden) reagieren? "sinnvoll" ist denke ich nicht so einfach realisierbar, aber beenden müsste machbar sein :-)
Das ist gerade in einer UCS DVS Standardinstallation aufgetreten. Aus meiner Sicht muss das zum Release behoben werden.
(In reply to comment #5) > (In reply to comment #4) > > Ok, wenn die Ursachenbehebung nicht so einfach ist, könnte der UMC-Prozess den > > Fehlerzustand erkennen und darauf sinnvoll (ggf durch beenden) reagieren? > > "sinnvoll" ist denke ich nicht so einfach realisierbar, aber beenden müsste > machbar sein :-) Beenden halte ich an dieser Stelle für nicht sinnvoll, weil dann der Status von der Template Erstellung verloren geht. Man kann also die Instanz neu versiegeln. Können wir das parallele Abfragen aus UMC unterbinden?
Die maximale Rekursionstiefe wurde für den Modulprozess erhöht auf 50
In UMC wurde der RefreshFrame um einen optionalen, booleschen Parameter "no_concurrency" erweitert, der den Default "False" verwendet. no_concurrency=False: Der Javascript-Timer feuert im angegebenen Intervall und setzt Ajax-Requests ab, ungeachtet dessen, ob die Antwort für diese Requests bereits eingegangen ist. no_concurrency=True: NACH dem Eingang der Antwort wird ein neuer Timeout gestartet. Sollte eine Antwort ausbleiben, finden keine Refreshs mehr statt. Das regelmäßige Intervall zwischen den Anfragen setzt sich dabei aus a) dem angegebenem Intervall und b) der Zeit zwischen Anfrage und Antwort zusammen. Changelogeintrag wurde vorgenommen. Hint: Commit wurden fälschlicherweise mit Bugnummer 22711 vorgenommen.
Das Problem trat bei DVS-Tests mit UCS 2.4-3 nicht mehr auf. ChangeLog-Eintrag vorhanden
UCS 2.4-3 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".