thr3ads.net - libvirt users - Re: [libvirt-users] QemuDomainObjEndJob called when libvirtd is started and libvirt insists qemu is using the wrong disk source. [Apr 2015]

If this information is useful, please help other people find it:
Share via:

Matthew Schumacher

2015-Apr-21 01:28 UTC

Re: [libvirt-users] QemuDomainObjEndJob called when libvirtd is started and libvirt insists qemu is using the wrong disk source.

On 04/20/2015 05:12 PM, Laine Stump wrote:> On 04/20/2015 08:45 PM, Matthew Schumacher wrote:
>> List,
>>
>> I was under the impression that I could restart libvirtd without it
>> destroying my VMs, but am not finding that to be true. 
> If not, then something is wrong.
>
Here are the logs from the vm:

2015-04-20 23:50:20.387+0000: shutting down
qemu: terminating on signal 15 from pid 25298

And part of the logs from libvirt when I started it.  Does this help at all?

2015-04-20 23:50:20.387+0000: 25373: error :
virStorageFileBackendFileReadHeader:1443 : Failed to open file
'/dev/sr0': No medium found
2015-04-20 23:50:20.387+0000: 25373: debug :
virStorageFileReadHeader:2714 : read of storage header 0x7fb8cc0d75f0:
ret=-1            
2015-04-20 23:50:20.387+0000: 25373: debug :
virStorageFileBackendFileDeinit:1369 : deinitializing FS storage file
0x7fb8cc0d75f0 (block:/dev/sr0)                   
2015-04-20 23:50:20.387+0000: 25373: info : virObjectUnref:259 :
OBJECT_UNREF:
obj=0x7fb8cc0155b0                                                
2015-04-20 23:50:20.387+0000: 25373: debug : qemuDomainObjEndJob:1542 :
Stopping job: modify (async=none vm=0x7fb8cc0d8510 name=test)            
2015-04-20 23:50:20.387+0000: 25373: info : virObjectRef:296 :
OBJECT_REF:
obj=0x7fb8cc0155b0                                                    
2015-04-20 23:50:20.387+0000: 25373: debug : qemuProcessStop:5089 :
Shutting down vm=0x7fb8cc0d8510 name=test id=6 pid=25245
flags=0             
2015-04-20 23:50:20.387+0000: 25373: info : virObjectRef:296 :
OBJECT_REF:
obj=0x7fb8cc0155b0                                                    
2015-04-20 23:50:20.387+0000: 25373: info : virObjectUnref:259 :
OBJECT_UNREF:
obj=0x7fb8cc0155b0                                                
2015-04-20 23:50:20.387+0000: 25373: debug : virFileClose:102 : Closed
fd 19                                                                     
2015-04-20 23:50:20.387+0000: 25373: info : qemuMonitorClose:904 :
QEMU_MONITOR_CLOSE: mon=0x7fb8d0000bd0
refs=2                                 
2015-04-20 23:50:20.387+0000: 25373: info : virEventPollRemoveHandle:186
: EVENT_POLL_REMOVE_HANDLE:
watch=10                                         
2015-04-20 23:50:20.387+0000: 25373: debug :
virEventPollRemoveHandle:199 : mark delete 9
18                                                     
2015-04-20 23:50:20.387+0000: 25373: debug :
virEventPollInterruptLocked:726 :
Interrupting                                                      
2015-04-20 23:50:20.387+0000: 25373: debug : virFileClose:102 : Closed
fd 18                                                                     
2015-04-20 23:50:20.387+0000: 25373: info : virObjectUnref:259 :
OBJECT_UNREF:
obj=0x7fb8d0000bd0                                                
2015-04-20 23:50:20.387+0000: 25373: debug : qemuProcessKill:5047 :
vm=0x7fb8cc0d8510 name=test pid=25245
flags=5                                
2015-04-20 23:50:20.387+0000: 25373: debug : virProcessKillPainfully:352
: vpid=25245 force=1                                                    
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollRunOnce:650 :
Poll got 2 event(s)                                                       
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchTimeouts:432 : Dispatch
0                                                       
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:478 : Dispatch
8                                                        
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:492 : i=0
w=1                                                           
2015-04-20 23:50:20.387+0000: 25298: info :
virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=1
events=1                       
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:492 : i=1
w=2                                                           
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:492 : i=4
w=5                                                           
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:492 : i=5
w=6                                                           
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:492 : i=7
w=8                                              
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:492 : i=8
w=9                                              
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:492 : i=9
w=10                                            
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:495 : Skip deleted n=9 w=10
f=18                          
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollDispatchHandles:492 : i=10
w=11                                   
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollCleanupTimeouts:525 : Cleanup
0                                 
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollCleanupTimeouts:561 : Found 0 out of 0 timeout slots used,
releasing 0
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollCleanupHandles:574 : Cleanup
11                                                                   
2015-04-20 23:50:20.387+0000: 25298: info :
virEventPollCleanupHandles:587 : EVENT_POLL_PURGE_HANDLE:
watch=10                                                                     

