Bug 20296 - UVMM Modul läd nicht / UVMMd reagiert nicht/läuft nich
UVMM Modul läd nicht / UVMMd reagiert nicht/läuft nich
Status: CLOSED WONTFIX
Product: UCS
Classification: Unclassified
Component: Virtualization - UVMM
UCS 2.4
Other Linux
: P5 normal (vote)
: ---
Assigned To: UCS maintainers
:
: 21661 21702 (view as bug list)
Depends on: 21874
Blocks:
  Show dependency treegraph
 
Reported: 2010-10-07 12:23 CEST by Janis Meybohm
Modified: 2023-06-28 10:46 CEST (History)
4 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
uvmmd backtrace von samla (1.16 KB, text/plain)
2010-11-25 12:14 CET, Janis Meybohm
Details
uvmmd backtrace skubb (1.16 KB, text/plain)
2010-11-25 12:14 CET, Janis Meybohm
Details
uvmmd backtrace von skubb #2 (8.26 KB, text/plain)
2010-12-20 09:58 CET, Janis Meybohm
Details
lsof & gdb von samla 20110222-120835 (18.00 KB, text/plain)
2011-02-22 12:10 CET, Janis Meybohm
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Janis Meybohm univentionstaff 2010-10-07 12:23:24 CEST
Es gibt fälle in denen das UVMM Modul nicht geladen wird, in der UMC wird dann in einem endlosen Refresh "Der Vorgang ist noch nicht abgeschlossen. Bitte warten ..." angezeigt.

