[Pkg-libvirt-maintainers] Bug#661029: libvirt-bin - crash on startup

Adrian Bridgett adrian at smop.co.uk
Thu Feb 23 18:18:14 UTC 2012 

Package: libvirt-bin
Version: 0.9.9-3+b2

libvirtd is frequently crashing on startup with the output below.

I'm actually trying to debug what appears to be a related problem 
("udevadm settle" hanging as a single event has been lost between the 
kernel and udev) and so I'm restarting udev in rc.local (sometimes with 
debug on, sometimes not).  This seems to help to trigger the problem.

In fact, I seem to be able to reproduce this at will now. Steps:
a) edit /etc/udev/udev.conf and set udev_log="debug"
b) /etc/init.d/udev restart
c) /etc/init.d/libvirt-bin restart



2012-02-23 17:38:56.254+0000: 1483: info : libvirt version: 0.9.9
2012-02-23 17:38:56.254+0000: 1483: error : udev_set_log_fn:336 : custom 
logging function 0x7f426e428af8 registered

Caught Segmentation violation dumping internal log buffer:


     ====== start of log =====

2012-02-23 17:38:55.601+00001472: debug : virNetServerMDNSAddGroup:473 : 
Adding group 'Virtualization Host bl-vmhost-s03'
2012-02-23 17:38:55.601+00001472: debug : 
virEventRegisterDefaultImpl:204 : registering default event implementation
2012-02-23 17:38:55.601+00001472: debug : virEventPollAddHandle:116 : 
Used 0 handle slots, adding at least 10 more
2012-02-23 17:38:55.601+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.601+00001472: debug : virEventPollAddHandle:141 : 
EVENT_POLL_ADD_HANDLE: watch=1 fd=7 events=1 cb=0x7f427e2d10d0 
opaque=(nil) ff=(nil)
2012-02-23 17:38:55.601+00001472: debug : virEventRegisterImpl:177 : 
addHandle=0x7f427e2d1b10 updateHandle=0x7f427e2d1a10 
removeHandle=0x7f427e2d14b0 addTimeout=0x7f427e2d15f0 
updateTimeout=0x7f427e2d1790 removeTimeout=0x7f427e2d18a0
2012-02-23 17:38:55.601+00001472: debug : virNetServerNew:404 : 
srv=0xb4ec40 refs=1
2012-02-23 17:38:55.608+00001472: debug : virRegisterNetworkDriver:592 : 
registering Network as network driver 3
2012-02-23 17:38:55.608+00001472: debug : virRegisterInterfaceDriver:625 
: registering Interface as interface driver 2
2012-02-23 17:38:55.608+00001472: debug : virRegisterStorageDriver:658 : 
registering storage as storage driver 3
2012-02-23 17:38:55.608+00001472: debug : udevNodeRegister:1779 : 
Registering udev node device backend
2012-02-23 17:38:55.608+00001472: debug : virRegisterDeviceMonitor:691 : 
registering udevDeviceMonitor as device driver 2
2012-02-23 17:38:55.608+00001472: debug : virRegisterSecretDriver:724 : 
registering secret as secret driver 2
2012-02-23 17:38:55.608+00001472: debug : virRegisterNWFilterDriver:757 
: registering nwfilter as network filter driver 2
2012-02-23 17:38:55.609+00001472: debug : virRegisterDriver:775 : 
driver=0x72eba0 name=QEMU
2012-02-23 17:38:55.609+00001472: debug : virRegisterDriver:799 : 
registering QEMU as driver 6
2012-02-23 17:38:55.610+00001472: debug : virRegisterDriver:775 : 
driver=0x72f220 name=LXC
2012-02-23 17:38:55.610+00001472: debug : virRegisterDriver:799 : 
registering LXC as driver 7
2012-02-23 17:38:55.610+00001472: debug : virRegisterDriver:775 : 
driver=0x72f8e0 name=UML
2012-02-23 17:38:55.610+00001472: debug : virRegisterDriver:799 : 
registering UML as driver 8
2012-02-23 17:38:55.610+00001472: debug : virNetServerProgramNew:66 : 
prog=0x7f4270000d20 refs=1
2012-02-23 17:38:55.610+00001472: debug : virNetServerProgramRef:87 : 
prog=0x7f4270000d20 refs=2
2012-02-23 17:38:55.610+00001472: debug : virNetServerProgramNew:66 : 
prog=0x7f4270001140 refs=1
2012-02-23 17:38:55.610+00001472: debug : virNetServerProgramRef:87 : 
prog=0x7f4270001140 refs=2
2012-02-23 17:38:55.610+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.610+00001472: debug : virEventPollAddHandle:141 : 
EVENT_POLL_ADD_HANDLE: watch=2 fd=9 events=1 cb=0x7f427e395260 
opaque=0xb4ec40 ff=(nil)
2012-02-23 17:38:55.610+00001472: debug : virHookCheck:115 : No hook 
script /etc/libvirt/hooks/daemon
2012-02-23 17:38:55.610+00001472: debug : virHookCheck:115 : No hook 
script /etc/libvirt/hooks/qemu
2012-02-23 17:38:55.610+00001472: debug : virHookCheck:115 : No hook 
script /etc/libvirt/hooks/lxc
2012-02-23 17:38:55.611+00001472: debug : virNetSocketNew:119 : 
localAddr=0x7fffad38c7e0 remoteAddr=(nil) fd=11 errfd=-1 pid=0
2012-02-23 17:38:55.611+00001472: debug : virNetSocketNew:179 : 
RPC_SOCKET_NEW: sock=0x7f42700012c0 refs=1 fd=11 errfd=-1 pid=0 
localAddr=127.0.0.1;0, remoteAddr=(null)
2012-02-23 17:38:55.611+00001472: debug : virNetSocketRef:709 : 
RPC_SOCKET_REF: sock=0x7f42700012c0 refs=2
2012-02-23 17:38:55.611+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.611+00001472: debug : virEventPollAddHandle:141 : 
EVENT_POLL_ADD_HANDLE: watch=3 fd=11 events=0 cb=0x7f427e39ddb0 
opaque=0x7f42700012c0 ff=0x7f427e39e3d0
2012-02-23 17:38:55.611+00001472: debug : virNetSocketNew:119 : 
localAddr=0x7fffad38c7e0 remoteAddr=(nil) fd=12 errfd=-1 pid=0
2012-02-23 17:38:55.611+00001472: debug : virNetSocketNew:179 : 
RPC_SOCKET_NEW: sock=0x7f42700028a0 refs=1 fd=12 errfd=-1 pid=0 
localAddr=127.0.0.1;0, remoteAddr=(null)
2012-02-23 17:38:55.611+00001472: debug : virNetSocketRef:709 : 
RPC_SOCKET_REF: sock=0x7f42700028a0 refs=2
2012-02-23 17:38:55.611+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.611+00001472: debug : virEventPollAddHandle:141 : 
EVENT_POLL_ADD_HANDLE: watch=4 fd=12 events=0 cb=0x7f427e39ddb0 
opaque=0x7f42700028a0 ff=0x7f427e39e3d0
2012-02-23 17:38:55.611+00001472: debug : virNetServerMDNSAddEntry:518 : 
Adding entry _libvirt._tcp -1 to group Virtualization Host bl-vmhost-s03
2012-02-23 17:38:55.740+00001472: debug : virNetServerRef:417 : 
srv=0xb4ec40 refs=2
2012-02-23 17:38:55.740+00001472: debug : virNetServerMDNSStart:451 : 
Starting client 0x7f42700008e0
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSTimeoutNew:336 
: Add timeout TV (nil)
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSTimeoutNew:351 
: Trigger timed for 1330018735 742012      0 0
2012-02-23 17:38:55.742+00001472: debug : virEventPollAddTimeout:225 : 
Used 0 timeout slots, adding at least 10 more
2012-02-23 17:38:55.742+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.742+00001472: debug : virEventPollAddTimeout:248 : 
EVENT_POLL_ADD_TIMEOUT: timer=1 frequency=-1 cb=0x7f427e3983e0 
opaque=0x7f42700050d0 ff=0x7f427e398020
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSWatchNew:282 : 
New handle 0x7f4270004bf0 FD 6 Event 1
2012-02-23 17:38:55.742+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.742+00001472: debug : virEventPollAddHandle:141 : 
EVENT_POLL_ADD_HANDLE: watch=5 fd=6 events=1 cb=0x7f427e398910 
opaque=0x7f4270004bf0 ff=0x7f427e398040
2012-02-23 17:38:55.742+00001472: debug : 
virNetServerMDNSTimeoutUpdate:383 : Update timeout 0x7f42700050d0 TV 
0x7f427cb90a80
2012-02-23 17:38:55.742+00001472: debug : virEventPollUpdateTimeout:259 
: EVENT_POLL_UPDATE_TIMEOUT: timer=1 frequency=0
2012-02-23 17:38:55.742+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSTimeoutNew:336 
: Add timeout TV 0x7fffad38c6f0
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSTimeoutNew:351 
: Trigger timed for 1330018735 742097      1330018760 742092
2012-02-23 17:38:55.742+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.742+00001472: debug : virEventPollAddTimeout:248 : 
EVENT_POLL_ADD_TIMEOUT: timer=2 frequency=0 cb=0x7f427e3983e0 
opaque=0x7f4270008520 ff=0x7f427e398020
2012-02-23 17:38:55.742+00001472: debug : 
virNetServerMDNSTimeoutFree:404 : Free timeout 0x7f4270008520
2012-02-23 17:38:55.742+00001472: debug : virEventPollRemoveTimeout:293 
: EVENT_POLL_REMOVE_TIMEOUT: timer=2
2012-02-23 17:38:55.742+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSTimeoutNew:336 
: Add timeout TV 0x7fffad38c6f0
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSTimeoutNew:351 
: Trigger timed for 1330018735 742465      1330018760 742457
2012-02-23 17:38:55.742+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.742+00001472: debug : virEventPollAddTimeout:248 : 
EVENT_POLL_ADD_TIMEOUT: timer=3 frequency=0 cb=0x7f427e3983e0 
opaque=0x7f42700085c0 ff=0x7f427e398020
2012-02-23 17:38:55.742+00001472: debug : 
virNetServerMDNSTimeoutFree:404 : Free timeout 0x7f42700085c0
2012-02-23 17:38:55.742+00001472: debug : virEventPollRemoveTimeout:293 
: EVENT_POLL_REMOVE_TIMEOUT: timer=3
2012-02-23 17:38:55.742+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSTimeoutNew:336 
: Add timeout TV 0x7fffad38c6f0
2012-02-23 17:38:55.742+00001472: debug : virNetServerMDNSTimeoutNew:351 
: Trigger timed for 1330018735 742822      1330018760 742813
2012-02-23 17:38:55.742+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.742+00001472: debug : virEventPollAddTimeout:248 : 
EVENT_POLL_ADD_TIMEOUT: timer=4 frequency=0 cb=0x7f427e3983e0 
opaque=0x7f4270008910 ff=0x7f427e398020
2012-02-23 17:38:55.743+00001472: debug : 
virNetServerMDNSTimeoutFree:404 : Free timeout 0x7f4270008910
2012-02-23 17:38:55.743+00001472: debug : virEventPollRemoveTimeout:293 
: EVENT_POLL_REMOVE_TIMEOUT: timer=4
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.743+00001472: debug : virNetServerMDNSTimeoutNew:336 
: Add timeout TV 0x7fffad38c740
2012-02-23 17:38:55.743+00001472: debug : virNetServerMDNSTimeoutNew:351 
: Trigger timed for 1330018735 743206      1330018760 743195
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.743+00001472: debug : virEventPollAddTimeout:248 : 
EVENT_POLL_ADD_TIMEOUT: timer=5 frequency=0 cb=0x7f427e3983e0 
opaque=0x7f42700090a0 ff=0x7f427e398020
2012-02-23 17:38:55.743+00001472: debug : 
virNetServerMDNSTimeoutFree:404 : Free timeout 0x7f42700090a0
2012-02-23 17:38:55.743+00001472: debug : virEventPollRemoveTimeout:293 
: EVENT_POLL_REMOVE_TIMEOUT: timer=5
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-02-23 17:38:55.743+00001472: debug : 
virNetServerMDNSClientCallback:201 : Callback state=101
2012-02-23 17:38:55.743+00001472: debug : 
virNetServerMDNSClientCallback:245 : Client connecting.... 0x7f4270004b10
2012-02-23 17:38:55.743+00001472: debug : virNetServerRun:711 : 
srv=0xb4ec40 quit=0
2012-02-23 17:38:55.743+00001472: debug : virEventRunDefaultImpl:244 : 
running default event implementation
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 5
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCleanupTimeouts:519 : EVENT_POLL_PURGE_TIMEOUT: timer=2
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCleanupTimeouts:519 : EVENT_POLL_PURGE_TIMEOUT: timer=3
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCleanupTimeouts:519 : EVENT_POLL_PURGE_TIMEOUT: timer=4
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCleanupTimeouts:519 : EVENT_POLL_PURGE_TIMEOUT: timer=5
2012-02-23 17:38:55.743+00001472: debug : virEventPollCleanupHandles:554 
: Cleanup 5
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=0 w=1, f=7 e=1 d=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=1 w=2, f=9 e=1 d=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=2 w=3, f=11 e=0 d=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=3 w=4, f=12 e=0 d=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=4 w=5, f=6 e=1 d=0
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCalculateTimeout:325 : Calculate expiry of 1 timers
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCalculateTimeout:331 : Got a timeout scheduled for 1330018735742
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCalculateTimeout:351 : Timeout at 1330018735742 due in 0 ms
2012-02-23 17:38:55.743+00001472: debug : virEventPollRunOnce:619 : 
EVENT_POLL_RUN: nhandles=3 imeout=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollRunOnce:630 : Poll 
got 0 event(s)
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollDispatchTimeouts:415 : Dispatch 1
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollDispatchTimeouts:438 : EVENT_POLL_DISPATCH_TIMEOUT: timer=1
2012-02-23 17:38:55.743+00001472: debug : 
virNetServerMDNSTimeoutDispatch:318 : Dispatch timeout 0x7f42700050d0 1
2012-02-23 17:38:55.743+00001472: debug : virEventPollUpdateTimeout:259 
: EVENT_POLL_UPDATE_TIMEOUT: timer=1 frequency=-1
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 1 2125129760
2012-02-23 17:38:55.743+00001472: debug : 
virNetServerMDNSTimeoutUpdate:383 : Update timeout 0x7f42700050d0 TV (nil)
2012-02-23 17:38:55.743+00001472: debug : virEventPollUpdateTimeout:259 
: EVENT_POLL_UPDATE_TIMEOUT: timer=1 frequency=-1
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 1 2125129760
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 1
2012-02-23 17:38:55.743+00001472: debug : virEventPollCleanupHandles:554 
: Cleanup 5
2012-02-23 17:38:55.743+00001472: debug : virEventRunDefaultImpl:244 : 
running default event implementation
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 1
2012-02-23 17:38:55.743+00001472: debug : virEventPollCleanupHandles:554 
: Cleanup 5
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=0 w=1, f=7 e=1 d=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=1 w=2, f=9 e=1 d=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=2 w=3, f=11 e=0 d=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=3 w=4, f=12 e=0 d=0
2012-02-23 17:38:55.743+00001472: debug : virEventPollMakePollFDs:383 : 
Prepare n=4 w=5, f=6 e=1 d=0
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCalculateTimeout:325 : Calculate expiry of 1 timers
2012-02-23 17:38:55.743+00001472: debug : 
virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-02-23 17:38:55.743+00001472: debug : virEventPollRunOnce:619 : 
EVENT_POLL_RUN: nhandles=3 imeout=-1
2012-02-23 17:38:55.773+00001483: info : networkReloadIptablesRules:1513 
: Reloading iptables rules
2012-02-23 17:38:55.792+00001483: debug : virCommandRunAsync:2142 : 
About to run /sbin/udevadm settle
2012-02-23 17:38:55.792+00001483: debug : virCommandRunAsync:2159 : 
Command result 0, with PID 1496
2012-02-23 17:38:55.906+00001483: debug : virCommandProcessIO:1786 : 
hangup on stdout
2012-02-23 17:38:55.906+00001483: debug : virCommandProcessIO:1783 : 
hangup on stderr
2012-02-23 17:38:55.906+00001483: debug : virCommandRun:1962 : Result 
exit status 0, stdout: '' stderr: ''
2012-02-23 17:38:55.906+00001483: debug : virCommandRunAsync:2142 : 
About to run /sbin/lvs --separator # --noheadings --units b --unbuffered 
--nosuffix --options 
lv_name,origin,uuid,devices,segtype,stripes,seg_size,vg_extent_size rootvg
2012-02-23 17:38:55.906+00001483: debug : virCommandRunAsync:2159 : 
Command result 0, with PID 1513
2012-02-23 17:38:56.156+00001483: debug : virCommandRunAsync:2142 : 
About to run /sbin/vgs --separator : --noheadings --units b --unbuffered 
--nosuffix --options vg_size,vg_free rootvg
2012-02-23 17:38:56.156+00001483: debug : virCommandRunAsync:2159 : 
Command result 0, with PID 1521
2012-02-23 17:38:56.254+00001483: error : udev_set_log_fn:336 : custom 
logging function 0x7f426e428af8 registered

2012-02-23 17:38:56.268+00001483: debug : 
virEventPollInterruptLocked:706 : Interrupting
2012-02-23 17:38:56.268+00001483: debug : virEventPollAddHandle:141 : 
EVENT_POLL_ADD_HANDLE: watch=6 fd=14 events=1 cb=0x4d3580 opaque=(nil) 
ff=(nil)
2012-02-23 17:38:56.268+00001472: debug : virEventPollRunOnce:630 : Poll 
got 1 event(s)
2012-02-23 17:38:56.268+00001472: debug : 
virEventPollDispatchTimeouts:415 : Dispatch 1
2012-02-23 17:38:56.268+00001472: debug : 
virEventPollDispatchHandles:460 : Dispatch 3
2012-02-23 17:38:56.268+00001472: debug : 
virEventPollDispatchHandles:474 : i=0 w=1
2012-02-23 17:38:56.268+00001472: debug : 
virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=1 
events=1


      ====== end of log =====

More information about the Pkg-libvirt-maintainers mailing list