Bug 1185865 - [JSON] Force extend block domain, in JSONRPC, using a "dirty" LUN, fail
Summary: [JSON] Force extend block domain, in JSONRPC, using a "dirty" LUN, fail
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine
Version: 3.5.0
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ovirt-3.6.0-rc
: 3.6.0
Assignee: Fred Rolland
QA Contact: Ori Gofen
URL:
Whiteboard:
Depends On: 1215427 1218657
Blocks: 1186410
TreeView+ depends on / blocked
 
Reported: 2015-01-26 13:35 UTC by Ori Gofen
Modified: 2016-03-10 11:58 UTC (History)
14 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1186410 (view as bug list)
Environment:
Last Closed: 2016-03-10 10:33:39 UTC
oVirt Team: Storage
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
logs (1.02 MB, application/x-gzip)
2015-01-26 13:35 UTC, Ori Gofen
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 37320 0 master MERGED core: JSON-RPC extend storage domain failure Never

Description Ori Gofen 2015-01-26 13:35:36 UTC
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.

Comment 1 Allon Mureinik 2015-01-27 06:22:45 UTC
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?

Comment 2 Piotr Kliczewski 2015-01-27 08:55:26 UTC
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?

Comment 3 Allon Mureinik 2015-01-27 10:09:46 UTC
Tal - Please have someone look into this - I'll be backed up with meetings all day.

Comment 4 Tal Nisan 2015-01-27 15:03:50 UTC
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

Comment 6 Gilad Lazarovich 2015-02-19 09:16:23 UTC
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

Comment 7 Ori Gofen 2015-04-26 13:47:48 UTC
can't verify this one due to bz #1215427, the operation of 'force extend block domain' fails, but due to other issue.

Comment 8 Ori Gofen 2015-05-05 16:29:55 UTC
verified on oVirt 3.6 master

Comment 9 Allon Mureinik 2016-03-10 10:33:39 UTC
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE

Comment 10 Allon Mureinik 2016-03-10 10:36:05 UTC
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE

Comment 11 Allon Mureinik 2016-03-10 10:41:41 UTC
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE

Comment 12 Allon Mureinik 2016-03-10 11:58:35 UTC
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE


Note You need to log in before you can comment on or make changes to this bug.