In der UVMMd Logfile gibt es seit einiger Zeit keine Einträge mehr (auch nicht die timer_callback Meldungen). Auf einem System wo das derzeit der Fall ist hängt der UVMMd in einem futex:
Process 315 attached with 2 threads - interrupt to quit
[pid   315] restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid   314] futex(0x238cef0, FUTEX_WAIT_PRIVATE, 0, NULL
Comment 1 Philipp Hahn univentionstaff 2010-10-08 08:11:44 CEST
Ein "lof -p 314" hat gezeigt, daß der laufende UVMM weiterhin brav nach /var/log/univention/virtual-machine-manager-daemon.log.7 geloggt hat, was er eben damals als /var/log/univention/virtual-machine-manager-daemon.log geöffnet und inzwischen durch logrotate mehrfach umbenannt wurde; dorft fehlt definitiv auch noch eine Funktionalität in UVMMd zum neu-öffnen des Logfiles (SIGHUP?) oder ein Neustart.
Aber auch im besagten Logfile war nichts zu finden.

Weiterhin hat das lsof auch keine weiteren auffälligen Verbindungen gezeigt.

Der Versuch herauszubekommen, welchen SysCall Thread 315 da gerade wiederholt hat, führte auch nicht zum Erfolg: Die Ausgabe von SysRq-t (echo t >/proc/sysrq-trigger) war für den Log-Puffer zu groß.
$ echo $((1 << $(sed -ne 's/CONFIG_LOG_BUF_SHIFT=//p' /boot/config-$(uname -r))))
131072
Comment 2 Philipp Hahn univentionstaff 2010-11-02 19:57:18 CET
Mal wieder bei einem Kunden aufgetreten. Im UMC-Log fand sich ein Hinweis auf den Traceback aus Bug #20177. Der dort beschriebene Fehler kann auch Ursache für diesen Bug hier sein, daß durchaus mal Socket-Verbindungen beim UVMM unsauber geschlossen werden.

Der Fix (s/socket/sock) wurde beim Kunden manuell durchgeführt. Nach einem Neustart von univention-management-console-server konnte das UVMM-Modul im UMC erstmal wieder aufgerufen erden.
Comment 3 Janis Meybohm univentionstaff 2010-11-15 14:04:32 CET
Ticket#: 2010102810000641 
Beim Kunden hat der Fix von Bug #20177 vermutlich das Problem des "immer ladenden" UMC Moduls behoben oder es zumindest deutlich verbessert.
Comment 4 Janis Meybohm univentionstaff 2010-11-25 12:14:08 CET
Created attachment 2857 [details]
uvmmd backtrace von samla

Das Problem des nicht mehr reagierenden UVMMd haben wir gerade wieder auf samla und skubb.
In diesem Fall aufgefallen da ein vom Listener gestartetes "/usr/sbin/univention-virtual-machine-manager add qemu://tirup.knut.univention.de/system" nicht beendet wurde und der Listener dadurch stehen bleibt.
Comment 5 Janis Meybohm univentionstaff 2010-11-25 12:14:36 CET
Created attachment 2858 [details]
uvmmd backtrace skubb
Comment 6 Philipp Hahn univentionstaff 2010-11-25 14:00:12 CET
Für den Backtrace:
  univention-install gdb libc6-dbg libldap-2.4-2-dbg libvirt0-dbg python2.4-dbg
  gdb -batch -p `pgrep -f univention-virtual-machine-manager-daemon` -x /dev/stdin <<<$'thread apply all bt\ndetach'

Verdächtig ist, daß nur noch 2 Threads existieren:
1 ist der Hauptthread, der per select() auf neue Verbindungen wartet. Dieses kann gerade keine neuen Verbindungen annehmen, weil er auf ein Semaphor wartet.
2 ist ein unbekannter Thread, der ein Verezichnis probiert auszulesen (fts_read()). Verdächtig ist das Auftachen von libldap_r.so im Backtrace, was ggf. darauf hindeutet, daß dort ein LDAP-Aufruf im Gange ist.

Fehlen tut auf jeden Fall der Event-Loop-Thread von libvirt und die beiden Timer-Threads für die beiden Hosts, die von diesem UVMMd überwacht werden.

Aus dem Logfile /var/log/univention/virtual-machine-manager-daemon.log.6 ergibt sich, daß der letzte Eintrag vom 2010-11-18 00:30:35,126 ist: die üblichen timer_callback()-Aufrufe. In den übrigen Logfiles ist nichts verdächtiges zu diesem Zeitpunkt zu finden.

# cat /proc/4414/maps 
00400000-00501000 r-xp 00000000 08:02 427739                             /usr/bin/python2.4
00701000-0072c000 rw-p 00101000 08:02 427739                             /usr/bin/python2.4
0072c000-00733000 rw-p 00000000 00:00 0 
01856000-07cd9000 rw-p 00000000 00:00 0                                  [heap]
4006f000-40070000 ---p 00000000 00:00 0 
40070000-40870000 rw-p 00000000 00:00 0 
40870000-40871000 ---p 00000000 00:00 0 
40871000-41071000 rw-p 00000000 00:00 0 
418c5000-418c6000 ---p 00000000 00:00 0 
418c6000-420c6000 rw-p 00000000 00:00 0 
7fbe4b5dc000-7fbe4b5e0000 r-xp 00000000 08:02 895879                     /lib/libnss_dns-2.7.so (deleted)
7fbe4b5e0000-7fbe4b7df000 ---p 00004000 08:02 895879                     /lib/libnss_dns-2.7.so (deleted)
7fbe4b7df000-7fbe4b7e1000 rw-p 00003000 08:02 895879                     /lib/libnss_dns-2.7.so (deleted)
7fbe4b7e1000-7fbe4b7e3000 r-xp 00000000 08:02 895915                     /lib/libpam_misc.so.0.81.3
7fbe4b7e3000-7fbe4b9e3000 ---p 00002000 08:02 895915                     /lib/libpam_misc.so.0.81.3
7fbe4b9e3000-7fbe4b9e4000 rw-p 00002000 08:02 895915                     /lib/libpam_misc.so.0.81.3
7fbe4b9e4000-7fbe4b9ef000 r-xp 00000000 08:02 895916                     /lib/libpam.so.0.81.12
7fbe4b9ef000-7fbe4bbee000 ---p 0000b000 08:02 895916                     /lib/libpam.so.0.81.12
7fbe4bbee000-7fbe4bbef000 rw-p 0000a000 08:02 895916                     /lib/libpam.so.0.81.12
7fbe4bbef000-7fbe4bbf3000 r-xp 00000000 08:02 430442                     /usr/lib/python2.4/site-packages/PAMmodule.so
7fbe4bbf3000-7fbe4bdf2000 ---p 00004000 08:02 430442                     /usr/lib/python2.4/site-packages/PAMmodule.so
7fbe4bdf2000-7fbe4bdf3000 rw-p 00003000 08:02 430442                     /usr/lib/python2.4/site-packages/PAMmodule.so
7fbe4bdf3000-7fbe4bdfc000 r-xp 00000000 08:02 489536                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/SSL.so
7fbe4bdfc000-7fbe4bffb000 ---p 00009000 08:02 489536                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/SSL.so
7fbe4bffb000-7fbe4c000000 rw-p 00008000 08:02 489536                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/SSL.so
7fbe4c000000-7fbe4c7aa000 rw-p 00000000 00:00 0 
7fbe4c7aa000-7fbe50000000 ---p 00000000 00:00 0 
7fbe50065000-7fbe50071000 r-xp 00000000 08:02 489537                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/crypto.so
7fbe50071000-7fbe50271000 ---p 0000c000 08:02 489537                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/crypto.so
7fbe50271000-7fbe50277000 rw-p 0000c000 08:02 489537                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/crypto.so
7fbe50277000-7fbe50279000 r-xp 00000000 08:02 489535                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/rand.so
7fbe50279000-7fbe50478000 ---p 00002000 08:02 489535                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/rand.so
7fbe50478000-7fbe50479000 rw-p 00001000 08:02 489535                     /usr/lib/python-support/python-openssl/python2.4/OpenSSL/rand.so
7fbe504ba000-7fbe504c4000 r-xp 00000000 08:02 895854                     /lib/libnss_files-2.7.so (deleted)
7fbe504c4000-7fbe506c4000 ---p 0000a000 08:02 895854                     /lib/libnss_files-2.7.so (deleted)
7fbe506c4000-7fbe506c6000 rw-p 0000a000 08:02 895854                     /lib/libnss_files-2.7.so (deleted)
7fbe506c6000-7fbe50748000 rw-p 00000000 00:00 0 
7fbe50749000-7fbe5084d000 rw-p 00000000 00:00 0 
7fbe5084e000-7fbe50993000 rw-p 00000000 00:00 0 
7fbe50994000-7fbe50a57000 rw-p 00000000 00:00 0 
7fbe50a57000-7fbe50a5f000 r-xp 00000000 08:02 427965                     /usr/lib/libcrack.so.2.8.0
7fbe50a5f000-7fbe50c5f000 ---p 00008000 08:02 427965                     /usr/lib/libcrack.so.2.8.0
7fbe50c5f000-7fbe50c60000 rw-p 00008000 08:02 427965                     /usr/lib/libcrack.so.2.8.0
7fbe50c60000-7fbe50c64000 rw-p 00000000 00:00 0 
7fbe50c64000-7fbe50c65000 r-xp 00000000 08:02 427993                     /usr/lib/python2.4/site-packages/_cracklibmodule.so
7fbe50c65000-7fbe50e65000 ---p 00001000 08:02 427993                     /usr/lib/python2.4/site-packages/_cracklibmodule.so
7fbe50e65000-7fbe50e66000 rw-p 00001000 08:02 427993                     /usr/lib/python2.4/site-packages/_cracklibmodule.so
7fbe50e66000-7fbe50f50000 r-xp 00000000 08:02 428667                     /usr/lib/libdb-4.2.so
7fbe50f50000-7fbe51150000 ---p 000ea000 08:02 428667                     /usr/lib/libdb-4.2.so
7fbe51150000-7fbe51154000 rw-p 000ea000 08:02 428667                     /usr/lib/libdb-4.2.so
7fbe51154000-7fbe5115c000 r-xp 00000000 08:02 895867                     /lib/libcrypt-2.7.so (deleted)
7fbe5115c000-7fbe5135c000 ---p 00008000 08:02 895867                     /lib/libcrypt-2.7.so (deleted)
7fbe5135c000-7fbe5135e000 rw-p 00008000 08:02 895867                     /lib/libcrypt-2.7.so (deleted)
7fbe5135e000-7fbe5138c000 rw-p 00000000 00:00 0 
7fbe5138c000-7fbe513b3000 r-xp 00000000 08:02 428666                     /usr/lib/libwind.so.0.0.0
7fbe513b3000-7fbe515b2000 ---p 00027000 08:02 428666                     /usr/lib/libwind.so.0.0.0
7fbe515b2000-7fbe515b3000 rw-p 00026000 08:02 428666                     /usr/lib/libwind.so.0.0.0
7fbe515b3000-7fbe515f6000 r-xp 00000000 08:02 428669                     /usr/lib/libhx509.so.3.0.0
7fbe515f6000-7fbe517f5000 ---p 00043000 08:02 428669                     /usr/lib/libhx509.so.3.0.0
7fbe517f5000-7fbe517f9000 rw-p 00042000 08:02 428669                     /usr/lib/libhx509.so.3.0.0
7fbe517f9000-7fbe5180d000 r-xp 00000000 08:02 428800                     /usr/lib/libroken.so.18.1.0
7fbe5180d000-7fbe51a0c000 ---p 00014000 08:02 428800                     /usr/lib/libroken.so.18.1.0
7fbe51a0c000-7fbe51a0d000 rw-p 00013000 08:02 428800                     /usr/lib/libroken.so.18.1.0
7fbe51a0d000-7fbe51a10000 r-xp 00000000 08:02 895903                     /lib/libcom_err.so.2.1
7fbe51a10000-7fbe51c0f000 ---p 00003000 08:02 895903                     /lib/libcom_err.so.2.1
7fbe51c0f000-7fbe51c10000 rw-p 00002000 08:02 895903                     /lib/libcom_err.so.2.1
7fbe51c10000-7fbe51c95000 r-xp 00000000 08:02 428664                     /usr/lib/libasn1.so.8.0.0
7fbe51c95000-7fbe51e94000 ---p 00085000 08:02 428664                     /usr/lib/libasn1.so.8.0.0
7fbe51e94000-7fbe51e99000 rw-p 00084000 08:02 428664                     /usr/lib/libasn1.so.8.0.0
7fbe51e99000-7fbe51eb4000 r-xp 00000000 08:02 428693                     /usr/lib/libhdb.so.9.2.0
7fbe51eb4000-7fbe520b4000 ---p 0001b000 08:02 428693                     /usr/lib/libhdb.so.9.2.0
7fbe520b4000-7fbe520b6000 rw-p 0001b000 08:02 428693                     /usr/lib/libhdb.so.9.2.0
7fbe520b6000-7fbe520bf000 r-xp 00000000 08:02 428675                     /usr/lib/libkadm5clnt.so.7.0.1
7fbe520bf000-7fbe522bf000 ---p 00009000 08:02 428675                     /usr/lib/libkadm5clnt.so.7.0.1
7fbe522bf000-7fbe522c0000 rw-p 00009000 08:02 428675                     /usr/lib/libkadm5clnt.so.7.0.1
7fbe522c0000-7fbe52390000 r-xp 00000000 08:02 428671                     /usr/lib/libkrb5.so.25.0.0
7fbe52390000-7fbe52590000 ---p 000d0000 08:02 428671                     /usr/lib/libkrb5.so.25.0.0
7fbe52590000-7fbe52596000 rw-p 000d0000 08:02 428671                     /usr/lib/libkrb5.so.25.0.0
7fbe52596000-7fbe52597000 rw-p 00000000 00:00 0 
7fbe52597000-7fbe525a6000 r-xp 00000000 08:02 428771                     /usr/lib/python2.4/site-packages/heimdal.so
7fbe525a6000-7fbe527a5000 ---p 0000f000 08:02 428771                     /usr/lib/python2.4/site-packages/heimdal.so
7fbe527a5000-7fbe527a7000 rw-p 0000e000 08:02 428771                     /usr/lib/python2.4/site-packages/heimdal.so
7fbe527a7000-7fbe527d6000 r-xp 00000000 08:02 490131                     /usr/lib/python2.4/site-packages/_xmlplus/parsers/pyexpat.so
7fbe527d6000-7fbe529d6000 ---p 0002f000 08:02 490131                     /usr/lib/python2.4/site-packages/_xmlplus/parsers/pyexpat.so
7fbe529d6000-7fbe529da000 rw-p 0002f000 08:02 490131                     /usr/lib/python2.4/site-packages/_xmlplus/parsers/pyexpat.so
7fbe529da000-7fbe52a1b000 rw-p 00000000 00:00 0 
7fbe52a1b000-7fbe52a2c000 r-xp 00000000 08:02 448962                     /usr/lib/python2.4/lib-dynload/datetime.so
7fbe52a2c000-7fbe52c2b000 ---p 00011000 08:02 448962                     /usr/lib/python2.4/lib-dynload/datetime.so
7fbe52c2b000-7fbe52c2f000 rw-p 00010000 08:02 448962                     /usr/lib/python2.4/lib-dynload/datetime.so
7fbe52c2f000-7fbe52c31000 r-xp 00000000 08:02 448958                     /usr/lib/python2.4/lib-dynload/_bisect.so
7fbe52c31000-7fbe52e30000 ---p 00002000 08:02 448958                     /usr/lib/python2.4/lib-dynload/_bisect.so
7fbe52e30000-7fbe52e31000 rw-p 00001000 08:02 448958                     /usr/lib/python2.4/lib-dynload/_bisect.so
7fbe52e31000-7fbe52eb3000 rw-p 00000000 00:00 0 
7fbe52eb3000-7fbe52eb4000 r-xp 00000000 08:02 448982                     /usr/lib/python2.4/lib-dynload/_weakref.so
7fbe52eb4000-7fbe530b4000 ---p 00001000 08:02 448982                     /usr/lib/python2.4/lib-dynload/_weakref.so
7fbe530b4000-7fbe530b5000 rw-p 00001000 08:02 448982                     /usr/lib/python2.4/lib-dynload/_weakref.so
7fbe530b5000-7fbe53137000 rw-p 00000000 00:00 0 
7fbe53137000-7fbe53193000 r-xp 00000000 08:02 472803                     /usr/lib/python-support/python-m2crypto/python2.4/M2Crypto/__m2crypto.so
7fbe53193000-7fbe53392000 ---p 0005c000 08:02 472803                     /usr/lib/python-support/python-m2crypto/python2.4/M2Crypto/__m2crypto.so
7fbe53392000-7fbe5339b000 rw-p 0005b000 08:02 472803                     /usr/lib/python-support/python-m2crypto/python2.4/M2Crypto/__m2crypto.so
7fbe5339b000-7fbe5339e000 r-xp 00000000 08:02 448852                     /usr/lib/python2.4/lib-dynload/_random.so
7fbe5339e000-7fbe5359d000 ---p 00003000 08:02 448852                     /usr/lib/python2.4/lib-dynload/_random.so
7fbe5359d000-7fbe5359e000 rw-p 00002000 08:02 448852                     /usr/lib/python2.4/lib-dynload/_random.so
7fbe5359e000-7fbe535a1000 r-xp 00000000 08:02 448860                     /usr/lib/python2.4/lib-dynload/md5.so
7fbe535a1000-7fbe537a0000 ---p 00003000 08:02 448860                     /usr/lib/python2.4/lib-dynload/md5.so
7fbe537a0000-7fbe537a1000 rw-p 00002000 08:02 448860                     /usr/lib/python2.4/lib-dynload/md5.so
7fbe537a1000-7fbe537a4000 r-xp 00000000 08:02 448855                     /usr/lib/python2.4/lib-dynload/sha.so
7fbe537a4000-7fbe539a3000 ---p 00003000 08:02 448855                     /usr/lib/python2.4/lib-dynload/sha.so
7fbe539a3000-7fbe539a4000 rw-p 00002000 08:02 448855                     /usr/lib/python2.4/lib-dynload/sha.so
7fbe539a4000-7fbe53a67000 rw-p 00000000 00:00 0 
7fbe53a67000-7fbe53a6c000 r-xp 00000000 08:02 448847                     /usr/lib/python2.4/lib-dynload/operator.so
7fbe53a6c000-7fbe53c6c000 ---p 00005000 08:02 448847                     /usr/lib/python2.4/lib-dynload/operator.so
7fbe53c6c000-7fbe53c6e000 rw-p 00005000 08:02 448847                     /usr/lib/python2.4/lib-dynload/operator.so
7fbe53c6e000-7fbe53caf000 rw-p 00000000 00:00 0 
7fbe53caf000-7fbe53cb1000 r-xp 00000000 08:02 427960                     /usr/lib/libuniventiondebug.so.0.0.1
7fbe53cb1000-7fbe53eb0000 ---p 00002000 08:02 427960                     /usr/lib/libuniventiondebug.so.0.0.1
7fbe53eb0000-7fbe53eb1000 rw-p 00001000 08:02 427960                     /usr/lib/libuniventiondebug.so.0.0.1
7fbe53eb1000-7fbe53eb3000 r-xp 00000000 08:02 449309                     /usr/lib/python2.4/site-packages/univention/_debug.so
7fbe53eb3000-7fbe540b2000 ---p 00002000 08:02 449309                     /usr/lib/python2.4/site-packages/univention/_debug.so
7fbe540b2000-7fbe540b3000 rw-p 00001000 08:02 449309                     /usr/lib/python2.4/site-packages/univention/_debug.so
7fbe540b3000-7fbe540f4000 rw-p 00000000 00:00 0 
7fbe540f4000-7fbe54101000 r-xp 00000000 08:02 427943                     /usr/lib/liblber-2.4.so.2.5.6
7fbe54101000-7fbe54301000 ---p 0000d000 08:02 427943                     /usr/lib/liblber-2.4.so.2.5.6
7fbe54301000-7fbe54302000 rw-p 0000d000 08:02 427943                     /usr/lib/liblber-2.4.so.2.5.6
7fbe54302000-7fbe5434b000 r-xp 00000000 08:02 427944                     /usr/lib/libldap_r-2.4.so.2.5.6
7fbe5434b000-7fbe5454b000 ---p 00049000 08:02 427944                     /usr/lib/libldap_r-2.4.so.2.5.6
7fbe5454b000-7fbe5454e000 rw-p 00049000 08:02 427944                     /usr/lib/libldap_r-2.4.so.2.5.6
7fbe5454e000-7fbe54550000 rw-p 00000000 00:00 0 
7fbe54550000-7fbe5455e000 r-xp 00000000 08:02 427957                     /usr/lib/python2.4/site-packages/_ldap.so
7fbe5455e000-7fbe5475d000 ---p 0000e000 08:02 427957                     /usr/lib/python2.4/site-packages/_ldap.so
7fbe5475d000-7fbe5475f000 rw-p 0000d000 08:02 427957                     /usr/lib/python2.4/site-packages/_ldap.so
7fbe5475f000-7fbe54761000 r-xp 00000000 08:02 448856                     /usr/lib/python2.4/lib-dynload/grp.so
7fbe54761000-7fbe54960000 ---p 00002000 08:02 448856                     /usr/lib/python2.4/lib-dynload/grp.so
7fbe54960000-7fbe54961000 rw-p 00001000 08:02 448856                     /usr/lib/python2.4/lib-dynload/grp.so
7fbe54961000-7fbe54966000 r-xp 00000000 08:02 448853                     /usr/lib/python2.4/lib-dynload/binascii.so
7fbe54966000-7fbe54b65000 ---p 00005000 08:02 448853                     /usr/lib/python2.4/lib-dynload/binascii.so
7fbe54b65000-7fbe54b66000 rw-p 00004000 08:02 448853                     /usr/lib/python2.4/lib-dynload/binascii.so
7fbe54b66000-7fbe54b69000 r-xp 00000000 08:02 448859                     /usr/lib/python2.4/lib-dynload/fcntl.so
7fbe54b69000-7fbe54d68000 ---p 00003000 08:02 448859                     /usr/lib/python2.4/lib-dynload/fcntl.so
7fbe54d68000-7fbe54d6a000 rw-p 00002000 08:02 448859                     /usr/lib/python2.4/lib-dynload/fcntl.so
7fbe54d6a000-7fbe54dab000 rw-p 00000000 00:00 0 
7fbe54dab000-7fbe54dae000 r-xp 00000000 08:02 448857                     /usr/lib/python2.4/lib-dynload/math.so
7fbe54dae000-7fbe54fae000 ---p 00003000 08:02 448857                     /usr/lib/python2.4/lib-dynload/math.so
7fbe54fae000-7fbe54faf000 rw-p 00003000 08:02 448857                     /usr/lib/python2.4/lib-dynload/math.so
7fbe54faf000-7fbe54ff0000 rw-p 00000000 00:00 0 
7fbe54ff0000-7fbe54ff3000 r-xp 00000000 08:02 448850                     /usr/lib/python2.4/lib-dynload/select.so
7fbe54ff3000-7fbe551f3000 ---p 00003000 08:02 448850                     /usr/lib/python2.4/lib-dynload/select.so
7fbe551f3000-7fbe551f4000 rw-p 00003000 08:02 448850                     /usr/lib/python2.4/lib-dynload/select.so
7fbe551f4000-7fbe551f6000 r-xp 00000000 08:02 448970                     /usr/lib/python2.4/lib-dynload/resource.so
7fbe551f6000-7fbe553f6000 ---p 00002000 08:02 448970                     /usr/lib/python2.4/lib-dynload/resource.so
7fbe553f6000-7fbe553f7000 rw-p 00002000 08:02 448970                     /usr/lib/python2.4/lib-dynload/resource.so
7fbe553f7000-7fbe55549000 r-xp 00000000 08:02 428516                     /usr/lib/libxml2.so.2.6.32
7fbe55549000-7fbe55748000 ---p 00152000 08:02 428516                     /usr/lib/libxml2.so.2.6.32
7fbe55748000-7fbe55752000 rw-p 00151000 08:02 428516                     /usr/lib/libxml2.so.2.6.32
7fbe55752000-7fbe55753000 rw-p 00000000 00:00 0 
7fbe55753000-7fbe55758000 r-xp 00000000 08:02 428721                     /usr/lib/libxenstore.so.3.0.0
7fbe55758000-7fbe55957000 ---p 00005000 08:02 428721                     /usr/lib/libxenstore.so.3.0.0
7fbe55957000-7fbe55958000 rw-p 00004000 08:02 428721                     /usr/lib/libxenstore.so.3.0.0
7fbe55958000-7fbe5595b000 rw-p 00000000 00:00 0 
7fbe5595b000-7fbe5596b000 r-xp 00000000 08:02 895872                     /lib/libresolv-2.7.so (deleted)
7fbe5596b000-7fbe55b6b000 ---p 00010000 08:02 895872                     /lib/libresolv-2.7.so (deleted)
7fbe55b6b000-7fbe55b6d000 rw-p 00010000 08:02 895872                     /lib/libresolv-2.7.so (deleted)
7fbe55b6d000-7fbe55b6f000 rw-p 00000000 00:00 0 
7fbe55b6f000-7fbe55b88000 r-xp 00000000 08:02 426369                     /usr/lib/libsasl2.so.2.0.22
7fbe55b88000-7fbe55d88000 ---p 00019000 08:02 426369                     /usr/lib/libsasl2.so.2.0.22
7fbe55d88000-7fbe55d89000 rw-p 00019000 08:02 426369                     /usr/lib/libsasl2.so.2.0.22
7fbe55d89000-7fbe55d8c000 r-xp 00000000 08:02 426253                     /usr/lib/libgpg-error.so.0.3.0
7fbe55d8c000-7fbe55f8b000 ---p 00003000 08:02 426253                     /usr/lib/libgpg-error.so.0.3.0
7fbe55f8b000-7fbe55f8c000 rw-p 00002000 08:02 426253                     /usr/lib/libgpg-error.so.0.3.0
7fbe55f8c000-7fbe55ff0000 r-xp 00000000 08:02 426233                     /usr/lib/libgcrypt.so.11.4.4
7fbe55ff0000-7fbe561f0000 ---p 00064000 08:02 426233                     /usr/lib/libgcrypt.so.11.4.4
7fbe561f0000-7fbe561f3000 rw-p 00064000 08:02 426233                     /usr/lib/libgcrypt.so.11.4.4
7fbe561f3000-7fbe56203000 r-xp 00000000 08:02 426379                     /usr/lib/libtasn1.so.3.0.15
7fbe56203000-7fbe56402000 ---p 00010000 08:02 426379                     /usr/lib/libtasn1.so.3.0.15
7fbe56402000-7fbe56403000 rw-p 0000f000 08:02 426379                     /usr/lib/libtasn1.so.3.0.15
7fbe56403000-7fbe564aa000 r-xp 00000000 08:02 426239                     /usr/lib/libgnutls.so.26.4.6
7fbe564aa000-7fbe566aa000 ---p 000a7000 08:02 426239                     /usr/lib/libgnutls.so.26.4.6
7fbe566aa000-7fbe566b5000 rw-p 000a7000 08:02 426239                     /usr/lib/libgnutls.so.26.4.6
7fbe566b5000-7fbe567bb000 r-xp 00000000 08:02 429665                     /usr/lib/libvirt.so.0.8.3
7fbe567bb000-7fbe569ba000 ---p 00106000 08:02 429665                     /usr/lib/libvirt.so.0.8.3
7fbe569ba000-7fbe569c3000 rw-p 00105000 08:02 429665                     /usr/lib/libvirt.so.0.8.3
7fbe569c3000-7fbe569d3000 rw-p 00000000 00:00 0 
7fbe569d3000-7fbe569f3000 r-xp 00000000 08:02 430782                     /usr/lib/python2.4/site-packages/libvirtmod.so
7fbe569f3000-7fbe56bf3000 ---p 00020000 08:02 430782                     /usr/lib/python2.4/site-packages/libvirtmod.so
7fbe56bf3000-7fbe56bf6000 rw-p 00020000 08:02 430782                     /usr/lib/python2.4/site-packages/libvirtmod.so
7fbe56bf6000-7fbe56cf8000 rw-p 00000000 00:00 0 
7fbe56cf8000-7fbe56cfd000 r-xp 00000000 08:02 448851                     /usr/lib/python2.4/lib-dynload/struct.so
7fbe56cfd000-7fbe56efc000 ---p 00005000 08:02 448851                     /usr/lib/python2.4/lib-dynload/struct.so
7fbe56efc000-7fbe56efe000 rw-p 00004000 08:02 448851                     /usr/lib/python2.4/lib-dynload/struct.so
7fbe56efe000-7fbe56f11000 r-xp 00000000 08:02 448983                     /usr/lib/python2.4/lib-dynload/cPickle.so
7fbe56f11000-7fbe57110000 ---p 00013000 08:02 448983                     /usr/lib/python2.4/lib-dynload/cPickle.so
7fbe57110000-7fbe57112000 rw-p 00012000 08:02 448983                     /usr/lib/python2.4/lib-dynload/cPickle.so
7fbe57112000-7fbe57129000 r-xp 00000000 08:02 425555                     /usr/lib/libz.so.1.2.3.3
7fbe57129000-7fbe57328000 ---p 00017000 08:02 425555                     /usr/lib/libz.so.1.2.3.3
7fbe57328000-7fbe57329000 rw-p 00016000 08:02 425555                     /usr/lib/libz.so.1.2.3.3
7fbe57329000-7fbe5749b000 r-xp 00000000 08:02 424247                     /usr/lib/libcrypto.so.0.9.8
7fbe5749b000-7fbe5769a000 ---p 00172000 08:02 424247                     /usr/lib/libcrypto.so.0.9.8
7fbe5769a000-7fbe576c0000 rw-p 00171000 08:02 424247                     /usr/lib/libcrypto.so.0.9.8
7fbe576c0000-7fbe576c4000 rw-p 00000000 00:00 0 
7fbe576c4000-7fbe5770e000 r-xp 00000000 08:02 424246                     /usr/lib/libssl.so.0.9.8
7fbe5770e000-7fbe5790e000 ---p 0004a000 08:02 424246                     /usr/lib/libssl.so.0.9.8
7fbe5790e000-7fbe57915000 rw-p 0004a000 08:02 424246                     /usr/lib/libssl.so.0.9.8
7fbe57915000-7fbe57919000 r-xp 00000000 08:02 448989                     /usr/lib/python2.4/lib-dynload/_ssl.so
7fbe57919000-7fbe57b18000 ---p 00004000 08:02 448989                     /usr/lib/python2.4/lib-dynload/_ssl.so
7fbe57b18000-7fbe57b19000 rw-p 00003000 08:02 448989                     /usr/lib/python2.4/lib-dynload/_ssl.so
7fbe57b19000-7fbe57b24000 r-xp 00000000 08:02 448844                     /usr/lib/python2.4/lib-dynload/_socket.so
7fbe57b24000-7fbe57d23000 ---p 0000b000 08:02 448844                     /usr/lib/python2.4/lib-dynload/_socket.so
7fbe57d23000-7fbe57d27000 rw-p 0000a000 08:02 448844                     /usr/lib/python2.4/lib-dynload/_socket.so
7fbe57d27000-7fbe57d2b000 r-xp 00000000 08:02 448986                     /usr/lib/python2.4/lib-dynload/collections.so
7fbe57d2b000-7fbe57f2b000 ---p 00004000 08:02 448986                     /usr/lib/python2.4/lib-dynload/collections.so
7fbe57f2b000-7fbe57f2c000 rw-p 00004000 08:02 448986                     /usr/lib/python2.4/lib-dynload/collections.so
7fbe57f2c000-7fbe57f30000 r-xp 00000000 08:02 448845                     /usr/lib/python2.4/lib-dynload/cStringIO.so
7fbe57f30000-7fbe5812f000 ---p 00004000 08:02 448845                     /usr/lib/python2.4/lib-dynload/cStringIO.so
7fbe5812f000-7fbe58131000 rw-p 00003000 08:02 448845                     /usr/lib/python2.4/lib-dynload/cStringIO.so
7fbe58131000-7fbe58136000 r-xp 00000000 08:02 448861                     /usr/lib/python2.4/lib-dynload/strop.so
7fbe58136000-7fbe58335000 ---p 00005000 08:02 448861                     /usr/lib/python2.4/lib-dynload/strop.so
7fbe58335000-7fbe58337000 rw-p 00004000 08:02 448861                     /usr/lib/python2.4/lib-dynload/strop.so
7fbe58337000-7fbe5833a000 r-xp 00000000 08:02 448848                     /usr/lib/python2.4/lib-dynload/time.so
7fbe5833a000-7fbe5853a000 ---p 00003000 08:02 448848                     /usr/lib/python2.4/lib-dynload/time.so
7fbe5853a000-7fbe5853c000 rw-p 00003000 08:02 448848                     /usr/lib/python2.4/lib-dynload/time.so
7fbe5853c000-7fbe58540000 r-xp 00000000 08:02 448977                     /usr/lib/python2.4/lib-dynload/_locale.so
7fbe58540000-7fbe58740000 ---p 00004000 08:02 448977                     /usr/lib/python2.4/lib-dynload/_locale.so
7fbe58740000-7fbe58741000 rw-p 00004000 08:02 448977                     /usr/lib/python2.4/lib-dynload/_locale.so
7fbe58741000-7fbe5888b000 r-xp 00000000 08:02 895866                     /lib/libc-2.7.so (deleted)
7fbe5888b000-7fbe58a8a000 ---p 0014a000 08:02 895866                     /lib/libc-2.7.so (deleted)
7fbe58a8a000-7fbe58a8d000 r--p 00149000 08:02 895866                     /lib/libc-2.7.so (deleted)
7fbe58a8d000-7fbe58a8f000 rw-p 0014c000 08:02 895866                     /lib/libc-2.7.so (deleted)
7fbe58a8f000-7fbe58a94000 rw-p 00000000 00:00 0 
7fbe58a94000-7fbe58b16000 r-xp 00000000 08:02 895858                     /lib/libm-2.7.so (deleted)
7fbe58b16000-7fbe58d15000 ---p 00082000 08:02 895858                     /lib/libm-2.7.so (deleted)
7fbe58d15000-7fbe58d17000 rw-p 00081000 08:02 895858                     /lib/libm-2.7.so (deleted)
7fbe58d17000-7fbe58d19000 r-xp 00000000 08:02 895882                     /lib/libutil-2.7.so (deleted)
7fbe58d19000-7fbe58f18000 ---p 00002000 08:02 895882                     /lib/libutil-2.7.so (deleted)
7fbe58f18000-7fbe58f1a000 rw-p 00001000 08:02 895882                     /lib/libutil-2.7.so (deleted)
7fbe58f1a000-7fbe58f1c000 r-xp 00000000 08:02 895856                     /lib/libdl-2.7.so (deleted)
7fbe58f1c000-7fbe5911c000 ---p 00002000 08:02 895856                     /lib/libdl-2.7.so (deleted)
7fbe5911c000-7fbe5911e000 rw-p 00002000 08:02 895856                     /lib/libdl-2.7.so (deleted)
7fbe5911e000-7fbe59134000 r-xp 00000000 08:02 895869                     /lib/libpthread-2.7.so (deleted)
7fbe59134000-7fbe59334000 ---p 00016000 08:02 895869                     /lib/libpthread-2.7.so (deleted)
7fbe59334000-7fbe59336000 rw-p 00016000 08:02 895869                     /lib/libpthread-2.7.so (deleted)
7fbe59336000-7fbe5933a000 rw-p 00000000 00:00 0 
7fbe5933a000-7fbe59356000 r-xp 00000000 08:02 895877                     /lib/ld-2.7.so (deleted)
7fbe59392000-7fbe59496000 rw-p 00000000 00:00 0 
7fbe594c7000-7fbe5954c000 rw-p 00000000 00:00 0 
7fbe59550000-7fbe59555000 rw-p 00000000 00:00 0 
7fbe59555000-7fbe59557000 rw-p 0001b000 08:02 895877                     /lib/ld-2.7.so (deleted)

Die (deleted) deuten darauf hin, daß in de Zwischenzeit Pakete aktualisiert wurden und daß der Prozeß noch die alte Version der Bibliotheken geöffnet hat. Das halte ich hier für weniger relevant.
Comment 7 Janis Meybohm univentionstaff 2010-12-20 09:58:08 CET
Created attachment 2936 [details]
uvmmd backtrace von skubb #2

(In reply to comment #4)
Das Problem des nicht mehr reagierenden UVMMd haben wir gerade wieder auf skubb. Gleiches Symptom wie in comment #4 - uvmm add blockiert den Listener.
Comment 8 Philipp Hahn univentionstaff 2011-01-25 12:47:23 CET
Ein ähnliches Problem trat heute auch auf xen[234] auf.
(gdb) bt
#2  0x00007f802240f4aa in pthread_mutex_lock () from /lib/libpthread.so.0
#3  0x00007f801f8ec261 in remoteDomainEventQueueFlush (timer=<value optimized out>, opaque=0x3868170) at /tmp/buildd/libvirt-0.8.3/src/remote/remote_driver.c:211
#4  0x00007f801fb8e668 in libvirt_virEventInvokeTimeoutCallback (self=<value optimized out>, args=<value optimized out>)
    at /tmp/buildd/libvirt-0.8.3/python/libvirt-override.c:2970
#5  0x000000000047d914 in PyEval_EvalFrame (f=0x2921a70) at ../Python/ceval.c:3568
#6  0x000000000047de47 in PyEval_EvalFrame (f=0x291e640) at ../Python/ceval.c:3651
#7  0x000000000047de47 in PyEval_EvalFrame (f=0x29226e0) at ../Python/ceval.c:3651
#8  0x000000000047de47 in PyEval_EvalFrame (f=0x2613f80) at ../Python/ceval.c:3651
#9  0x000000000047de47 in PyEval_EvalFrame (f=0x2613cb0) at ../Python/ceval.c:3651
#10 0x000000000047e7c5 in PyEval_EvalCodeEx (co=0x7f801fe7c8f0, globals=<value optimized out>, locals=<value optimized out>, args=0x7f80227e8068, argcount=0, kws=0x26f49b0, 
    kwcount=0, defs=0x0, defcount=0, closure=0x0) at ../Python/ceval.c:2741
#11 0x00000000004ca5b6 in function_call (func=0x7f801fe7fde8, arg=0x7f80227e8050, kw=0x263a670) at ../Objects/funcobject.c:548
#12 0x0000000000416000 in PyObject_Call (func=0x0, arg=0x3868170, kw=0x706560) at ../Objects/abstract.c:1795
#13 0x000000000047b7e0 in PyEval_EvalFrame (f=0x26532c0) at ../Python/ceval.c:3845
#14 0x000000000047de47 in PyEval_EvalFrame (f=0x2616210) at ../Python/ceval.c:3651
#15 0x000000000047e7c5 in PyEval_EvalCodeEx (co=0x7f802276ce30, globals=<value optimized out>, locals=<value optimized out>, args=0x7f801fe7d6a8, argcount=1, kws=0x0, kwcount=0, 
    defs=0x0, defcount=0, closure=0x0) at ../Python/ceval.c:2741
