[ovirt-users] ovirt 3.5 rc2 duplicate id (was Re: Duplicate ID 'drive-ide0-1-0' for drive .)

Mon Sep 15 22:37:54 UTC 2014

On Wed, Sep 10, 2014 at 7:01 PM, Dan Kenigsberg <danken at redhat.com> wrote:

> On Wed, Sep 10, 2014 at 05:17:35PM +0200, Sven Kieske wrote:
> >
> >
> > On 10/09/14 17:05, Nathanaël Blanchet wrote:
> > > Hello everyone,
> > >
> > > I experiment the same error with all of my host with vdsm 4.14.11.2
> since I upgraded to engine 3.4.x.
> > > I can't boot any new VMs, and the issue is about the duplicate ID
> drive.
> > > If I run once instead of "run", the vm boots fine.
> > > I've tested the suggested workaround and it works but it is not
> comfortable...
> > > What about this nasty bug? will it be resolved with 3.4.4?
> > > Thanks.
> >
> > I'm not aware of this bug reported at bugzilla.redhat.com
> >
> > I may have missed it because there are plenty of bugs, but if you
> > don't report the bug there it's not very likely to get fixed.
>
> I'm not 100% that it's the same issue, but I have cloned
>
>     Bug 1140323 - fails to run VM - duplicate ID
>
> to 3.4.4. Let's see if what virt developers say.
>

BTW: the same problem is still present in 3.5. rc2
I just tried with a centos 6.5 iso image.
if you "erroneously" (?) attach cd iso during VM initial creation phase and
you start VM you get the same problem. Then you use the run once and you
are able to install os.
But then you continue to have the same problem, even if you modify the VM
and you say no cd is present at all.
Only able to start it again with run once method.

Instead if you create VM without specifying any cd and then you use the run
once method to connect the iso and install the VM you get no problem at all
with cd isos afterwards.

It is quite annoying not being able to recover the situation.

 In engine.log
2014-09-16 00:22:49,683 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(DefaultQuartzScheduler_Worker-17) Correlation ID: null, Call Stack: null,
Custom Event ID: -1, Message: VM c65 is down with error. Exit message:
internal error process exited while connecting to monitor: qemu-kvm: -drive
if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=:
Duplicate ID 'drive-ide0-1-0' for drive
.
2014-09-16 00:22:49,684 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-17) Running on vds during rerun failed vm:
null
2014-09-16 00:22:49,691 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-17) VM c65
(a858f04a-e4f4-49e8-a097-8ba8390b4d25) is running in db and not running in
VDS ovnode04
2014-09-16 00:22:49,710 ERROR
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-17) Rerun vm
a858f04a-e4f4-49e8-a097-8ba8390b4d25. Called from vds ovnode04
2014-09-16 00:22:49,717 WARN
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(org.ovirt.thread.pool-8-thread-12) Correlation ID: 7599780, Job ID:
8d63e66b-b26b-4344-85e0-ab72bf53fa1d, Call Stack: null, Custom Event ID:
-1, Message: Failed to run VM c65 on Host ovnode04.
2014-09-16 00:22:49,722 INFO  [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-12) Lock Acquired to object EngineLock
[exclusiveLocks= key: a858f04a-e4f4-49e8-a097-8ba8390b4d25 value: VM
, sharedLocks= ]

In VM.log on hypervisor under /var/log/libvirt/qemu/vm.log

2014-09-15 22:22:49.358+0000: starting up
LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin QEMU_AUDIO_DRV=spice
/usr/libexec/qemu-kvm -na
me c65 -S -M rhel6.5.0 -cpu Nehalem -enable-kvm -m 2048 -realtime mlock=off
-smp 2,maxcpus
=32,sockets=16,cores=2,threads=1 -uuid a858f04a-e4f4-49e8-a097-8ba8390b4d25
-smbios type=1
,manufacturer=oVirt,product=oVirt
Node,version=6-5.el6.centos.11.2,serial=9B1B2F84-3CB9-11
DE-B5A1-001517B493E8,uuid=a858f04a-e4f4-49e8-a097-8ba8390b4d25 -nodefconfig
-nodefaults -c
hardev
socket,id=charmonitor,path=/var/lib/libvirt/qemu/c65.monitor,server,nowait
-mon cha
rdev=charmonitor,id=monitor,mode=control -rtc
base=2014-09-16T00:22:49,driftfix=slew -no-k
vm-pit-reinjection -no-shutdown -device
piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -devi
ce virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x4 -device
virtio-serial-pci,id=virtio-serial0,max_ports=16,bus=pci.0,addr=0x5 -drive
if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=
-device ide-drive,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -drive
if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=
-device ide-drive,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -drive
file=/rhev/data-center/4512e567-f94e-476a-a050-6cd0a15e260a/346732c8-e1e9-49de-9ca4-63f4477ef6dd/images/c0a1e1a3-af66-482b-96b4-e8ec928053f7/c968201d-d3fe-4c29-904e-554004a43e3e,if=none,id=drive-scsi0-0-0-0,format=raw,serial=c0a1e1a3-af66-482b-96b4-e8ec928053f7,cache=none,werror=stop,rerror=stop,aio=native
-device
scsi-hd,bus=scsi0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0-0-0-0,id=scsi0-0-0-0,bootindex=1
-netdev tap,fd=28,id=hostnet0,vhost=on,vhostfd=29 -device
virtio-net-pci,netdev=hostnet0,id=net0,mac=00:01:a4:a3:42:00,bus=pci.0,addr=0x3
-chardev
socket,id=charchannel0,path=/var/lib/libvirt/qemu/channels/a858f04a-e4f4-49e8-a097-8ba8390b4d25.com.redhat.rhevm.vdsm,server,nowait
-device
virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=com.redhat.rhevm.vdsm
-chardev
socket,id=charchannel1,path=/var/lib/libvirt/qemu/channels/a858f04a-e4f4-49e8-a097-8ba8390b4d25.org.qemu.guest_agent.0,server,nowait
-device
virtserialport,bus=virtio-serial0.0,nr=2,chardev=charchannel1,id=channel1,name=org.qemu.guest_agent.0
-chardev spicevmc,id=charchannel2,name=vdagent -device
virtserialport,bus=virtio-serial0.0,nr=3,chardev=charchannel2,id=channel2,name=com.redhat.spice.0
-spice
port=5902,tls-port=5903,addr=192.168.1.74,x509-dir=/etc/pki/vdsm/libvirt-spice,tls-channel=main,tls-channel=display,tls-channel=inputs,tls-channel=cursor,tls-channel=playback,tls-channel=record,tls-channel=smartcard,tls-channel=usbredir,seamless-migration=on
-k en-us -vga qxl -global qxl-vga.ram_size=67108864 -global
qxl-vga.vram_size=33554432 -device
virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x6
qemu-kvm: -drive
if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=:
Duplicate ID 'drive-ide0-1-0' for drive
2014-09-15 22:22:49.633+0000: shutting down