2015-04-20 23:50:20.387+0000: 25298: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0x7fb8d0000bd0                             
2015-04-20 23:50:20.387+0000: 25298: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0x7fb8d0000bd0                           
2015-04-20 23:50:20.387+0000: 25298: debug : qemuMonitorDispose:259 :
mon=0x7fb8d0000bd0

2015-04-20 23:50:20.387+0000: 25298: info : virObjectUnref:259 :
OBJECT_UNREF:
obj=0x7fb8cc0d8510

2015-04-20 23:50:20.387+0000: 25298: debug : virEventRunDefaultImpl:305
: running default event implementation                
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollCleanupTimeouts:525 : Cleanup
0                                      
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollCleanupTimeouts:561 : Found 0 out of 0 timeout slots used,
releasing 0                                      
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollCleanupHandles:574 : Cleanup 10
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=0 w=1, f=7 e=1 d=0                                          
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=1 w=2, f=9 e=1 d=0                                          
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=2 w=3, f=11 e=0 d=0                                         
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=3 w=4, f=12 e=0 d=0                                         
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=4 w=5, f=6 e=1 d=0                                          
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=5 w=6, f=13 e=1 d=0                                         
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=6 w=7, f=14 e=0 d=0                                         
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=7 w=8, f=14 e=1 d=0                                         
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=8 w=9, f=16 e=1 d=0                                         
2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
: Prepare n=9 w=11, f=20 e=1 d=0                                        
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollCalculateTimeout:338 : Calculate expiry of 0
timers                        
2015-04-20 23:50:20.387+0000: 25298: debug :
virEventPollCalculateTimeout:370 : No timeout is
pending                               
2015-04-20 23:50:20.387+0000: 25298: info : virEventPollRunOnce:640 :
EVENT_POLL_RUN: nhandles=7 timeout=-1

Laine Stump

2015-Apr-21 01:42 UTC

head link

Re: [libvirt-users] QemuDomainObjEndJob called when libvirtd is started and libvirt insists qemu is using the wrong disk source.

On 04/20/2015 09:28 PM, Matthew Schumacher wrote:>
> On 04/20/2015 05:12 PM, Laine Stump wrote:
>> On 04/20/2015 08:45 PM, Matthew Schumacher wrote:
>>> List,
>>>
>>> I was under the impression that I could restart libvirtd without it
>>> destroying my VMs, but am not finding that to be true. 
>> If not, then something is wrong.
>>
> Here are the logs from the vm:
>
> 2015-04-20 23:50:20.387+0000: shutting down
> qemu: terminating on signal 15 from pid 25298
>
> And part of the logs from libvirt when I started it.  Does this help at
all?
>
> 2015-04-20 23:50:20.387+0000: 25373: error :
> virStorageFileBackendFileReadHeader:1443 : Failed to open file
> '/dev/sr0': No medium found
> 2015-04-20 23:50:20.387+0000: 25373: debug :
> virStorageFileReadHeader:2714 : read of storage header 0x7fb8cc0d75f0:
> ret=-1            
> 2015-04-20 23:50:20.387+0000: 25373: debug :
> virStorageFileBackendFileDeinit:1369 : deinitializing FS storage file
> 0x7fb8cc0d75f0 (block:/dev/sr0)                   
> 2015-04-20 23:50:20.387+0000: 25373: info : virObjectUnref:259 :
> OBJECT_UNREF:
> obj=0x7fb8cc0155b0                                                
> 2015-04-20 23:50:20.387+0000: 25373: debug : qemuDomainObjEndJob:1542 :
> Stopping job: modify (async=none vm=0x7fb8cc0d8510 name=test)            
> 2015-04-20 23:50:20.387+0000: 25373: info : virObjectRef:296 :
> OBJECT_REF:
> obj=0x7fb8cc0155b0                                                    
> 2015-04-20 23:50:20.387+0000: 25373: debug : qemuProcessStop:5089 :
> Shutting down vm=0x7fb8cc0d8510 name=test id=6 pid=25245
> flags=0             
> 2015-04-20 23:50:20.387+0000: 25373: info : virObjectRef:296 :
> OBJECT_REF:
> obj=0x7fb8cc0155b0                                                    
> 2015-04-20 23:50:20.387+0000: 25373: info : virObjectUnref:259 :
> OBJECT_UNREF:
> obj=0x7fb8cc0155b0                                                
> 2015-04-20 23:50:20.387+0000: 25373: debug : virFileClose:102 : Closed
> fd 19                                                                     
> 2015-04-20 23:50:20.387+0000: 25373: info : qemuMonitorClose:904 :
> QEMU_MONITOR_CLOSE: mon=0x7fb8d0000bd0
> refs=2                                 
> 2015-04-20 23:50:20.387+0000: 25373: info : virEventPollRemoveHandle:186
> : EVENT_POLL_REMOVE_HANDLE:
> watch=10                                         
> 2015-04-20 23:50:20.387+0000: 25373: debug :
> virEventPollRemoveHandle:199 : mark delete 9
> 18                                                     
> 2015-04-20 23:50:20.387+0000: 25373: debug :
> virEventPollInterruptLocked:726 :
> Interrupting                                                      
> 2015-04-20 23:50:20.387+0000: 25373: debug : virFileClose:102 : Closed
> fd 18                                                                     
> 2015-04-20 23:50:20.387+0000: 25373: info : virObjectUnref:259 :
> OBJECT_UNREF:
> obj=0x7fb8d0000bd0                                                
> 2015-04-20 23:50:20.387+0000: 25373: debug : qemuProcessKill:5047 :
> vm=0x7fb8cc0d8510 name=test pid=25245
> flags=5                                
Well, this is when the qemu process is killed (I'm pretty clever, eh? :-)

I have 3 questions:

1) what version of libvirt are you running and on what distro?