#16 0x00000000004ca4d7 in function_call (func=0x7f80227021b8, arg=0x7f801fe7d690, kw=0x0) at ../Objects/funcobject.c:548
#17 0x0000000000416000 in PyObject_Call (func=0x0, arg=0x3868170, kw=0x706560) at ../Objects/abstract.c:1795
#18 0x000000000041c5e7 in instancemethod_call (func=0x7f80227021b8, arg=0x7f801fe7d690, kw=0x0) at ../Objects/classobject.c:2532
#19 0x0000000000416000 in PyObject_Call (func=0x0, arg=0x3868170, kw=0x706560) at ../Objects/abstract.c:1795
#20 0x0000000000477871 in PyEval_CallObjectWithKeywords (func=0x7f80227436e0, arg=0x7f80227e8050, kw=0x0) at ../Python/ceval.c:3435
#21 0x00000000004ad37d in t_bootstrap (boot_raw=0x26f9820) at ../Modules/threadmodule.c:434
#22 0x00007f802240dfc7 in start_thread () from /lib/libpthread.so.0
#23 0x00007f8021af959d in clone () from /lib/libc.so.6
#24 0x0000000000000000 in ?? ()

Verdächtig ist auch hier wieder, das libvirt auf ein Semaphore wartet. Es scheint, als ob es Probleme mit der Verbindung zu einem remote-libvirtd gibt.

