<font size=2 face="sans-serif">Hi,</font>
<br><font size=2 face="sans-serif">My config: vdsm host - CentOS
7, oVirt 3.5</font>
<br>
<br><tt><font size=2>> Could you please share from hypervisor the /var/log/vdsm/vdsm.log
too?</font></tt>
<br>
<br><font size=2 face="sans-serif">my </font><tt><font size=2> /var/log/vdsm/vdsm.log</font></tt>
<br>
<br><tt><font size=2>Thread-283375::DEBUG::2014-12-06 21:20:40,219::stompReactor::163::yajsonrpc.StompServer::(send)
Sending response</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,252::lvm::288::Storage.Misc.excCmd::(cmd)
SUCCESS: <err> = ' WARNING: lvmetad is running but disabled.
Restart lvmetad before enabling it!\n'; <rc> = 0</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,253::lvm::454::Storage.LVM::(_reloadlvs)
lvs reloaded</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,254::lvm::454::Storage.OperationMutex::(_reloadlvs)
Operation 'lvm reload operation' released the operation mutex</font></tt>
<br><tt><font size=2>Thread-283376::WARNING::2014-12-06 21:20:40,254::lvm::600::Storage.LVM::(getLv)
lv: fb8466c9-0867-4e73-8362-2c95eea89a83 not found in lvs vg: 9d53ecef-8bfc-470b-8867-836bfa7df137
response</font></tt>
<br><tt><font size=2>Thread-283376::ERROR::2014-12-06 21:20:40,254::task::866::Storage.TaskManager.Task::(_setError)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::Unexpected error</font></tt>
<br><tt><font size=2>Traceback (most recent call last):</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/storage/task.py",
line 873, in _run</font></tt>
<br><tt><font size=2> return fn(*args, **kargs)</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/logUtils.py",
line 45, in wrapper</font></tt>
<br><tt><font size=2> res = f(*args, **kwargs)</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/storage/hsm.py",
line 3099, in getVolumeSize</font></tt>
<br><tt><font size=2> apparentsize = str(dom.getVSize(imgUUID,
volUUID))</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/storage/blockSD.py",
line 622, in getVSize</font></tt>
<br><tt><font size=2> size = lvm.getLV(self.sdUUID, volUUID).size</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/storage/lvm.py",
line 893, in getLV</font></tt>
<br><tt><font size=2> raise se.LogicalVolumeDoesNotExistError("%s/%s"
% (vgName, lvName))</font></tt>
<br><tt><font size=2>LogicalVolumeDoesNotExistError: Logical volume does
not exist: (u'9d53ecef-8bfc-470b-8867-836bfa7df137/fb8466c9-0867-4e73-8362-2c95eea89a83',)</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,255::task::885::Storage.TaskManager.Task::(_run)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::Task._run: cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd
(u'9d53ecef-8bfc-470b-8867-836bfa7df137', u'00000002-0002-0002-0002-00000000010b',
u'7deace0a-0c83-41c8-9122-84079ad949c2', u'fb8466c9-0867-4e73-8362-2c95eea89a83')
{} failed - stopping task</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,255::task::1217::Storage.TaskManager.Task::(stop)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::stopping in state preparing
(force False)</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,255::task::993::Storage.TaskManager.Task::(_decref)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::ref 1 aborting True</font></tt>
<br><tt><font size=2>Thread-283376::INFO::2014-12-06 21:20:40,255::task::1171::Storage.TaskManager.Task::(prepare)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::aborting: Task is aborted:
'Logical volume does not exist' - code 610</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,255::task::1176::Storage.TaskManager.Task::(prepare)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::Prepare: aborted: Logical
volume does not exist</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,256::task::993::Storage.TaskManager.Task::(_decref)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::ref 0 aborting True</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,256::task::928::Storage.TaskManager.Task::(_doAbort)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::Task._doAbort: force False</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,256::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,256::task::595::Storage.TaskManager.Task::(_updateState)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::moving from state preparing
-> state aborting</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,256::task::550::Storage.TaskManager.Task::(__state_aborting)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::_aborting: recover policy
none</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,256::task::595::Storage.TaskManager.Task::(_updateState)
Task=`cb86d3c3-77f7-46c8-aec0-4c848f1eb2cd`::moving from state aborting
-> state failed</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,257::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,257::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}</font></tt>
<br><tt><font size=2><b>Thread-283376::ERROR::2014-12-06 21:20:40,257::dispatcher::76::Storage.Dispatcher::(wrapper)
{'status': {'message': "Logical volume does not exist: (u'9d53ecef-8bfc-470b-8867-836bfa7df137/fb8466c9-0867-4e73-8362-2c95eea89a83',)",
'code': 610}}</b></font></tt>
<br><tt><font size=2><b># My comment:"</b></font></tt><font size=2 face="sans-serif"><b>Realy,
this is volume is present! I mount it in the vdsm host!</b></font><tt><font size=2><b>
But, mount /dev/block/253:20 , no present in /dev/9d53ecef-8bfc-470b-8867-836bfa7df137/"</b></font></tt>
<br>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,257::vm::2289::vm.Vm::(_startUnderlyingVm)
vmId=`d1ccb04d-bda8-42a2-bab6-7def2f8b2a00`::_ongoingCreations released</font></tt>
<br><tt><font size=2>Thread-283376::ERROR::2014-12-06 21:20:40,257::vm::2326::vm.Vm::(_startUnderlyingVm)
vmId=`d1ccb04d-bda8-42a2-bab6-7def2f8b2a00`::The vm start process failed</font></tt>
<br><tt><font size=2>Traceback (most recent call last):</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/virt/vm.py",
line 2266, in _startUnderlyingVm</font></tt>
<br><tt><font size=2> self._run()</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/virt/vm.py",
line 3301, in _run</font></tt>
<br><tt><font size=2> devices = self.buildConfDevices()</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/virt/vm.py",
line 2063, in buildConfDevices</font></tt>
<br><tt><font size=2> self._normalizeVdsmImg(drv)</font></tt>
<br><tt><font size=2> File "/usr/share/vdsm/virt/vm.py",
line 1986, in _normalizeVdsmImg</font></tt>
<br><tt><font size=2> drv['volumeID'])</font></tt>
<br><tt><font size=2>StorageUnavailableError: ('Failed to get size for
volume %s', u'fb8466c9-0867-4e73-8362-2c95eea89a83')</font></tt>
<br><tt><font size=2>Thread-283376::DEBUG::2014-12-06 21:20:40,260::vm::2838::vm.Vm::(setDownStatus)
vmId=`d1ccb04d-bda8-42a2-bab6-7def2f8b2a00`::Changed state to Down: ('Failed
to get size for volume %s', u'fb8466c9-0867-4e73-8362-2c95eea89a83') (code=1)</font></tt>
<br><tt><font size=2>JsonRpc (StompReactor)::DEBUG::2014-12-06 21:20:41,089::stompReactor::98::Broker.StompAdapter::(handle_frame)
Handling message <StompFrame command='SEND'></font></tt>
<br><tt><font size=2>JsonRpcServer::DEBUG::2014-12-06 21:20:41,091::__init__::504::jsonrpc.JsonRpcServer::(serve_requests)
Waiting for request</font></tt>
<br><tt><font size=2>Thread-283378::DEBUG::2014-12-06 21:20:41,097::stompReactor::163::yajsonrpc.StompServer::(send)
Sending response</font></tt>
<br><tt><font size=2>JsonRpc (StompReactor)::DEBUG::2014-12-06 21:20:41,101::stompReactor::98::Broker.StompAdapter::(handle_frame)
Handling message <StompFrame command='SEND'></font></tt>
<br><tt><font size=2>JsonRpcServer::DEBUG::2014-12-06 21:20:41,103::__init__::504::jsonrpc.JsonRpcServer::(serve_requests)
Waiting for request</font></tt>
<br><tt><font size=2>Thread-283379::DEBUG::2014-12-06 21:20:41,108::vm::486::vm.Vm::(_getUserCpuTuneInfo)
vmId=`c66e3966-a190-4cb1-8677-3d49d29cedc9`::Domain Metadata is not set</font></tt>
<br><tt><font size=2>Thread-283379::DEBUG::2014-12-06 21:20:41,110::stompReactor::163::yajsonrpc.StompServer::(send)
Sending response</font></tt>
<br><font size=2 face="sans-serif"><br>
</font>
<br>
<br><tt><font size=2>Douglas Schilling Landgraf <dougsland@redhat.com>
ΞΑΠΙΣΑΞΟ 06.12.2014 03:02:33:<br>
<br>
> οΤ: Douglas Schilling Landgraf <dougsland@redhat.com></font></tt>
<br><tt><font size=2>> λΟΝΥ: users@ovirt.org, </font></tt>
<br><tt><font size=2>> λΟΠΙΡ: drovalev@kaluga-gov.ru, Dan Kenigsberg
<danken@redhat.com></font></tt>
<br><tt><font size=2>> δΑΤΑ: 05.12.2014 23:58</font></tt>
<br><tt><font size=2>> τΕΝΑ: Re: [ovirt-users] Don't start vm</font></tt>
<br><tt><font size=2>> <br>
> On 12/05/2014 02:55 PM, Roman Nikolayevich Drovalev wrote:<br>
> > Hi,<br>
> > Please Help<br>
> ><br>
> > I normal stop my virtual mashine. But not start !<br>
> ><br>
> > in the logs<br>
> ><br>
> > 2014-12-05 09:38:06,437 ERROR<br>
> > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]<br>
> > (DefaultQuartzScheduler_Worker-87) Correlation ID: null, Call
Stack:<br>
> > null, Custom Event ID: -1, Message: VM Cent is down with error.
Exit<br>
> > message: ('Failed to get size for volume %s',<br>
> > u'fb8466c9-0867-4e73-8362-2c95eea89a83').<br>
> > 2014-12-05 09:38:06,439 INFO<br>
> > [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]<br>
> > (DefaultQuartzScheduler_Worker-87) Running on vds during rerun
failed<br>
> > vm: null<br>
> > 2014-12-05 09:38:06,447 INFO<br>
> > [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]<br>
> > (DefaultQuartzScheduler_Worker-87) VM Cent<br>
> > (d1ccb04d-bda8-42a2-bab6-7def2f8b2a00) is running in db and not
running<br>
> > in VDS x3550m2down<br>
> > 2014-12-05 09:38:06,475 ERROR<br>
> > [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]<br>
> > (DefaultQuartzScheduler_Worker-87) Rerun vm<br>
> > d1ccb04d-bda8-42a2-bab6-7def2f8b2a00. Called from vds x3550m2down<br>
> > 2014-12-05 09:38:06,482 WARN<br>
> > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]<br>
> > (org.ovirt.thread.pool-8-thread-16) Correlation ID: 2f3d1469,
Job ID:<br>
> > 86d62fc3-f2d3-48f1-a5b3-d2abd0f84d6c, Call Stack: null, Custom
Event ID:<br>
> > -1, Message: Failed to run VM Cent on Host x3550m2down<br>
> > 2014-12-05 09:38:06,486 INFO [org.ovirt.engine.core.bll.RunVmCommand]<br>
> > (org.ovirt.thread.pool-8-thread-16) Lock Acquired to object EngineLock<br>
> > [exclusiveLocks= key: d1ccb04d-bda8-42a2-bab6-7def2f8b2a00 value:
VM<br>
> > , sharedLocks= ]<br>
> > 2014-12-05 09:38:06,504 INFO<br>
> > [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]<br>
> > (org.ovirt.thread.pool-8-thread-16) START,<br>
> > IsVmDuringInitiatingVDSCommand( vmId =<br>
> > d1ccb04d-bda8-42a2-bab6-7def2f8b2a00), log id: 2e257f81<br>
> > 2014-12-05 09:38:06,505 INFO<br>
> > [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]<br>
> > (org.ovirt.thread.pool-8-thread-16) FINISH,<br>
> > IsVmDuringInitiatingVDSCommand, return: false, log id: 2e257f81<br>
> > 2014-12-05 09:38:06,509 WARN [org.ovirt.engine.core.bll.RunVmCommand]<br>
> > (org.ovirt.thread.pool-8-thread-16) CanDoAction of action RunVm
failed.<br>
> > <br>
> Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,SCHEDULING_NO_HOSTS<br>
> ><br>
> > 2014-12-05 09:38:06,510 INFO [org.ovirt.engine.core.bll.RunVmCommand]<br>
> > (org.ovirt.thread.pool-8-thread-16) Lock freed to object EngineLock<br>
> > [exclusiveLocks= key: d1ccb04d-bda8-42a2-bab6-7def2f8b2a00 value:
VM<br>
> > , sharedLocks= ]<br>
> > 2014-12-05 09:38:06,539 ERROR<br>
> > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]<br>
> > (org.ovirt.thread.pool-8-thread-16) Correlation ID: 2f3d1469,
Job ID:<br>
> > 86d62fc3-f2d3-48f1-a5b3-d2abd0f84d6c, Call Stack: null, Custom
Event ID:<br>
> > -1, Message: Failed to run VM Cent (User: admin).<br>
> > 2014-12-05 09:38:06,548 INFO<br>
> > [org.ovirt.engine.core.bll.ProcessDownVmCommand]<br>
> > (org.ovirt.thread.pool-8-thread-27) [58fe3e35] Running command:<br>
> > ProcessDownVmCommand internal: true.<br>
> ><br>
> > What me do?<br>
> ><br>
> <br>
> Hi Roman,<br>
> <br>
> <br>
> Could you please share from hypervisor the /var/log/vdsm/vdsm.log
too?<br>
> <br>
> <br>
> -- <br>
> Cheers<br>
> Douglas<br>
</font></tt>