RHEV data center SPM failure + failover failure broke all storage domains

Issue

RHEV 3.3.4 data center instance encountered a SPM failure 08/04/2014 @ ~1546CDT during continuous starting of guests, which broke all of its storage domains. The catalyst seems to be a RHEV-M -> hypervisor VDSM SSL socket timeout/failure that we've seen occurring randomly in this instance/data center.

uxqavrh0040d was the SPM for rv-qa-dc3-dc01 until 15:46:21CDT when the RHEV-M logs a failed call to UpdateVMVDS due to timeout. uxqavrh0066d is selected as the new SPM, but the failover doesn't seem successful as subsequent CreateVDSCommands are encountering storage domain illegal state / inaccessible errors.

This continues for a while. Over the subsequent ~2 hours the data center experiences similar SPM failovers. At the moment it seems functional as guests can be started.

From engine.log on RHEV-M abc:

2014-08-04 15:45:54,057 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-96) [75b9ad98] FINISH, FullListVds
Command, return: [Ljava.util.HashMap;@69bcb658, log id: eb9e90f
2014-08-04 15:45:56,727 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-34) [1fdb1573] VM qa0685d 1416e71d-b6be-4e
db-9ccd-dc13510217db moved from PoweringUp --> Up
2014-08-04 15:45:56,779 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-34) [1fdb1573] Correlation
 ID: 553f50c, Job ID: c64b8edd-151a-4468-9ebb-d03b2f90cfa3, Call Stack: null, Custom Event ID: -1, Message: VM qa0685d started on Host uxqavrh0004d
2014-08-04 15:46:06,464 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8702-9) Running command: LoginUserCommand internal: false.
2014-08-04 15:46:06,569 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp-/127.0.0.1:8702-8) [ed28aef] org.ovirt.engine.core.vdsbroker.v
dsbroker.CreateVDSCommand spiceSslCipherSuite=DEFAULT,memSize=51200,kvmEnable=true,smp=4,vmType=kvm,emulatedMachine=rhel6.5.0,keyboardLayout=en-us,memGuarante
edSize=51200,pitReinjection=false,nice=0,display=vnc,smartcardEnable=false,tabletEnable=true,smpCoresPerSocket=4,spiceSecureChannels=smain,sinputs,scursor,spl
ayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=0,transparentHugePages=true,vmId=35685b22-8d8e-4575-8373-7081fd05ee2b,devices=[Ljava.util.HashMap;@767
4f79c,acpiEnable=true,vmName=qa0688d,cpuType=SandyBridge,custom={device_aa9b7f5a-729e-4442-aeec-57788d7364e9device_eb902c12-1d1d-4733-bd48-7b2b2d18646b=VmDevi
ce {vmId=35685b22-8d8e-4575-8373-7081fd05ee2b, deviceId=eb902c12-1d1d-4733-bd48-7b2b2d18646b, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={
port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}, device_aa9b7f5a-729e-4442-aeec-57788d7364e9device_eb902c12-1d1d-4733-bd48-7b2b2d18646bdevice_845f5c7b-4c24-48bb-a123-5119b79fe3cadevice_8e60bfe8-6235-4d63-a5f2-aeff03662939=VmDevice {vmId=35685b22-8d8e-4575-8373-7081fd05ee2b, deviceId=8e60bfe8-6235-4d63-a5f2-aeff03662939, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}, device_aa9b7f5a-729e-4442-aeec-57788d7364e9device_eb902c12-1d1d-4733-bd48-7b2b2d18646bdevice_845f5c7b-4c24-48bb-a123-5119b79fe3ca=VmDevice {vmId=35685b22-8d8e-4575-8373-7081fd05ee2b, deviceId=845f5c7b-4c24-48bb-a123-5119b79fe3ca, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}, device_aa9b7f5a-729e-4442-aeec-57788d7364e9=VmDevice {vmId=35685b22-8d8e-4575-8373-7081fd05ee2b, deviceId=aa9b7f5a-729e-4442-aeec-57788d7364e9, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}}
2014-08-04 15:46:06,569 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp-/127.0.0.1:8702-8) [ed28aef] FINISH, CreateVDSCommand, log id: 5adebe48
2014-08-04 15:46:06,579 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-9) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-vdsmhook logged in.
2014-08-04 15:46:06,686 INFO  [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp-/127.0.0.1:8702-8) [ed28aef] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 7ef443a9
2014-08-04 15:46:06,686 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-8) [ed28aef] Lock freed to object EngineLock [exclusiveLocks= key: 35685b22-8d8e-4575-8373-7081fd05ee2b value: VM
, sharedLocks= ]
2014-08-04 15:46:06,749 INFO  [org.ovirt.engine.core.bll.LogoutUserCommand] (ajp-/127.0.0.1:8702-9) [5d211d1c] Running command: LogoutUserCommand internal: false.
2014-08-04 15:46:06,754 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-8) [ed28aef] Correlation ID: ed28aef, Job ID: 32c2d96d-a9c6-4915-a9bb-1f2e5d2636bf, Call Stack: null, Custom Event ID: -1, Message: VM qa0688d was started by esp-qa-rhev-prov (Host: uxqavrh0023d).
2014-08-04 15:46:06,772 INFO  [org.ovirt.engine.core.bll.LogoutUserCommand] (ajp-/127.0.0.1:8702-8) [4630bb41] Running command: LogoutUserCommand internal: false.
2014-08-04 15:46:06,825 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-9) [5d211d1c] Correlation ID: 5d211d1c, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-vdsmhook logged out.
2014-08-04 15:46:06,848 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-8) [4630bb41] Correlation ID: 4630bb41, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-prov logged out.
2014-08-04 15:46:08,197 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8702-6) Running command: LoginUserCommand internal: false.
2014-08-04 15:46:08,301 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-6) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-prov logged in.
2014-08-04 15:46:09,103 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] Lock Acquired to object EngineLock [exclusiveLocks= key: f2c0f10c-43a3-4b65-b054-dd6c7579f6d7 value: VM
, sharedLocks= ]
2014-08-04 15:46:09,168 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] START, IsVmDuringInitiatingVDSCommand( vmId = f2c0f10c-43a3-4b65-b054-dd6c7579f6d7), log id: 53f5e2f9
2014-08-04 15:46:09,168 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 53f5e2f9
2014-08-04 15:46:10,108 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] Running command: RunVmCommand internal: false. Entities affected :  ID: f2c0f10c-43a3-4b65-b054-dd6c7579f6d7 Type: VM
2014-08-04 15:46:11,839 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8702-3) Running command: LoginUserCommand internal: false.
2014-08-04 15:46:11,936 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-3) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-sched logged in.
2014-08-04 15:46:17,674 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] START, IsoPrefixVDSCommand(HostName = uxqavrh0008d, HostId = cdaccf36-fec9-4011-8b63-a8fccf3129f1, storagePoolId=ef37a082-5b76-4f68-8327-057dfe154c47), log id: 1a65533e
2014-08-04 15:46:17,897 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-72) [7c5bc8f9] VM qa0688d 35685b22-8d8e-4575-8373-7081fd05ee2b moved from WaitForLaunch --> PoweringUp
2014-08-04 15:46:17,926 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-72) [7c5bc8f9] START, FullListVdsCommand(HostName = uxqavrh0023d, HostId = da946b2e-cea5-4d2c-9a81-db1629adb9a0, vds=Host[uxqavrh0023d], vmIds=[35685b22-8d8e-4575-8373-7081fd05ee2b]), log id: 195f9a05
2014-08-04 15:46:18,116 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] FINISH, IsoPrefixVDSCommand, return: , log id: 1a65533e
2014-08-04 15:46:18,177 INFO  [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] START, CreateVmVDSCommand(HostName = uxqavrh0008d, HostId = cdaccf36-fec9-4011-8b63-a8fccf3129f1, vmId=f2c0f10c-43a3-4b65-b054-dd6c7579f6d7, vm=VM [qa0689d]), log id: 66cc4b55
2014-08-04 15:46:19,213 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-72) [7c5bc8f9] FINISH, FullListVdsCommand, return: [Ljava.util.HashMap;@19977c47, log id: 195f9a05
2014-08-04 15:46:20,453 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] START, CreateVDSCommand(HostName = uxqavrh0008d, HostId = cdaccf36-fec9-4011-8b63-a8fccf3129f1, vmId=f2c0f10c-43a3-4b65-b054-dd6c7579f6d7, vm=VM [qa0689d]), log id: 47e17ad5
2014-08-04 15:46:21,323 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-36) [37cf64ad] IrsBroker::Failed::UpdateVMVDS due to: TimeoutException:
2014-08-04 15:46:22,569 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (DefaultQuartzScheduler_Worker-36) [37cf64ad] START, SpmStopVDSCommand(HostName = uxqavrh0040d, HostId = 3434923c-4b36-4751-9630-8abee31e2b44, storagePoolId = ef37a082-5b76-4f68-8327-057dfe154c47), log id: 7028c0fa
2014-08-04 15:46:22,739 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (DefaultQuartzScheduler_Worker-36) [37cf64ad] SpmStopVDSCommand::Stopping SPM on vds uxqavrh0040d, pool id ef37a082-5b76-4f68-8327-057dfe154c47
2014-08-04 15:46:22,935 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (DefaultQuartzScheduler_Worker-36) [37cf64ad] FINISH, SpmStopVDSCommand, log id: 7028c0fa
2014-08-04 15:46:22,935 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-36) [37cf64ad] Irs placed on server 3434923c-4b36-4751-9630-8abee31e2b44 failed. Proceed Failover
2014-08-04 15:46:23,342 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-80) [25e7b28] VM qa0686d ddfdd4ed-7293-48c0-acdb-25f63f47058a moved from PoweringUp --> Up
2014-08-04 15:46:23,463 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-80) [25e7b28] Correlation ID: 4f97e0a4, Job ID: 41ae085c-adba-473a-9033-afacb987f686, Call Stack: null, Custom Event ID: -1, Message: VM qa0686d started on Host uxqavrh0040d
2014-08-04 15:46:23,966 INFO  [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] Running command: SetStoragePoolStatusCommand internal: true. Entities affected :  ID: ef37a082-5b76-4f68-8327-057dfe154c47 Type: StoragePool
2014-08-04 15:46:24,042 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-36) [59c28e0d] Correlation ID: 59c28e0d, Call Stack: null, Custom Event ID: -1, Message: Data Center is being initialized, please wait for initialization to complete.
2014-08-04 15:46:24,425 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] hostFromVds::selectedVds - uxqavrh0066d, spmStatus Free, storage pool rv-qa-dc3-dc01
2014-08-04 15:46:24,431 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] SPM Init: could not find reported vds or not up - pool:rv-qa-dc3-dc01 vds_spm_id: 66
2014-08-04 15:46:24,455 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] SPM selection - vds seems as spm uxqavrh0040d
2014-08-04 15:46:24,472 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] START, SpmStopVDSCommand(HostName = uxqavrh0040d, HostId = 3434923c-4b36-4751-9630-8abee31e2b44, storagePoolId = ef37a082-5b76-4f68-8327-057dfe154c47), log id: 50242df1
2014-08-04 15:46:24,660 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value

TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]

2014-08-04 15:46:24,676 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] HostName = uxqavrh0040d
2014-08-04 15:46:24,676 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] Command HSMGetAllTasksStatusesVDS execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM
2014-08-04 15:46:24,676 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] FINISH, SpmStopVDSCommand, log id: 50242df1
2014-08-04 15:46:24,676 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] spm stop succeeded, continuing with spm selection
2014-08-04 15:46:24,692 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] starting spm on vds uxqavrh0066d, storage pool rv-qa-dc3-dc01, prevId 66, LVER 126
2014-08-04 15:46:24,711 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] START, SpmStartVDSCommand(HostName = uxqavrh0066d, HostId = c58b626a-266a-4a32-88ca-f7118bf9a61a, storagePoolId = ef37a082-5b76-4f68-8327-057dfe154c47, prevId=66, prevLVER=126, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=true), log id: 4491d992
2014-08-04 15:46:25,163 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] spmStart polling st
arted: taskId = 8bf8f8cc-9c81-41e9-9d75-3afc0e5249c5
2014-08-04 15:46:26,449 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] spmStart polling ended: taskId = 8bf8f8cc-9c81-41e9-9d75-3afc0e5249c5 task status = finished
2014-08-04 15:46:26,744 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] spmStart polling ended, spm status: SPM
2014-08-04 15:46:26,763 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] START, HSMClearTaskVDSCommand(HostName = uxqavrh0066d, HostId = c58b626a-266a-4a32-88ca-f7118bf9a61a, taskId=8bf8f8cc-9c81-41e9-9d75-3afc0e5249c5), log id: b7dc2de
2014-08-04 15:46:27,088 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] FINISH, HSMClearTaskVDSCommand, log id: b7dc2de
2014-08-04 15:46:27,088 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@2e06ee47, log id: 4491d992
2014-08-04 15:46:27,108 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-36) [59c28e0d] Initialize Irs proxy from vds: abc.acme.com
2014-08-04 15:46:27,176 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-36) [59c28e0d] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Storage Pool Manager runs on Host uxqavrh0066d (Address: abc.acme.com).
2014-08-04 15:46:27,218 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] (pool-4-thread-99) [59c28e0d] START, SPMGetAllTasksInfoVDSCommand( storagePoolId = ef37a082-5b76-4f68-8327-057dfe154c47, ignoreFailoverLimit = false), log id: 462bb59
2014-08-04 15:46:30,630 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=DEFAULT,memSize=51200,kvmEnable=true,smp=4,vmType=kvm,emulatedMachine=rhel6.5.0,keyboardLayout=en-us,memGuaranteedSize=51200,pitReinjection=false,nice=0,display=vnc,smartcardEnable=false,tabletEnable=true,smpCoresPerSocket=4,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,timeOffset=0,transparentHugePages=true,vmId=f2c0f10c-43a3-4b65-b054-dd6c7579f6d7,devices=[Ljava.util.HashMap;@295528ab,acpiEnable=true,vmName=qa0689d,cpuType=SandyBridge,custom={device_ac9a353f-851d-407a-b5a0-2c88cbfd3bd9device_c3d5c8a3-0e64-4771-9e9d-aca7597640f9device_3694535b-9ca5-4994-8063-929e99096399=VmDevice {vmId=f2c0f10c-43a3-4b65-b054-dd6c7579f6d7, deviceId=3694535b-9ca5-4994-8063-929e99096399, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}, device_ac9a353f-851d-407a-b5a0-2c88cbfd3bd9=VmDevice {vmId=f2c0f10c-43a3-4b65-b054-dd6c7579f6d7, deviceId=ac9a353f-851d-407a-b5a0-2c88cbfd3bd9, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}, device_ac9a353f-851d-407a-b5a0-2c88cbfd3bd9device_c3d5c8a3-0e64-4771-9e9d-aca7597640f9=VmDevice {vmId=f2c0f10c-43a3-4b65-b054-dd6c7579f6d7, deviceId=c3d5c8a3-0e64-4771-9e9d-aca7597640f9, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}, device_ac9a353f-851d-407a-b5a0-2c88cbfd3bd9device_c3d5c8a3-0e64-4771-9e9d-aca7597640f9device_3694535b-9ca5-4994-8063-929e99096399device_991ebfc8-bcc1-4ad7-94a6-99511e80d66a=VmDevice {vmId=f2c0f10c-43a3-4b65-b054-dd6c7579f6d7, deviceId=991ebfc8-bcc1-4ad7-94a6-99511e80d66a, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}}
2014-08-04 15:46:30,630 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] FINISH, CreateVDSCommand, log id: 47e17ad5
2014-08-04 15:46:30,720 INFO  [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 66cc4b55
2014-08-04 15:46:30,720 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-10) [7b671b43] Lock freed to object EngineLock [exclusiveLocks= key: f2c0f10c-43a3-4b65-b054-dd6c7579f6d7 value: VM , sharedLocks= ]
2014-08-04 15:46:30,768 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-10) [7b671b43] Correlation ID: 7b671b43, Job ID: c860dc36-79e4-4c40-992f-814f7e09692c, Call Stack: null, Custom Event ID: -1, Message: VM qa0689d was started by esp-qa-rhev-prov (Host: uxqavrh0008d).
2014-08-04 15:46:30,870 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8702-8) Running command: LoginUserCommand internal: false.
2014-08-04 15:46:30,965 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-8) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-vdsmhook logged in.
2014-08-04 15:46:31,127 INFO  [org.ovirt.engine.core.bll.LogoutUserCommand] (ajp-/127.0.0.1:8702-8) [c9059fb] Running command: LogoutUserCommand internal: false.
2014-08-04 15:46:31,201 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-8) [c9059fb] Correlation ID: c9059fb, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-vdsmhook logged out.
2014-08-04 15:46:32,119 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8702-6) Running command: LoginUserCommand internal: false.
2014-08-04 15:46:32,200 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-6) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-prov logged in.
2014-08-04 15:46:32,956 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-3) [78832a70] Lock Acquired to object EngineLock [exclusiveLocks= key: 49a2d3c0-4009-4124-b8ae-9baa83b0f005 value: VM
, sharedLocks= ]
2014-08-04 15:46:33,012 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8702-3) [78832a70] START, IsVmDuringInitiatingVDSCommand( vmId = 49a2d3c0-4009-4124-b8ae-9baa83b0f005), log id: 12e4f9ca
2014-08-04 15:46:33,012 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8702-3) [78832a70] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 12e4f9ca
2014-08-04 15:46:33,049 WARN  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-3) [78832a70] CanDoAction of action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,ACTION_TYPE_FAILED_STORAGE_DOMAIN_STATUS_ILLEGAL
2014-08-04 15:46:33,050 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-3) [78832a70] Lock freed to object EngineLock [exclusiveLocks= key: 49a2d3c0-4009-4124-b8ae-9baa83b0f005 value: VM
, sharedLocks= ]
2014-08-04 15:46:33,141 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8702-3) Operation Failed: [Cannot run VM. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.]
2014-08-04 15:46:34,459 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8702-10) Running command: LoginUserCommand internal: false.
2014-08-04 15:46:34,562 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-10) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User esp-qa-rhev-prov logged in.
2014-08-04 15:46:35,326 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-9) [12324720] Lock Acquired to object EngineLock [exclusiveLocks= key: b5eaf766-703d-4958-b93b-46e42b58dd21 value: VM
, sharedLocks= ]
2014-08-04 15:46:35,378 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8702-9) [12324720] START, IsVmDuringInitiatingVDSCommand( vmId = b5eaf766-703d-4958-b93b-46e42b58dd21), log id: fa74fdb
2014-08-04 15:46:35,378 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8702-9) [12324720] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: fa74fdb
2014-08-04 15:46:35,401 WARN  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-9) [12324720] CanDoAction of action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,ACTION_TYPE_FAILED_STORAGE_DOMAIN_STATUS_ILLEGAL
2014-08-04 15:46:35,401 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-9) [12324720] Lock freed to object EngineLock [exclusiveLocks= key: b5eaf766-703d-4958-b93b-46e42b58dd21 value: VM
, sharedLocks= ]
2014-08-04 15:46:35,495 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8702-9) Operation Failed: [Cannot run VM. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.]