#5 libvirt.py:150 eventInvokeTimeoutCallback()
#6 univention/uvmm/eventloop.py:104 virEventLoopPure.virEventLoopPureHandle.dispatch()
#7 univention/uvmm/eventloop.py:171 run_once()
#8 univention/uvmm/eventloop.py:240 run_loop()
#9 univention/uvmm/eventloop.py:412 virEventLoopPureRun()
#13 threading.py:420 Thread.run()

> (gdb)
print *((virConnectPtr)opaque)
$16 = {magic = 0, flags = 0, uri = 0x0, driver = 0x0, networkDriver = 0x0, interfaceDriver = 0x0, storageDriver = 0x0, deviceMonitor = 0x0, secretDriver = 0x0, 
  nwfilterDriver = 0x0, privateData = 0x0, networkPrivateData = 0x0, interfacePrivateData = 0x0, storagePrivateData = 0x0, devMonPrivateData = 0x0, secretPrivateData = 0x0, 
  nwfilterPrivateData = 0x0, lock = {lock = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, 
      __size = '\0' <repeats 39 times>, __align = 0}}, err = {code = 0, domain = 0, message = 0x0, level = VIR_ERR_NONE, conn = 0x0, dom = 0x0, str1 = 0x0, 
    str2 = 0x859dcc80324489dc <Address 0x859dcc80324489dc out of bounds>, str3 = 0x7f8022807e40 "\001\030", int1 = 58119680, int2 = 0, net = 0x0}, handler = 0, userData = 0x0, 
  domains = 0x0, networks = 0x0, interfaces = 0x0, storagePools = 0xb2adf335f9c0e38c, storageVols = 0x7f801fe9c298, nodeDevices = 0x36e6ea8, secrets = 0x0, nwfilterPools = 0x0, 
  refs = 0}
