Univention Bugzilla – Bug 21616
New UVMMd protocol needed - allow multiple concurrent calls
Last modified: 2023-06-28 10:46:01 CEST
Bei einem Partner (Ticket#: 2011021710000292) trat das Problem auf, daß auf einem frisch installiertem UCS-2.4-0 Master mit anschließendem Upgrade auf 2.4-1 eine VM installiert werden sollte. Nach dem Anlegen der VM blieb die UMC für >1h im "in progress"-Zustand hängen (Vermuting: UMC-Timout 3.600.000 ms). Während dieser Zeit konnte der Partner aber weiterhin in der UMC arbeiten. Im UVMMd.log war nichts auffällig zu finden: Das Image wurde <1s angelegt, ebenso die VM. Danach erfolgen nur noch die Eintragungen im LDAP (vorher wurde einmalig ein LDAP-Problem bein Start von UVMM gemeldet) und das Warten auf wait_for_update() (maximal 10s), was hier keine Rolle spielen sollte. (Allerdings keine Meldung, das die Funktion wirklich fertig war.) 2011-02-09 17:34:16,262 - uvmmd.ldap - INFO - Using cached LDAP data "/var/cache/univention-virtual-machine-manager-daemon/ldap.pic" 2011-02-09 17:34:16,262 - uvmmd - WARNING - Could not query "ldap://cebit-master.demo.ucs:389/dc=demo,dc=ucs" Im UMC-Module.log fanden sich nur zahlreiche Meldungen zu Problemen bei der Kommunikation über den UVMMd-UNIX-Socket: 10.02.11 13:20:53 ADMIN ( WARN ) : UVMM: send failed 10.02.11 17:19:42 ADMIN ( ERROR ) : Execution of command 'uvmm/domain/state' has failed: Traceback (most recent call last): File "/usr/lib/python2.4/site-packages/univention/management/console/handlers/__init__.py", line 160, in execute func( object ) File "/usr/lib/python2.4/site-packages/univention/management/console/handlers/uvmm/__init__.py", line 1018, in uvmm_domain_state resp = self.uvmm.domain_set_state( object.options[ 'node' ], object.options[ 'domain' ], object.options[ 'state' ] ) File "/usr/lib/python2.4/site-packages/univention/management/console/handlers/uvmm/uvmmd.py", line 334, in domain_set_state return self.recv_blocking() File "/usr/lib/python2.4/site-packages/univention/management/console/handlers/uvmm/uvmmd.py", line 133, in recv_blocking notifier.step() File "/usr/lib/python2.4/site-packages/notifier/nf_generic.py", line 231, in step if not timer[ CALLBACK ](): File "/usr/lib/python2.4/site-packages/univention/management/console/protocol/modserver.py", line 125, in _timed_out sys.exit( 0 ) SystemExit: 0 Ebenso in der UMC-server.log: 10.02.11 12:32:59 ADMIN ( ERROR ) : Client.connect: failed: (2, 'No such file or directory') 10.02.11 12:32:59 ADMIN ( ERROR ) : Client.connect: failed: (2, 'No such file or directory') 10.02.11 12:32:59 ADMIN ( ERROR ) : Client.connect: failed: (2, 'No such file or directory') 10.02.11 12:32:59 ADMIN ( ERROR ) : Client.connect: failed: (2, 'No such file or directory') 10.02.11 12:32:59 ADMIN ( ERROR ) : Client.connect: failed: (2, 'No such file or directory') 10.02.11 12:32:59 ADMIN ( ERROR ) : Client.connect: failed: (2, 'No such file or directory') 10.02.11 12:32:59 ADMIN ( ERROR ) : Client.connect: failed: (2, 'No such file or directory') 10.02.11 12:32:59 ADMIN ( ERROR ) : Client.connect: failed: (2, 'No such file or directory') 10.02.11 12:35:53 ADMIN ( WARN ) : socket died (module=uvmm) 10.02.11 12:35:53 ADMIN ( WARN ) : module process died: cleaning up requests 10.02.11 12:38:08 ADMIN ( ERROR ) : values: ERROR: UMCP PARSING ERROR Ebenso in der UMV-web.log: 11.02.11 14:16:08 ADMIN ( ERROR ) : Traceback (most recent call last): File "/usr/share/univention-management-console/frontend/univention-console-frontend.py", line 335, in main raise Exception( 'timeout' ) # timeout Exception: timeout Auch in der UVMMd.log: 2011-02-11 13:46:06,228 - uvmmd.node - DEBUG - domain_callback cebit-backup(-1) Stopped 4 2011-02-11 13:46:06,253 - uvmmd.unix - ERROR - [2] Exception: Traceback (most recent call last): File "/usr/lib/python2.4/site-packages/univention/uvmm/unix.py", line 114, in handle self.wfile.write(packet) File "/usr/lib/python2.4/socket.py", line 248, in write self.flush() File "/usr/lib/python2.4/socket.py", line 235, in flush self._sock.sendall(buffer) error: (32, 'Broken pipe') In der UMC-Server-Log fanden sich einen am Tag darauf massenhaft folgende Meldungen, die ggf. Bug #12034 sind: 2011-02-11 13:45:33,347: notifier: ERROR : maximum recursion depth reached None Das Problem ein einmalig aufgetreten: Beim Versuch das ganze nachzustellen, funktionierte alles Reibungslos. Weitere Besonderheit: Der Aufbau ist für ein Messe-System: Der Host ist der DC_Master und KVM Host, in dem ein DC_Backup virtualisiert laufen soll. Weitere berichtete Probleme waren: - Maschine ließ sich nicht herunterfahren: Gast meldete suspend, aber kvm-Prozeß wurde nicht beenden - Bei einem anderen Sichern sind die KVM- und libvirt-Prozesse abgestürzt
Ursache sind mindestens 2 Probleme: 1. Nach dem Senden einer Anfrage über den UNIX-Socket an den UVMMd muß das UMC-Modul warten, wozu einen Unter-Eventloop gestartet wird: notifier.step() Durch die Verwendung von AJAX kommt es dann wohl dazu, daß parallel zu einer laufenden Anfrage eine weitere dazukommt, die dann parallel über die gleiche UVMMd-Verbindung abgearbeitet wird und zum Problem mit der "maximum recursion depth reached" führt. 2. Das UVMMd-Protokoll ist nicht auf die parallele Abarbeitung von mehreren Kommandos über nur eine Socket-Verbindung gleichzeitig ausgelegt: es gibt keine Request-ID, über die eine Antwort ihrer ursprünglichen Anfrage zugeordnet werden kann. Deswegen öffnet das UMC-Modul schon eine zweite Verbindung zum UVMMd, über die die AJAX-Request gesondert abgehandelt werden. Das hat die Situation verbessert, allerdings tritt der Fehler immer noch auf.
Siehe auch Bug 22594
This issue has been filed against UCS 4.2. UCS 4.2 is out of maintenance and many UCS components have changed in later releases. Thus, this issue is now being closed. If this issue still occurs in newer UCS versions, please use "Clone this bug" or reopen it and update the UCS version. In this case please provide detailed information on how this issue is affecting you.