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

Thu Feb 23 18:48:39 UTC 2012

On Thu, Feb 23, 2012 at 06:18:14PM +0000, Adrian Bridgett wrote:
> 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

Thanks for your report. Could you check tiwh 0.9.10 from experimental?
Also check #649435 which points to libudev. Could you also check with
valgrind?
Cheers,
 -- Guido

> 
> 
> 
> 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 =====
> 
> 
> 
> 
> _______________________________________________
> Pkg-libvirt-maintainers mailing list
> Pkg-libvirt-maintainers at lists.alioth.debian.org
> http://lists.alioth.debian.org/cgi-bin/mailman/listinfo/pkg-libvirt-maintainers
>