> (gdb) print ((virConnectPtr)opaque)->privateData
$17 = (void *) 0x0

Das dürfte nicht NULL sein!?!


Notizen zum Debuggen:
1. Ggf. per "gdb -p $(</var/run/uvmmd.pid) ... gcore" einen core-Dump erzeugt
2. Nächstes mal auch ein "lsof -p $(</var/run/uvmmd.pid)" nicht vergessen
3. apt-get install python2.4-dbg
4. <http://www.python.org/~jeremy/weblog/031003.html> beschreibt, wie man per gdb an einige nützliche Informationen herankommt:

> (gdb) dir /usr/src/python2.4-2.4.6/build-shared
> (gdb) p f->f_lineno
> $18 = 345
> (gdb) x/s ((PyStringObject*)f->f_code->co_filename)->ob_sval
> 0x7f8018f54d14:  "/usr/lib/python2.4/site-packages/univention/uvmm/unix.py"

Der Python-Code ist in univention/uvmm/unix.py:345

(gdb) print tvp
$5 = (struct timeval *) 0x0

Der Timeout ist 0, also wird unendlich lange gewartet.

(gdb) print /x &ifdset
$10 = 0x7fff8f55d310
(gdb) x /4xb 0x7fff8f55d310
0x7fff8f55d310: 0x00    0x03    0x00    0x00

