Bug 1117688

Summary: Run VM once fail on invalid iso/floppy path.
Product: Red Hat Enterprise Virtualization Manager Reporter: Ilanit Stein <istein>
Component: ovirt-engineAssignee: Yeela Kaplan <ykaplan>
Status: CLOSED DUPLICATE QA Contact: Ilanit Stein <istein>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 3.5.0CC: acathrow, amureini, eedri, gklein, iheim, lpeer, michal.skrivanek, obasan, oourfali, pstehlik, Rhev-m-bugs, scohen, yeylon
Target Milestone: ---Keywords: AutomationBlocker, Regression, Triaged
Target Release: 3.5.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: infra
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-07-13 07:45:28 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
logs none

Description Ilanit Stein 2014-07-09 08:19:15 UTC 
Description of problem:
Run once from iso/floppy fail following GetFileStatsVDSCommand ERROR.

Version-Release number of selected component (if applicable):
ovirt-engine-3.5.0-0.0.master.20140629172257.git0b16ed7.el6.noarch
Same test pass for rhevm-3.4

Failing test:
http://jenkins.qa.lab.tlv.redhat.com:8080/job/3.5-art_rpm_build_testing/34/

How reproducible:
Till now failures repeated for all 3 daily runs.

Steps to Reproduce:
1. Attach iso domain
2. Run VM once using iso image or floppy.

