5:33 a.m.
On 17.05.2013 11:37, Li Wei wrote:
On 05/17/2013 04:52 PM, Michal Privoznik wrote:
> On 17.05.2013 10:16, Li Wei wrote:
>> On 05/17/2013 04:07 PM, Michal Privoznik wrote:
>>> On 17.05.2013 07:47, Li Wei wrote:
>>>> Hi Michal, Daniel
>>>>
>>>> It seems there is something wrong with the 2/2 part of this patchset.
>>>> When I do an "change-media" command in virsh, it doesn't do
any better
>>>> than before, but even worse(I must to wait 5 secs to see the error).
>>>>
>>>> I'm not family with libvirt, just add some log things in the
qemu_hotplug.c
>>>> and found the tray_status never change to open, but with michal's
original
>>>> patch (which do active poll on tray_status), I can do
"change-media" successfully
>>>> every time.
>>>
>>> Yes & no. Thing is - originally we ignored tray status in the guest. So
>>> in case guest has locked the tray and thus ignored our eject request, we
>>> have changed the media anyway, resulting in possible I/O errors within
>>> guest.
>>>
>>> With my patch, we send eject request to the qemu, and actively poll for
>>> the tray to open. We check for up to 10 times every 200ms. So guest has
>>> 2 seconds to open the tray. If the guest doesn't eject media and open
>>> the tray we don't proceed with forcibly changing the media.
>>>
>>> These patches are actually a bug fix for
>>> https://bugzilla.redhat.com/show_bug.cgi?id=892289
>>
>> Hmm... I think you misunderstood my meaning(sorry for my pool english),
>> simply to say, I can get expected behavior by apply patch V1 but not V2.
>>
>> In V1, we do active poll on qemuMonitorGetBlockInfo(), and in V2 we just
>> wait for origdisk->tray_status to become VIR_DOMAIN_DISK_TRAY_OPEN but
>> this never happened.
>>
>> Thanks,
>> Wei
>
> Aaah, now I understand. So you are saying that the event is not being
> delivered. What's the qemu version?
I have the following version:
virsh # version
Compiled against library: libvirt 1.0.5
Using library: libvirt 1.0.5
Using API: QEMU 1.0.5
Running hypervisor: QEMU 1.4.1
>
> If you turn the debug logs on, do you see DEVICE_TRAY_MOVED in them?
> http://wiki.libvirt.org/page/DebugLogs
>
> Or maybe the timeout is just short for your guest to eject the tray. So
> after a while, does 'virsh change-media' succeed?
Yes, I can see the DEVICE_TRAY_MOVED in the log file, it goes after
the debug message "qemuDomainChangeEjectableMedia:103 : Waiting 500ms for tray to
open. Retries left 0".
does that mean the timeout is too short?
If the guest needs too much time to eject, I'm wondering why when I use
the v1 patch, I can get succeed in about 1 to 2 seconds. I doubt if there
are other problems cause tray_status not updated in time?
I appended the log file for your reference, if you need any other information,
please tell me.
Thanks,
Wei
I am pasting some interesting knobs from the log:
2013-05-17 09:04:46.234+0000: 27004: debug : qemuMonitorSend:892 : QEMU_MONITOR_SEND_MSG:
mon=0x7f7ac4000bd0
msg={"execute":"eject","arguments":{"device":"drive-ide0-1-0","force":false},"id":"libvirt-7"}
fd=-1
2013-05-17 09:04:46.234+0000: 27001: debug : virObjectRef:295 : OBJECT_REF:
obj=0x7f7ac4000bd0
2013-05-17 09:04:46.234+0000: 27001: debug : qemuMonitorIOWrite:458 :
QEMU_MONITOR_IO_WRITE: mon=0x7f7ac4000bd0
buf={"execute":"eject","arguments":{"device":"drive-ide0-1-0","force":false},"id":"libvirt-7"}
len=92 ret=92 errno=2
2013-05-17 09:04:46.234+0000: 27001: debug : virObjectUnref:258 : OBJECT_UNREF:
obj=0x7f7ac4000bd0
2013-05-17 09:04:46.234+0000: 27001: debug : virObjectRef:295 : OBJECT_REF:
obj=0x7f7ac4000bd0
2013-05-17 09:04:46.234+0000: 27001: debug : qemuMonitorIOProcess:350 :
QEMU_MONITOR_IO_PROCESS: mon=0x7f7ac4000bd0 buf={"id": "libvirt-7",
"error": {"class": "GenericError", "desc":
"Device 'drive-ide0-1-0' is locked"}}
len=102
2013-05-17 09:04:46.234+0000: 27001: debug : virObjectUnref:258 : OBJECT_UNREF:
obj=0x7f7ac4000bd0
2013-05-17 09:04:46.235+0000: 27004: error : qemuMonitorJSONCheckError:352 : internal
error unable to execute QEMU command 'eject': Device 'drive-ide0-1-0' is
locked
2013-05-17 09:04:46.235+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 9
2013-05-17 09:04:46.735+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 8
2013-05-17 09:04:47.235+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 7
2013-05-17 09:04:47.735+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 6
2013-05-17 09:04:48.186+0000: 27001: debug : virObjectRef:295 : OBJECT_REF:
obj=0x7f7ac4000bd0
2013-05-17 09:04:48.235+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 5
2013-05-17 09:04:48.735+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 4
2013-05-17 09:04:49.235+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 3
2013-05-17 09:04:49.736+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 2
2013-05-17 09:04:50.236+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 1
2013-05-17 09:04:50.736+0000: 27004: debug : qemuDomainChangeEjectableMedia:103 : Waiting
500ms for tray to open. Retries left 0
2013-05-17 09:04:51.236+0000: 27004: error : qemuDomainChangeEjectableMedia:117 :
operation failed: Unable to eject media before changing it
2013-05-17 09:04:51.236+0000: 27004: debug : virObjectUnref:258 : OBJECT_UNREF:
obj=0x7f7ac4000bd0
2013-05-17 09:04:51.236+0000: 27004: debug : virDomainLockDiskDetach:282 :
plugin=0x7f7acc007c00 dom=0x7f7acc0a4160 disk=0x7f7ac4003690
2013-05-17 09:04:51.236+0000: 27004: debug : virDomainLockManagerNew:128 :
plugin=0x7f7acc007c00 dom=0x7f7acc0a4160 withResources=0
2013-05-17 09:04:51.236+0000: 27004: debug : virLockManagerPluginGetDriver:295 :
plugin=0x7f7acc007c00
2013-05-17 09:04:51.236+0000: 27004: debug : virLockManagerNew:319 : driver=0x7f7ae53dc5e0
type=0 nparams=5 params=0x7f7ad7d25830 flags=0
2013-05-17 09:04:51.236+0000: 27001: debug : qemuMonitorIOProcess:350 :
QEMU_MONITOR_IO_PROCESS: mon=0x7f7ac4000bd0 buf={"timestamp":
{"seconds": 1368781488, "microseconds": 186399}, "event":
"DEVICE_TRAY_MOVED", "data": {"device":
"drive-ide0-1-0", "tray-open": true}}
len=151
What we can see here is:
1) libvirt asks qemu to eject
2) qemu responds with "Device is locked" - which is correct as it emulates guest
request
3) However, after a while, the guest decides it's now safe to eject the media (e.g.
all reads have finished, and the device has been unmounted) which is done
4) [not in the pasted log] After a while, you've decided to try again and this time it
succeeded, as the tray is already opened.
What we may do here is lifting the number of retries up. You can try yourself:
diff --git a/src/qemu/qemu_hotplug.c b/src/qemu/qemu_hotplug.c
index d037c9d..ddd8d17 100644
--- a/src/qemu/qemu_hotplug.c
+++ b/src/qemu/qemu_hotplug.c
@@ -50,7 +50,7 @@
#include "virstring.h"
#define VIR_FROM_THIS VIR_FROM_QEMU
-#define CHANGE_MEDIA_RETRIES 10
+#define CHANGE_MEDIA_RETRIES 20
int qemuDomainChangeEjectableMedia(virQEMUDriverPtr driver,
virDomainObjPtr vm,
Michal