Gewartet wird darauf, das File-Deskriptoren 8 und 9 lesbar werden. Leider fehlt hier jetzt die genaue Information von "lsof", aber vermutlich sind das der UNIX- und der TCP-socket:

# lsof -p $(</var/run/uvmmd.pid) | awk '$4 ~ "^[89]u" { print $0 }'
univentio 10222 root    8u  unix 0xffff88001d909200         6050470 /var/run/uvmm.socket
univentio 10222 root    9u  IPv4            6050472             TCP *:2106 (LISTEN)
Comment 9 Janis Meybohm univentionstaff 2011-02-09 14:03:01 CET
Das passiert mir recht häufig aus samla, skubb und laiva. Ein Kunde hat eben auch noch einmal deswegen angerufen. Ich setze mal P1 da man immer manuell eingreifen muss um den Prozess ggf. mit kill -9 zu beenden falls das init-Script dass nicht tut.
Comment 10 Janis Meybohm univentionstaff 2011-02-09 14:17:07 CET
(In reply to comment #9)
> Ein Kunde hat eben auch noch einmal deswegen angerufen. 
Ticket: #2011020910001261
Comment 11 Janis Meybohm univentionstaff 2011-02-22 12:10:12 CET
Created attachment 3063 [details]
lsof & gdb von samla 20110222-120835

Output nach:
https://hutten.knut.univention.de/mediawiki/index.php/Philipp_memo/debug#UVMMd_h.C3.A4ngt
von samla
Comment 12 Philipp Hahn univentionstaff 2011-02-28 11:43:44 CET
*** Bug 21661 has been marked as a duplicate of this bug. ***
Comment 13 Philipp Hahn univentionstaff 2011-03-08 07:26:07 CET
Auf der libvirt-ML ist ein Patch gepostet worden, der ein Problem löst, das IMHO große Ähnlichkeit mit dem hier beobachteten Problem hat: <http://www.redhat.com/archives/libvir-list/2011-March/msg00245.html>
Vermutlich kommt es zu einem Deadlock zwischen dem Event-Thread (eventLoop.lock) und einem anderen Thread (uvmm add), der einen weiteren Rechner dem UVMMd zur Überwachung hinzufügt (remoteDriver.remote ?).
Bevor ich den Patch aber einspiele, würde ich beim nächsten Hänger gerne erst nochmal verifizieren, daß der Patch der richtige für das bei uns auftretende Problem ist.
Comment 14 Philipp Hahn univentionstaff 2011-03-09 20:19:42 CET
Der Patch wurde jetzt testweise in libvirt eingebaut (svn8941, libvirt_0.8.7-1.53.201103091054). Ob er die Sache verbessert, muß sich noch zeigen.

Allerdings habe ich jetzt auf mehreren Servern das ursprüngliche Problem beobachtet, daß UVMM nicht mehr antwortet oder nur noch veraltete Daten ausgibt.
Das hat vermutlich nichts mit dem Patch zu tun, weil ich die gleichen Beobachtungen auch auf einem Server gemacht habe, wo noch die alte Version von libvirt (=ohne Patch) installiert war.

Ein "gdb -p $PID -ex 'thread apply all bt'" auf libvirtd zeigt folgende Auffälligkeit:

Thread 3 (Thread 0x4097b950 (LWP 4526)):
#0  0x00007f4cf98c7d29 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#1  0x00007f4cfb823216 in virCondWait (c=0x1d8aaec, m=0x80) at /tmp/buildd/libvirt-0.8.7/src/util/threads-pthread.c:108
#2  0x0000000000467b3e in qemuMonitorSend (mon=0x1d8aac0, msg=<value optimized out>) at /tmp/buildd/libvirt-0.8.7/src/qemu/qemu_monitor.c:728
#3  0x0000000000469c06 in qemuMonitorCommandWithHandler (mon=0x1d8aac0, cmd=0x4b2ab6 "info balloon", passwordHandler=0, passwordOpaque=0x0, scm_fd=-1, reply=0x4097ad00)
    at /tmp/buildd/libvirt-0.8.7/src/qemu/qemu_monitor_text.c:233
#4  0x000000000046d3f3 in qemuMonitorTextGetBalloonInfo (mon=0x1d8aaec, currmem=0x4097ad68) at /tmp/buildd/libvirt-0.8.7/src/qemu/qemu_monitor_text.c:553
#5  0x0000000000445229 in qemudDomainGetInfo (dom=<value optimized out>, info=0x4097add0) at /tmp/buildd/libvirt-0.8.7/src/qemu/qemu_driver.c:4000
#6  0x00007f4cfb87380e in virDomainGetInfo (domain=0x1cf8c80, info=0x4097add0) at /tmp/buildd/libvirt-0.8.7/src/libvirt.c:3190
#7  0x0000000000428d75 in remoteDispatchDomainGetInfo (server=<value optimized out>, client=<value optimized out>, conn=0x1d42b90, hdr=<value optimized out>, rerr=0x4097af50,
    args=<value optimized out>, ret=0x4097aea0) at /tmp/buildd/libvirt-0.8.7/daemon/remote.c:1503
#8  0x000000000042b754 in remoteDispatchClientRequest (server=0x1cfb710, client=0x7f4cf010de80, msg=0x7f4cf014e110) at /tmp/buildd/libvirt-0.8.7/daemon/dispatch.c:530
#9  0x000000000041c3b3 in qemudWorker (data=<value optimized out>) at /tmp/buildd/libvirt-0.8.7/daemon/libvirtd.c:1588
#10 0x00007f4cf98c3fc7 in start_thread () from /lib/libpthread.so.0
#11 0x00007f4cf963964d in clone () from /lib/libc.so.6
#12 0x0000000000000000 in ?? ()

Hier hat der libvirtd ein Kommando an den KVM-Prozeß geschickt und wartet nun auf dessen Rückantwort. Dazu blockiert er sich an einer Condition-Variable und wartet darauf, daß der andere Thread™ die Verfügbarkeit von Daten per select() bzw. poll() feststellt, und ihn dann aufweckt.