In vdsm.log
Thread-159167::ERROR::2014-09-16
00:22:49,849::vm::2326::vm.Vm::(_startUnderlyingVm)
vmId=`a858f04a-e4f4-49e8-a097-8ba8390b4d25`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/vm.py", line 2266, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/virt/vm.py", line 3368, in _run
    self._connection.createXML(domxml, flags),
  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line
111, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2665, in
createXML
    if ret is None:raise libvirtError('virDomainCreateXML() failed',
conn=self)
libvirtError: internal error process exited while connecting to monitor:
qemu-kvm: -drive
if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=:
Duplicate ID 'drive-ide0-1-0' for drive
Thread-159167::DEBUG::2014-09-16
00:22:49,851::vm::2838::vm.Vm::(setDownStatus)
vmId=`a858f04a-e4f4-49e8-a097-8ba8390b4d25`::Changed state to Down:
internal error process exited while connecting to monitor: qemu-kvm: -drive
if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial=:
Duplicate ID 'drive-ide0-1-0' for drive
 (code=1)
JsonRpc (StompReactor)::DEBUG::2014-09-16
00:22:50,554::stompReactor::98::Broker.StompAdapter::(handle_frame)
Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2014-09-16
00:22:50,556::__init__::504::jsonrpc.JsonRpcServer::(serve_requests)
Waiting for request
Thread-159169::DEBUG::2014-09-16
00:22:50,559::task::595::Storage.TaskManager.Task::(_updateState)
Task=`ae3d407b-6c40-455e-a2d7-5ef55d95d1c5`::moving from state init ->
state preparing
Thread-159169::INFO::2014-09-16
00:22:50,559::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats(options=None)
Thread-159169::INFO::2014-09-16
00:22:50,559::logUtils::47::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {u'3b23161a-18a3-4cfa-bc78-f4fe2052b19e':
{'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000441651',
'lastCheck': '8.2', 'valid': True}, '346732c8-e1e9-49de-9ca4-63f4477ef6dd':
{'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000640336',
'lastCheck': '3.5', 'valid': True}}
Thread-159169::DEBUG::2014-09-16
00:22:50,559::task::1191::Storage.TaskManager.Task::(prepare)
Task=`ae3d407b-6c40-455e-a2d7-5ef55d95d1c5`::finished:
{u'3b23161a-18a3-4cfa-bc78-f4fe2052b19e': {'code': 0, 'version': 0,
'acquired': True, 'delay': '0.000441651', 'lastCheck': '8.2', 'valid':
True}, '346732c8-e1e9-49de-9ca4-63f4477ef6dd': {'code': 0, 'version': 3,
'acquired': True, 'delay': '0.000640336', 'lastCheck': '3.5', 'valid':
True}}
Thread-159169::DEBUG::2014-09-16
00:22:50,559::task::595::Storage.TaskManager.Task::(_updateState)
Task=`ae3d407b-6c40-455e-a2d7-5ef55d95d1c5`::moving from state preparing ->
state finished
Thread-159169::DEBUG::2014-09-16
00:22:50,559::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-159169::DEBUG::2014-09-16
00:22:50,559::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-159169::DEBUG::2014-09-16
00:22:50,560::task::993::Storage.TaskManager.Task::(_decref)
Task=`ae3d407b-6c40-455e-a2d7-5ef55d95d1c5`::ref 0 aborting False
Thread-159169::DEBUG::2014-09-16
00:22:50,563::stompReactor::163::yajsonrpc.StompServer::(send) Sending
response
...

Gianluca
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20140916/23b43636/attachment-0001.html>