Created attachment 984216 [details] logs Description of problem: Force extend Block domain operation fails on ExtendSANStorageDomainCommand with "Failed to initialize physical device", this issue is a json-rpc issue and does not reproduce when using xml-rpc engine logs: 2015-01-26 15:09:46,677 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.ExtendStorageDomainVDSCommand] (ajp-/127.0.0.1:8702-12) [63e5c86a] Failed in ExtendStorageDomainVDS method 2015-01-26 15:09:46,678 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8702-12) [63e5c86a] IrsBroker::Failed::ExtendStorageDomainVDS due to: IRSErrorException: IRSGenericException: IRSErrorException: Failed to ExtendStorageDomainVDS, error = Failed to initialize physical device: ("[u'/dev/mapper/360060160f4a03000fb65675991dbe311', u'/dev/mapper/360060160f4a03000fa65675991dbe311', u'/dev/mapper/360060160f4a03000fc65675991dbe311', u'/dev/mapper/360060160f4a03000fe65675991dbe311', u'/dev/mapper/360060160f4a030007aeed85291dbe311', u'/dev/mapper/360060160f4a030007eeed85291dbe311', u'/dev/mapper/360060160f4a03000fd65675991dbe311']",), code = 601 2015-01-26 15:09:46,689 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.ExtendStorageDomainVDSCommand] (ajp-/127.0.0.1:8702-12) [63e5c86a] FINISH, ExtendStorageDomainVDSCommand, log id: 14c5ab7f 2015-01-26 15:09:46,689 ERROR [org.ovirt.engine.core.bll.storage.ExtendSANStorageDomainCommand] (ajp-/127.0.0.1:8702-12) [63e5c86a] Command org.ovirt.engine.core.bll.storage.ExtendSANStorageDomainCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IRSErrorException: IRSGenericException: IRSErrorException: Failed to ExtendStorageDomainVDS, error = Failed to initialize physical device: ("[u'/dev/mapper/360060160f4a03000fb65675991dbe311', u'/dev/mapper/360060160f4a03000fa65675991dbe311', u'/dev/mapper/360060160f4a03000fc65675991dbe311', u'/dev/mapper/360060160f4a03000fe65675991dbe311', u'/dev/mapper/360060160f4a030007aeed85291dbe311', u'/dev/mapper/360060160f4a030007eeed85291dbe311', u'/dev/mapper/360060160f4a03000fd65675991dbe311']",), code = 601 (Failed with error PhysDevInitializationError and code 601) 2015-01-26 15:09:46,695 INFO [org.ovirt.engine.core.bll.storage.ExtendSANStorageDomainCommand] (ajp-/127.0.0.1:8702-12) [63e5c86a] Command [id=9932a8a5-a0aa-4c8d-bffe-8f27d9a5ead4]: Compensating CHANGED_STATUS_ONLY of org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap; snapshot: EntityStatusSnapshot [id=storagePoolId = 00000002-0002-0002-0002-000000000278, storageId = b7abc844-5f5a-4bd9-a260-20012106086e, status=Active]. 2015-01-26 15:09:46,701 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-12) [63e5c86a] Correlation ID: 6b6e3c84, Job ID: 8ec1ade1-37cf-496a-b86c-9ecfa16c7dc6, Call Stack: null, Custom Event ID: -1, Message: Failed to extend Storage Domain iSCSi_1. (User: admin) Version-Release number of selected component (if applicable): vt13.8 How reproducible: 100% Steps to Reproduce: 1.extend a Block domain, choose Luns containing "old" storage metadata 2.engine prompts a warning window the notifies the user about data going to be lost, mark the "are you sure" flag. Actual results: operation fails Expected results: operation successful Additional info: not sure if it's a regression or not, probably regression.
Tentatively marking for 3.5.0-1 if a basic flow is indeed broken in JSONRPC. Piotr, if the same flow works in XMLRPC but doesn't in JSONRPC, perhaps something is wrong with the argument marshalling?
Looking at the log I can see for jsonrpc: The engine: 2015-01-26 15:09:46,689 ERROR [org.ovirt.engine.core.bll.storage.ExtendSANStorageDomainCommand] (ajp-/127.0.0.1:8702-12) [63e5c86a] Command org.ovirt.engine.core.bll.storage.ExtendSANStorageDomainCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IRSErrorException: IRSGenericException: IRSErrorException: Failed to ExtendStorageDomainVDS, error = Failed to initialize physical device: ("[u'/dev/mapper/360060160f4a03000fb65675991dbe311', u'/dev/mapper/360060160f4a03000fa65675991dbe311', u'/dev/mapper/360060160f4a03000fc65675991dbe311', u'/dev/mapper/360060160f4a03000fe65675991dbe311', u'/dev/mapper/360060160f4a030007aeed85291dbe311', u'/dev/mapper/360060160f4a030007eeed85291dbe311', u'/dev/mapper/360060160f4a03000fd65675991dbe311']",), code = 601 (Failed with error PhysDevInitializationError and code 601) and vdsm Thread-662::ERROR::2015-01-26 15:09:46,646::task::866::Storage.TaskManager.Task::(_setError) Task=`93b0c688-bedc-4f4c-b03a-0917584584f1`::Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 873, in _run return fn(*args, **kargs) File "/usr/share/vdsm/logUtils.py", line 45, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 740, in extendStorageDomain pool.extendSD(sdUUID, dmDevs, force) File "/usr/share/vdsm/storage/securable.py", line 77, in wrapper return method(self, *args, **kwargs) File "/usr/share/vdsm/storage/sp.py", line 1911, in extendSD sdCache.produce(sdUUID).extend(devlist, force) File "/usr/share/vdsm/storage/blockSD.py", line 719, in extend lvm.extendVG(self.sdUUID, devlist, force) File "/usr/share/vdsm/storage/lvm.py", line 957, in extendVG _initpvs(pvs, int(vg.vg_mda_size) / 2 ** 20, force) File "/usr/share/vdsm/storage/lvm.py", line 729, in _initpvs raise se.PhysDevInitializationError(str(devices)) PhysDevInitializationError: Failed to initialize physical device: ("[u'/dev/mapper/360060160f4a03000fb65675991dbe311', u'/dev/mapper/360060160f4a03000fa65675991dbe311', u'/dev/mapper/360060160f4a03000fc65675991dbe311', u'/dev/mapper/360060160f4a03000fe65675991dbe311', u'/dev/mapper/360060160f4a030007aeed85291dbe311', u'/dev/mapper/360060160f4a030007eeed85291dbe311', u'/dev/mapper/360060160f4a03000fd65675991dbe311']",) It looks like the error was sent OK. Looking at request sent I can see in the engine: 2015-01-26 15:09:42,580 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.ExtendStorageDomainVDSCommand] (ajp-/127.0.0.1:8702-12) [63e5c86a] START, ExtendStorageDomainVDSCommand( storagePoolId = 00000002-0002-0002-0002-000000000278, ignoreFailoverLimit = false, storageDomainId = b7abc844-5f5a-4bd9-a260-20012106086e, deviceList = [360060160f4a03000fb65675991dbe311, 360060160f4a03000fa65675991dbe311, 360060160f4a03000fc65675991dbe311, 360060160f4a03000fe65675991dbe311, 360060160f4a030007aeed85291dbe311, 360060160f4a030007eeed85291dbe311, 360060160f4a03000fd65675991dbe311]) and vdsm: Thread-662::DEBUG::2015-01-26 15:09:42,558::__init__::469::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StorageDomain.extend' in bridge with {u'devlist': [u'360060160f4a03000fb65675991dbe311', u'360060160f4a03000fa65675991dbe311', u'360060160f4a03000fc65675991dbe311', u'360060160f4a03000fe65675991dbe311', u'360060160f4a030007aeed85291dbe311', u'360060160f4a030007eeed85291dbe311', u'360060160f4a03000fd65675991dbe311'], u'storagepoolID': u'00000002-0002-0002-0002-000000000278', u'force': u'true', u'storagedomainID': u'b7abc844-5f5a-4bd9-a260-20012106086e'} The args looks the same on both ends. Can you please check PhysDevInitializationError?
Tal - Please have someone look into this - I'll be backed up with meetings all day.
This bug happens when trying to extend an existing block storage domain with a LUN that contains metadata from an old storage domain that existed on it and only via json-rpc, this is a corner case of a corner case thus moving to 3.5.1
Please note that getting a dirty LUN happens very frequently in Automation due to bug https://bugzilla.redhat.com/show_bug.cgi?id=1154425, so fixing this bug becomes even more important
can't verify this one due to bz #1215427, the operation of 'force extend block domain' fails, but due to other issue.
verified on oVirt 3.6 master
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE