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

Solution In Progress - Updated -

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.]

Environment

Red Hat Enterprise Virtualization
3.3

Subscriber exclusive content

A Red Hat subscription provides unlimited access to our knowledgebase of over 48,000 articles and solutions.

Current Customers and Partners

Log in for full access

Log In
Close

Welcome! Check out the Getting Started with Red Hat page for quick tours and guides for common tasks.