Additional info (engine.log):
2014-07-08 09:58:49,441 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-1) [6e3e0df0] Correlation ID: 352eb0da-9c86-4efe_attachStorageDomain_create, Job ID: 9bcbcdf5-0cbd-48c9-a988-78c99950457e, Call Stack: null, Custom Event ID: -1, Message: Storage Domain shared_iso_domain was attached to Data Center datacenter_reg_vms by admin
2014-07-08 09:58:49,760 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetFileStatsVDSCommand] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] Command GetFileStatsVDSCommand( storagePoolId = fd0bcdc0-8c00-4da5-ab5a-d2d005aba1b7, ignoreFailoverLimit = false) execution failed. Exception: IrsOperationFailedNoFailoverException: IRSGenericException: IRSErrorException: Cannot get file stats: ('7233a711-98e8-4c3c-bcfa-44c4bcc4f6c6',)
2014-07-08 09:58:49,761 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetFileStatsVDSCommand] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] FINISH, GetFileStatsVDSCommand, log id: 332a0cbf
2014-07-08 09:58:49,762 WARN  [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] The refresh process from VDSM, for Iso files failed.
2014-07-08 09:58:49,763 ERROR [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IrsOperationFailedNoFailoverException: IRSGenericException: IRSErrorException: Cannot get file stats: ('7233a711-98e8-4c3c-bcfa-44c4bcc4f6c6',) (Failed with error GET_FILE_LIST_ERROR and code 330)
2014-07-08 09:58:49,805 ERROR [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] The following storage domains had a problem retrieving data from VDSM  ( Storage Pool Id: fd0bcdc0-8c00-4da5-ab5a-d2d005aba1b7 Storage domain Id: 7233a711-98e8-4c3c-bcfa-44c4bcc4f6c6 File type: ISO) 
2014-07-08 09:58:49,811 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Refresh image list failed for domain(s):   shared_iso_domain (ISO file type). Please check domain activity.
2014-07-08 09:58:49,813 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetFileStatsVDSCommand] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] START, GetFileStatsVDSCommand( storagePoolId = fd0bcdc0-8c00-4da5-ab5a-d2d005aba1b7, ignoreFailoverLimit = false), log id: 1cfee03f
2014-07-08 09:58:50,113 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetFileStatsVDSCommand] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] Command GetFileStatsVDSCommand( storagePoolId = fd0bcdc0-8c00-4da5-ab5a-d2d005aba1b7, ignoreFailoverLimit = false) execution failed. Exception: IrsOperationFailedNoFailoverException: IRSGenericException: IRSErrorException: Cannot get file stats: ('7233a711-98e8-4c3c-bcfa-44c4bcc4f6c6',)
2014-07-08 09:58:50,114 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetFileStatsVDSCommand] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] FINISH, GetFileStatsVDSCommand, log id: 1cfee03f
2014-07-08 09:58:50,115 WARN  [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] The refresh process from VDSM, for Floppy files failed.
2014-07-08 09:58:50,115 ERROR [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IrsOperationFailedNoFailoverException: IRSGenericException: IRSErrorException: Cannot get file stats: ('7233a711-98e8-4c3c-bcfa-44c4bcc4f6c6',) (Failed with error GET_FILE_LIST_ERROR and code 330)
2014-07-08 09:58:50,177 ERROR [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] The following storage domains had a problem retrieving data from VDSM  ( Storage Pool Id: fd0bcdc0-8c00-4da5-ab5a-d2d005aba1b7 Storage domain Id: 7233a711-98e8-4c3c-bcfa-44c4bcc4f6c6 File type: Floppy) 
2014-07-08 09:58:50,182 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-47) [6e3e0df0] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Refresh image list failed for domain(s):   shared_iso_domain (Floppy file type). Please check domain activity.
2014-07-08 09:58:50,534 INFO  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-1) [7b4b9094-076b-400a_runVmOnce_syncAction] Lock Acquired to object EngineLock [exclusiveLocks= key: 405cc8a6-d557-430b-acb1-e116ab132fd8 value: VM
, sharedLocks= ]
2014-07-08 09:58:50,611 WARN  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-1) CanDoAction of action RunVmOnce failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,ERROR_CANNOT_FIND_ISO_IMAGE_PATH
2014-07-08 09:58:50,612 INFO  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-1) Lock freed to object EngineLock [exclusiveLocks= key: 405cc8a6-d557-430b-acb1-e116ab132fd8 value: VM
, sharedLocks= ]
2014-07-08 09:58:50,620 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp--127.0.0.1-8702-1) Operation Failed: [Invalid ISO image path]
2014-07-08 09:58:51,625 INFO  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-6) [20725ae1-888c-4a54_runVmOnce_syncAction] Lock Acquired to object EngineLock [exclusiveLocks= key: 405cc8a6-d557-430b-acb1-e116ab132fd8 value: VM
, sharedLocks= ]
2014-07-08 09:58:51,657 WARN  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-6) CanDoAction of action RunVmOnce failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,ERROR_CANNOT_FIND_FLOPPY_IMAGE_PATH
2014-07-08 09:58:51,658 INFO  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-6) Lock freed to object EngineLock [exclusiveLocks= key: 405cc8a6-d557-430b-acb1-e116ab132fd8 value: VM
, sharedLocks= ]
2014-07-08 09:58:51,664 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp--127.0.0.1-8702-6) Operation Failed: [Invalid Floppy image path]
2014-07-08 09:58:52,756 INFO  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-3) [a566da9b-3887-48c3_runVmOnce_syncAction] Lock Acquired to object EngineLock [exclusiveLocks= key: 405cc8a6-d557-430b-acb1-e116ab132fd8 value: VM
, sharedLocks= ]
Comment 1 Ilanit Stein 2014-07-09 08:23:46 UTC 
Created attachment 916672 [details]
logs

See Failure aroung Aug 7, 09:58
Comment 2 Michal Skrivanek 2014-07-10 06:45:50 UTC 
seems like some storage/IOProcess issue:

Thread-37::ERROR::2014-07-08 09:58:50,102::dispatcher::79::Storage.Dispatcher::(wrapper) '_IOProcessFileUtils' object has no attribute 'validateQemuReadable'
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 71, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 103, in wrapper
    return m(self, *a, **kw)
  File "/usr/share/vdsm/storage/task.py", line 1179, in prepare
    raise self.error
AttributeError: '_IOProcessFileUtils' object has no attribute 'validateQemuReadable'


also a ridiculous amount of IOProcess::(_processLogs) log lines!
Comment 4 Allon Mureinik 2014-07-10 18:35:45 UTC 
(In reply to Michal Skrivanek from comment #2)
> seems like some storage/IOProcess issue:
hence, infra.
Comment 5 Yeela Kaplan 2014-07-13 07:45:28 UTC 

*** This bug has been marked as a duplicate of bug 1114499 ***