(gdb) bt
#0  0x00007f4cf9630bd6 in poll () from /lib/libc.so.6
#1  0x0000000000418048 in virEventRunOnce () at /tmp/buildd/libvirt-0.8.7/daemon/event.c:589
#2  0x000000000041a9e6 in qemudOneLoop () at /tmp/buildd/libvirt-0.8.7/daemon/libvirtd.c:2244
#3  0x000000000041aeba in qemudRunLoop (opaque=<value optimized out>) at /tmp/buildd/libvirt-0.8.7/daemon/libvirtd.c:2354
#4  0x00007f4cf98c3fc7 in start_thread () from /lib/libpthread.so.0
#5  0x00007f4cf963964d in clone () from /lib/libc.so.6
#6  0x0000000000000000 in ?? ()
(gdb) print *fds@nfds
$10 = {{fd = 3, events = 1, revents = 0}, {fd = 5, events = 1, revents = 0}, {fd = 12, events = 1, revents = 0}, {fd = 14, events = 1, revents = 0}, {fd = 11, events = 25, 
    revents = 0}, {fd = 10, events = 25, revents = 0}, {fd = 8, events = 25, revents = 0}, {fd = 7, events = 25, revents = 0}, {fd = 15, events = 1, revents = 0}, {fd = 20, 
    events = 25, revents = 0}, {fd = 25, events = 25, revents = 0}, {fd = 24, events = 25, revents = 0}}


Schaut man sich den zugehörigen KVM-Prozeß an, so stellt man fest, das dieser in einem "kaputten" Zustand ist:
(gdb) thread apply all bt
Thread 2 (Thread 0x41d1c950 (LWP 9568)):
#0  0x00007feb2f0db2e7 in ioctl () from /lib/libc.so.6
#1  0x0000000000428709 in kvm_run (env=0x2be3a70) at /tmp/buildd/qemu-kvm-0.12.4+dfsg/qemu-kvm.c:921
#2  0x0000000000428b49 in kvm_cpu_exec (env=0xa) at /tmp/buildd/qemu-kvm-0.12.4+dfsg/qemu-kvm.c:1651
#3  0x0000000000428d7d in ap_main_loop (_env=<value optimized out>) at /tmp/buildd/qemu-kvm-0.12.4+dfsg/qemu-kvm.c:1893
#4  0x00007feb31a8cfc7 in start_thread () from /lib/libpthread.so.0
#5  0x00007feb2f0e264d in clone () from /lib/libc.so.6
#6  0x0000000000000000 in ?? ()

Thread 1 (Thread 0x7feb320a2760 (LWP 9561)):
#0  0x00007feb31a90d29 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#1  0x0000000000425d66 in pause_all_threads () at /tmp/buildd/qemu-kvm-0.12.4+dfsg/qemu-kvm.c:1445
#2  0x0000000000425f35 in kvm_main_loop () at /tmp/buildd/qemu-kvm-0.12.4+dfsg/qemu-kvm.c:2143
#3  0x000000000040f4bf in main (argc=44, argv=0x7fff654ecc18, envp=<value optimized out>) at /tmp/buildd/qemu-kvm-0.12.4+dfsg/vl.c:4212
#0  0x00007feb31a90d29 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0

Thread 2 ist für die Emulation einer VCPU in einer while(True)-Schleife zuständig, während Thread 1 die Main-Loop implementiert. Diese sorgt durch pause_all_threads() eigentlich dafür, daß Thread 2 sich beenden sollte, was dieser aber aus unbekanntem Grund nicht tut und weiterläuft. Deswegen werden hier auch keine Kommandos mehr von libvirt angenommen und das ganze steht faktisch still.

root@xen5:/var/log/univention# grep Sig /proc/9561/task/9568/status 
SigPnd: 0000000000000000
SigBlk: fffffffe7ffbfeef = 
SigIgn: 0000000000001000 = SIGSEGV
SigCgt: 0000002180016043 = SIGTRAP SIGUSR2 SIGPIPE SIGTERM SIGPWR SIGSYS
Comment 15 Philipp Hahn univentionstaff 2011-03-10 10:28:20 CET
(In reply to comment #14)
> Thread 2 ist für die Emulation einer VCPU in einer while(True)-Schleife
> zuständig,

Der Thread hätte in kvm_main_loop_wait() eigentlich prüfen sollen, ob für ihn ein SIG_IPI = SIGRT+4 = 38 vorliegt. Das ist dem Inter-Prozesser-Interrupt von physikalischen SMP-Maschinen nachempfunden und wird dort in Hardware vom APIC bereitgestellt.

> während Thread 1 die Main-Loop implementiert. Diese sorgt durch
> pause_all_threads() eigentlich dafür, daß Thread 2 sich beenden sollte,

Korrektur: nicht beenden (das wäre pthread_cancel()), sondern nur synchronisieren per pthread_kill(*, SIG_IPI). Der Thread 1 wartet anschließend aus ein Acknowledge per pthread_cond.

> was
> dieser aber aus unbekanntem Grund nicht tut und weiterläuft. Deswegen werden
> hier auch keine Kommandos mehr von libvirt angenommen und das ganze steht
> faktisch still.
> 
> root@xen5:/var/log/univention# grep Sig /proc/9561/task/9568/status 

Korrekturen: die symbolischen Bezeichner waren falsch:
> SigBlk: fffffffe7ffbfeef
HUP INT QUIT ILL ABRT BUS FPE USR1 SEGV USR2 PIPE ALRM TERM 16-16 CLD CONT TSTP TTIN TTOU URG XCPU XFSZ VTALRM PROF WINCH POLL PWR SYS RTMIN 35-63 RTMAX
> SigIgn: 0000000000001000
PIPE
> SigCgt: 0000002180016043
HUP INT BUS ALRM TERM CLD 32-33 38-38
Comment 16 Stefan Gohmann univentionstaff 2011-03-17 10:29:02 CET
Gerade nochmal im Kundensetup aufgetreten.

Wir sollten einen cron Job implementieren, der die Ausgabe von uvmm groups prüft. Wenn UVMM normal reagiert, dann sollte innerhalb einer sehr kurzen Zeit eine Ausgabe zurückkehren, wenn UVMM in diesem Zustand ist, kommt der Befehl nicht zurück.

Vorschlag:
- alle 30 Sekunden prüfen
- Auf die Ausgabe von "uvmm groups" sollte 10 Sekunden gewartet werden

Beide Zeiten sollten per UCR konfigurierbar sein. Wenn uvmm groups nicht reagiert, dann sollte eine syslog Meldung ausgegeben werden und der Dienst neu gestartet werden.

Prüfung ob UVMM eigentlich laufen soll geht per sv status:
 sv status /etc/runit/univention-virtual-machine-manager-daemon
Comment 17 Stefan Gohmann univentionstaff 2011-03-17 13:24:34 CET
*** Bug 21702 has been marked as a duplicate of this bug. ***
Comment 18 Stefan Gohmann univentionstaff 2011-03-17 13:38:21 CET
(In reply to comment #16)
> Gerade nochmal im Kundensetup aufgetreten.
> 
> Wir sollten einen cron Job implementieren, der die Ausgabe von uvmm groups
> prüft. Wenn UVMM normal reagiert, dann sollte innerhalb einer sehr kurzen Zeit
> eine Ausgabe zurückkehren, wenn UVMM in diesem Zustand ist, kommt der Befehl
> nicht zurück.
> 
> Vorschlag:
> - alle 30 Sekunden prüfen
> - Auf die Ausgabe von "uvmm groups" sollte 10 Sekunden gewartet werden
> 
> Beide Zeiten sollten per UCR konfigurierbar sein. Wenn uvmm groups nicht
> reagiert, dann sollte eine syslog Meldung ausgegeben werden und der Dienst neu
> gestartet werden.
> 
> Prüfung ob UVMM eigentlich laufen soll geht per sv status:
>  sv status /etc/runit/univention-virtual-machine-manager-daemon

Lösen wir dadurch auch Bug #18579?
Comment 19 Philipp Hahn univentionstaff 2011-12-13 15:11:58 CET
Ähnlich auf utby aufgetreten:

# dpkg-query -W libvirt\* qemu-kvm
libvirt-bin     0.8.7-1.94.201108311055
libvirt0        0.8.7-1.94.201108311055
libvirt0-dbg    0.8.7-1.94.201108311055
qemu-kvm        0.14.1+dfsg-4.12.201108051244

# gdb -ex "thread apply all bt"
Thread 7 (Thread 0x41a38950 (LWP 8520)):
#0  0x00007fdf12af3384 in __lll_lock_wait () from /lib/libpthread.so.0
#1  0x00007fdf12aeebf0 in _L_lock_102 () from /lib/libpthread.so.0
#2  0x00007fdf12aee4fe in pthread_mutex_lock () from /lib/libpthread.so.0
#3  0x00000000004692d9 in qemuMonitorIO (watch=7642, fd=128, events=313485712, opaque=0xffffffffffffffff)
    at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/qemu/qemu_monitor.c:521
#4  0x0000000000418451 in virEventRunOnce () at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/daemon/event.c:468
#5  0x000000000041a986 in qemudOneLoop () at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/daemon/libvirtd.c:2244
#6  0x000000000041ae5a in qemudRunLoop (opaque=<value optimized out>) at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/daemon/libvirtd.c:2354
#7  0x00007fdf12aecfc7 in start_thread () from /lib/libpthread.so.0
#8  0x00007fdf1286264d in clone () from /lib/libc.so.6
#9  0x0000000000000000 in ?? ()

Thread 6 (Thread 0x42239950 (LWP 8521)):
#0  0x00007fdf12af0d29 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#1  0x00007fdf14a4c216 in virCondWait (c=0x7fdf080310ac, m=0x80) at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/util/threads-pthread.c:108
#2  0x000000000046813e in qemuMonitorSend (mon=0x7fdf08031080, msg=<value optimized out>) at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/qemu/qemu_monitor.c:728
#3  0x000000000046a206 in qemuMonitorCommandWithHandler (mon=0x7fdf08031080, cmd=0x4b3620 "info chardev", passwordHandler=0, passwordOpaque=0x0, scm_fd=-1, reply=0x42236600)
    at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/qemu/qemu_monitor_text.c:233
#4  0x000000000046e083 in qemuMonitorTextGetPtyPaths (mon=0x7fdf080310ac, paths=0x7fdf080660e0)
    at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/qemu/qemu_monitor_text.c:1941
#5  0x000000000043759b in qemudStartVMDaemon (conn=0x19202c0, driver=0x1839990, vm=0x7fdf0804b780, migrateFrom=0x0, start_paused=false, stdin_fd=<value optimized out>, 
    stdin_path=0x0, vmop=VIR_VM_OP_CREATE) at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/qemu/qemu_driver.c:1870
#6  0x0000000000447107 in qemudDomainObjStart (conn=0x19202c0, driver=0x1839990, vm=0x7fdf0804b780, start_paused=false)
    at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/qemu/qemu_driver.c:6205
#7  0x00000000004476a4 in qemudDomainStartWithFlags (dom=0x7fdf0802ed20, flags=0) at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/qemu/qemu_driver.c:6251
#8  0x00007fdf14a956ff in virDomainCreate (domain=0x7fdf0802ed20) at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/src/libvirt.c:5066
#9  0x0000000000429514 in remoteDispatchDomainCreate (server=<value optimized out>, client=<value optimized out>, conn=0x19202c0, hdr=<value optimized out>, rerr=0x42238f50, 
    args=<value optimized out>, ret=0x42238ea0) at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/daemon/remote.c:1228