2) can you reproduce this reliably?

3) If the answer to 2 is "yes", do you have the libvirt-debuginfo
package installed, and can you stop libvirtd, then run it under gdb with
a breakpoint at qemuProcessKill? Once you hit that breakpoint, you could
get a backtrace with the "bt" command and that might give us some
useful
info about where it is coming from.

Oh, by the way, are these perhaps transient domains started with
virDomainCreate*? Or are they standard persistent domains defined with
virDomainDefineXML?

(Also, I'll just mention that qemuProcessKill() is called from
qemuProcessStop(), and I notice that is called in a couple places
related to snapshot create and revert which you mentioned in the
original message. Since this isn't normal behavior, and the snapshot
stuff is under active development, I wonder if this is
related...)> 2015-04-20 23:50:20.387+0000: 25373: debug : virProcessKillPainfully:352
> : vpid=25245 force=1                                                    
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollRunOnce:650 :
> Poll got 2 event(s)                                                       
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchTimeouts:432 : Dispatch
> 0                                                       
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:478 : Dispatch
> 8                                                        
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:492 : i=0
> w=1                                                           
> 2015-04-20 23:50:20.387+0000: 25298: info :
> virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=1
> events=1                       
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:492 : i=1
> w=2                                                           
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:492 : i=4
> w=5                                                           
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:492 : i=5
> w=6                                                           
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:492 : i=7
> w=8                                              
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:492 : i=8
> w=9                                              
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:492 : i=9
> w=10                                            
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:495 : Skip deleted n=9 w=10
> f=18                          
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollDispatchHandles:492 : i=10
> w=11                                   
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollCleanupTimeouts:525 : Cleanup
> 0                                 
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollCleanupTimeouts:561 : Found 0 out of 0 timeout slots used,
> releasing 0
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollCleanupHandles:574 : Cleanup
> 11                                                                   
> 2015-04-20 23:50:20.387+0000: 25298: info :
> virEventPollCleanupHandles:587 : EVENT_POLL_PURGE_HANDLE:
> watch=10
>
> 2015-04-20 23:50:20.387+0000: 25298: info : virObjectUnref:259 :
> OBJECT_UNREF: obj=0x7fb8d0000bd0                             
> 2015-04-20 23:50:20.387+0000: 25298: info : virObjectUnref:261 :
> OBJECT_DISPOSE: obj=0x7fb8d0000bd0                           
> 2015-04-20 23:50:20.387+0000: 25298: debug : qemuMonitorDispose:259 :
> mon=0x7fb8d0000bd0
>
> 2015-04-20 23:50:20.387+0000: 25298: info : virObjectUnref:259 :
> OBJECT_UNREF:
> obj=0x7fb8cc0d8510
>
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventRunDefaultImpl:305
> : running default event implementation                
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollCleanupTimeouts:525 : Cleanup
> 0                                      
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollCleanupTimeouts:561 : Found 0 out of 0 timeout slots used,
> releasing 0                                      
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollCleanupHandles:574 : Cleanup 10
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=0 w=1, f=7 e=1 d=0                                          
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=1 w=2, f=9 e=1 d=0                                          
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=2 w=3, f=11 e=0 d=0                                         
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=3 w=4, f=12 e=0 d=0                                         
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=4 w=5, f=6 e=1 d=0                                          
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=5 w=6, f=13 e=1 d=0                                         
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=6 w=7, f=14 e=0 d=0                                         
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=7 w=8, f=14 e=1 d=0                                         
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=8 w=9, f=16 e=1 d=0                                         
> 2015-04-20 23:50:20.387+0000: 25298: debug : virEventPollMakePollFDs:400
> : Prepare n=9 w=11, f=20 e=1 d=0                                        
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollCalculateTimeout:338 : Calculate expiry of 0
> timers                        
> 2015-04-20 23:50:20.387+0000: 25298: debug :
> virEventPollCalculateTimeout:370 : No timeout is
> pending                               
> 2015-04-20 23:50:20.387+0000: 25298: info : virEventPollRunOnce:640 :
> EVENT_POLL_RUN: nhandles=7 timeout=-1           
>
> _______________________________________________
> libvirt-users mailing list
> libvirt-users@redhat.com
> https://www.redhat.com/mailman/listinfo/libvirt-users
>
>

Matthew Schumacher

2015-Apr-21 21:53 UTC

head link

Re: [libvirt-users] QemuDomainObjEndJob called when libvirtd is started and libvirt insists qemu is using the wrong disk source.

On 04/20/2015 05:42 PM, Laine Stump wrote:> Well, this is when the qemu process is killed (I'm pretty clever, eh?
:-)
>
> I have 3 questions:
>
> 1) what version of libvirt are you running and on what distro?
>
> 2) can you reproduce this reliably?
>
> 3) If the answer to 2 is "yes", do you have the libvirt-debuginfo
> package installed, and can you stop libvirtd, then run it under gdb with
> a breakpoint at qemuProcessKill? Once you hit that breakpoint, you could
> get a backtrace with the "bt" command and that might give us some
useful
> info about where it is coming from.
>
> Oh, by the way, are these perhaps transient domains started with
> virDomainCreate*? Or are they standard persistent domains defined with
> virDomainDefineXML?
>
> (Also, I'll just mention that qemuProcessKill() is called from
> qemuProcessStop(), and I notice that is called in a couple places
> related to snapshot create and revert which you mentioned in the
> original message. Since this isn't normal behavior, and the snapshot
> stuff is under active development, I wonder if this is related...)
Laine,

First, thanks for your help, I appreciate it.  Your questions:

1.  # libvirtd -V
libvirtd (libvirt) 1.2.14

2.  I can reproduce this every time.

3.  I compile it myself, so I'll work on getting a libvirt-debug build
going.

So this is compiled on Slackware64-14.1 as I prefer a more bsd linux and
like the simplicity of a traditional init, as well as the ability to
cook this down into a very simple usb based distro not unlike slax.

Earlier I posted a bug
(https://bugzilla.redhat.com/show_bug.cgi?id=1210903) and got a reply
fro Shanzhi that said that he was unable to reproduce using
libvirt-1.2.14-1.el7.x86_64 and qemu-kvm-rhev-2.2.0-8.el7.x86_64, but I
don't see his comment on the ticket anymore, so I wonder if he was able
to reproduce and removed his comment or perhaps his comment got
removed.  If it does indeed work on the Redhat packages then that seems
to indicate that there is something that doesn't work when libvirt is
built on non-redhat systems which may be related.

Let me do some more digging and I'll back back to you tomorrow.

Thanks!
schu

Possibly Parallel Threads

Search for more maybe matching threads

libvirt users - Apr 2015 - Re: QemuDomainObjEndJob called when libvirtd is started and libvirt insists qemu is using the wrong disk source.

Re: [libvirt-users] QemuDomainObjEndJob called when libvirtd is started and libvirt insists qemu is using the wrong disk source.

Re: [libvirt-users] QemuDomainObjEndJob called when libvirtd is started and libvirt insists qemu is using the wrong disk source.

Re: [libvirt-users] QemuDomainObjEndJob called when libvirtd is started and libvirt insists qemu is using the wrong disk source.

Possibly Parallel Threads