#10 0x000000000042b9d4 in remoteDispatchClientRequest (server=0x17d9330, client=0x19209d0, msg=0x193edc0)
    at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/daemon/dispatch.c:526
#11 0x000000000041c353 in qemudWorker (data=<value optimized out>) at /var/build/temp/tmp.nGIqWwvZny/pbuilder/libvirt-0.8.7/daemon/libvirtd.c:1588
#12 0x00007fdf12aecfc7 in start_thread () from /lib/libpthread.so.0
#13 0x00007fdf1286264d in clone () from /lib/libc.so.6
#14 0x0000000000000000 in ?? ()
Comment 20 Stefan Gohmann univentionstaff 2012-06-14 23:02:07 CEST
Tritt das Problem auch noch mit UCS 3 auf?
Comment 21 Philipp Hahn univentionstaff 2012-06-15 08:26:54 CEST
(In reply to comment #20)
> Tritt das Problem auch noch mit UCS 3 auf?

Ja, in dieser oder einer ähnlichen Form.
Comment 22 Stefan Gohmann univentionstaff 2013-05-23 11:30:38 CEST
Bisher keine weiteren Kunden / Tester Rückmeldungen, falls es erneut auftritt, bitte aktuelle Infos an den Bug schreiben.
Comment 23 Philipp Hahn univentionstaff 2013-06-03 13:50:39 CEST
Heute ihn ähnlicher Form aufgetreten: UVMMd starb den SIGSEGV-Tod: Irgendwo wird virDomainEventCallbackListPurgeMarked() aus der Event-Loop aufgerufen, was zu einem SIGSEGV führt:

#0  0x00007f4be97a8300 in virDomainEventCallbackListPurgeMarked (timer=<value optimized out>, 
    opaque=<value optimized out>)
    at /var/build/temp/tmp.iA6vnKy5jZ/pbuilder/libvirt-0.9.12/./src/conf/domain_event.c:347
347             if (cbList->callbacks[i]->deleted) {
#1  virDomainEventStateFlush (timer=<value optimized out>, opaque=<value optimized out>)
    at /var/build/temp/tmp.iA6vnKy5jZ/pbuilder/libvirt-0.9.12/./src/conf/domain_event.c:1422
#2  virDomainEventTimer (timer=<value optimized out>, opaque=<value optimized out>)
    at /var/build/temp/tmp.iA6vnKy5jZ/pbuilder/libvirt-0.9.12/./src/conf/domain_event.c:637
#3  0x00007f4be9bae263 in libvirt_virEventInvokeTimeoutCallback (self=<value optimized out>, 
    args=<value optimized out>)
    at /var/build/temp/tmp.iA6vnKy5jZ/pbuilder/libvirt-0.9.12/./python/libvirt-override.c:4439
#4  0x00000000004a7d25 in call_function (f=
    Frame 0x2003fe0, for file /usr/lib/python2.6/dist-packages/libvirt.py, line 167, in _eventInvokeTimeoutCallback (timer=5, opaque=<PyCObject at remote 0x1f3b9e0>, opaquecompat=<PyCObject at remote 0x1f3b9e0>, callback=<PyCObject at remote 0x1f3bdf0>), throwflag=<value optimized out>) at ../Python/ceval.c:3750
#5  PyEval_EvalFrameEx (f=
    Frame 0x2003fe0, for file /usr/lib/python2.6/dist-packages/libvirt.py, line 167, in _eventInvokeTimeoutCallback (timer=5, opaque=<PyCObject at remote 0x1f3b9e0>, opaquecompat=<PyCObject at remote 0x1f3b9e0>, callback=<PyCObject at remote 0x1f3bdf0>), throwflag=<value optimized out>) at ../Python/ceval.c:2412
#6  0x00000000004a9741 in PyEval_EvalCodeEx (co=0x175da08, globals=<value optimized out>, 
    locals=<value optimized out>, args=0x3, argcount=<value optimized out>, kws=<value optimized out>, kwcount=0, 
    defs=0x180d828, defcount=1, closure=0x0) at ../Python/ceval.c:3000
#7  0x00000000004a78d2 in fast_function (f=
    Frame 0x1fb5a00, for file /usr/lib/pymodules/python2.6/univention/uvmm/eventloop.py, line 106, in dispatch (self=<virEventLoopPureTimer(cb=<function at remote 0x1804d70>, lastfired=1370254197427, interval=0, timer=5, opaque=(<PyCObject at remote 0x1f3bdf0>, <PyCObject at remote 0x1f3b9e0>, None)) at remote 0x1f378c0>), 
    throwflag=<value optimized out>) at ../Python/ceval.c:3846

Das wird zwar anscheinend behandelt, aber anschließend tritt der SEIGSEGV erneut auf und UVMMd hängt in einer Endlosschleife fest:
signal_handler (sig_num=11) at ../Modules/signalmodule.c:165
165     ../Modules/signalmodule.c: Datei oder Verzeichnis nicht gefunden.
        in ../Modules/signalmodule.c

Der SIGSEGV wird als pending markiert, aber die Warteschlange läuft über:
(gdb) print Handlers[11]
$8 = {tripped = 1, func = <function at remote 0x181faa0>}
Py_AddPendingCall (func=0x4d9d20 <checksignals_witharg>, arg=0x0) at ../Python/ceval.c:417
417             return -1; /* Queue full */
Comment 24 Stefan Gohmann univentionstaff 2016-04-25 07:52:12 CEST
This issue has been filed against UCS 2.4.

UCS 2.4 is out of maintenance and many UCS components have vastly 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".
In this case please provide detailed information on how this issue is affecting
you.