Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1176417

Summary: [engine-backend] After reconstruct, no SPM in DC while master domain is active
Product: Red Hat Enterprise Virtualization Manager Reporter: Elad <ebenahar>
Component: ovirt-engineAssignee: Liron Aravot <laravot>
Status: CLOSED CURRENTRELEASE QA Contact: Aharon Canan <acanan>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 3.5.0CC: amureini, ebenahar, ecohen, fsimonce, gklein, iheim, laravot, lpeer, lsurette, rbalakri, Rhev-m-bugs, scohen, tnisan, yeylon
Target Milestone: ---   
Target Release: 3.5.0   
Hardware: x86_64   
OS: Unspecified   
Whiteboard: storage
Fixed In Version: vt13.5 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1176407    
Bug Blocks:    
Attachments:
Description Flags
logs from host and engine
none
pg_dump
none
pg_dump (correct)
none
after engine restart
none
logs - 23.12.14 none

Description Elad 2014-12-21 15:22:56 UTC
Created attachment 971740 [details]
logs from host and engine

Description of problem:
I got to a scenario in which after reconstruct master succeeded and the new master became active, the host didn't take SPM.
I tried to maintenance the host and nothing happened. Tried also to manually select it as SPM, didn't help either.

Version-Release number of selected component (if applicable):
host and engine: rhel6.6

rhev 3.5 vt13.4

rhevm-3.5.0-0.26.el6ev.noarch

vdsm-4.16.8.1-4.el6ev.x86_64
libvirt-0.10.2-46.el6_6.2.x86_64
qemu-kvm-rhev-0.12.1.2-2.448.el6.x86_64
selinux-policy-3.7.19-260.el6_6.1.noarch
sanlock-2.8-1.el6.x86_64


How reproducible:
Tested once

Steps to Reproduce:
Have 2 storage domains in DC, 1 NFS (master) and 1 iSCSI. One host in DC
1. Block connectivity to master domain, wait for reconstruct to finish
2. Once reconstruct is funuished, put the host in maintenance.

Actual results:

Reconstruct finished successfully:

2014-12-21 16:14:25,781 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-1) [5cb67019] Correlation ID: 5cb67019, Job ID: d27e7a73-5517-400a-9271-164f2d00
d666, Call Stack: null, Custom Event ID: -1, Message: Reconstruct Master Domain for Data Center Default completed.

Set the host in maintenance:

2014-12-21 16:16:28,655 INFO  [org.ovirt.engine.core.bll.MaintenanceNumberOfVdssCommand] (org.ovirt.thread.pool-7-thread-3) [39640578] Running command: MaintenanceNumberOfVdssCommand internal: false. Entities affe
cted :  ID: ede38ee8-6f30-42d9-afa1-274b45dcbf11 Type: VDSAction group MANIPULATE_HOST with role type ADMIN
2014-12-21 16:16:28,658 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (org.ovirt.thread.pool-7-thread-3) [39640578] START, SetVdsStatusVDSCommand(HostName = green-vdsc, HostId = ede38ee8-6f30-42d9
-afa1-274b45dcbf11, status=PreparingForMaintenance, nonOperationalReason=NONE, stopSpmFailureLogged=true), log id: 6e7ae0c3



The maintenance host operation never completed. The host remains 'up' and there is no SPM in the DC. The master domain is active.



[root@green-vdsc images]# vdsClient -s 0 getSpmStatus 00000002-0002-0002-0002-0000000000f0
        spmId = -1
        spmStatus = Free
        spmLver = -1


[root@green-vdsc images]# vdsClient -s 0 getStorageDomainInfo 0151588f-b974-4a3d-996b-4518bfc4bcfa
        uuid = 0151588f-b974-4a3d-996b-4518bfc4bcfa
        vguuid = AjWjsa-OIJU-nwSc-1xi4-035a-mGRp-AFjBif
        state = OK
        version = 3
        role = Master
        type = ISCSI
        class = Data
        pool = ['00000002-0002-0002-0002-0000000000f0']
        name = iscsi1


[root@green-vdsc images]# vdsClient -s 0 getVGInfo AjWjsa-OIJU-nwSc-1xi4-035a-mGRp-AFjBif

============================
vgsize = 58653147136 
============================
name = 0151588f-b974-4a3d-996b-4518bfc4bcfa 
============================
vgUUID = AjWjsa-OIJU-nwSc-1xi4-035a-mGRp-AFjBif 
============================
pvlist:
vendorID = XtremIO  capacity = 58653147136  fwrev = 0000  vgUUID = AjWjsa-OIJU-nwSc-1xi4-035a-mGRp-AFjBif  pathlist = [{'connection': '10.35.146.129', 'iqn': 'iqn.2008-05.com.xtremio:001e675b8ee0', 'portal': '1', 'port': '3260', 'initiatorname': 'default'}, {'connection': '10.35.146.161', 'iqn': 'iqn.2008-05.com.xtremio:001e675b8ee1', 'portal': '1', 'port': '3260', 'initiatorname': 'default'}, {'connection': '10.35.146.193', 'iqn': 'iqn.2008-05.com.xtremio:001e675ba170', 'portal': '1', 'port': '3260', 'initiatorname': 'default'}, {'connection': '10.35.146.225', 'iqn': 'iqn.2008-05.com.xtremio:001e675ba171', 'portal': '1', 'port': '3260', 'initiatorname': 'default'}]  pathstatus = [{'physdev': 'sdd', 'type': 'iSCSI', 'state': 'active', 'lun': '5'}, {'physdev': 'sdf', 'type': 'iSCSI', 'state': 'active', 'lun': '5'}, {'physdev': 'sdh', 'type': 'iSCSI', 'state': 'active', 'lun': '5'}, {'physdev': 'sdj', 'type': 'iSCSI', 'state': 'active', 'lun': '5'}]  devtype = iSCSI  pvUUID = uvHCoM-pMgK-VIIv-yOyr-yc6V-yDAS-ISRujw  serial = SXtremIO_XtremApp_PSNT_Not_Set  GUID = 3514f0c5447600864  devcapacity = 59055800320  productID = XtremApp 
============================
state = OK 
============================
vgfree = 54492397568 
============================
type = 3 
============================
attr = {'partial': '-', 'permission': 'w', 'allocation': 'n', 'exported': '-', 'clustered': '-', 'resizeable': 'z'} 




I tried also to manually set the host as SPM, didn't work. 

Waited for around 1 hour, nothing had changed.

Expected results:
DC should never be in a state where there is an active master doamain with no SPM.

Additional info: logs from host and engine

Comment 1 Elad 2014-12-21 15:27:16 UTC
Created attachment 971741 [details]
pg_dump

Comment 2 Elad 2014-12-21 15:31:09 UTC
Created attachment 971744 [details]
pg_dump (correct)

Uploaded a wrong file, uploading the right database dump: pg_dump (correct)

Comment 3 Elad 2014-12-21 15:44:07 UTC
Created attachment 971745 [details]
after engine restart

Resterted ovirt-engine service. SpmStop is now called, but spmStart fails on vdsm:

2d80927d-16bc-436e-867b-f1083c75e174::ERROR::2014-12-21 17:39:51,714::task::866::Storage.TaskManager.Task::(_setError) Task=`2d80927d-16bc-436e-867b-f1083c75e174`::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/storage/task.py", line 334, in run
    return self.cmd(*self.argslist, **self.argsdict)
  File "/usr/share/vdsm/storage/sp.py", line 285, in startSpm
    self.masterDomain.createMasterTree()
  File "/usr/share/vdsm/storage/sd.py", line 648, in createMasterTree
    self.oop.fileUtils.createdir(vmsDir)
  File "/usr/share/vdsm/storage/outOfProcess.py", line 150, in createdir
    self._iop.mkdir(tmpPath)
  File "/usr/lib/python2.6/site-packages/ioprocess/__init__.py", line 449, in mkdir
    self.timeout)
  File "/usr/lib/python2.6/site-packages/ioprocess/__init__.py", line 385, in _sendCommand
    raise Timeout(os.strerror(errno.ETIMEDOUT))
Timeout: Connection timed out



2014-12-21 17:38:50,779 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-67) HostName = green-vdsc
2014-12-21 17:38:50,780 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-67) Command HSMGetAllTasksStatusesVDSCommand(HostName = green-vdsc, HostId = ede38ee8-6f30-42d9-afa1-274b45dcbf11) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM
2014-12-21 17:38:50,824 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-21) [46ca3a74] Correlation ID: 348b614e, Job ID: 560a09ef-417f-4a86-a39a-48d3b80b4124, Call Stack: null, Custom Event ID: -1, Message: Failed to activate Storage Domain iscsi1 (Data Center Default) by admin



Attaching the logs

Comment 4 Allon Mureinik 2014-12-21 16:19:53 UTC
Liron, please take a look

Comment 5 Liron Aravot 2014-12-22 07:34:42 UTC
Looking at the issue
Elad, can you please try to run the scenario again on DEBUG log levle to see if you can reproduce?
thanks.

Comment 6 Allon Mureinik 2014-12-22 07:57:28 UTC
(In reply to Liron Aravot from comment #5)
> Looking at the issue
> Elad, can you please try to run the scenario again on DEBUG log levle to see
> if you can reproduce?
> thanks.
Can we please have a page on oVirt's wiki explaining how to do this, and link to it here?
Thanks!

Comment 7 Liron Aravot 2014-12-22 13:57:17 UTC
I've looked into the issue - it could be one of -
1. a deadlock or 
2. transport issue which causes the engine to get stuck while holding the mutex for the vds monitoring and the spm execution.

as we have a jsonRpc bug i suspect that this is the issue rather than a deadlock.
the bug is https://bugzilla.redhat.com/show_bug.cgi?id=1176407.

Elad, please try to reproduce using Json and with XmlRpc - right now i'm marking this one as depends on and not as duplicate just to make sure this scenario is verified once the jsonrpc bug is merged.

Comment 8 Elad 2014-12-23 13:44:57 UTC
Created attachment 972394 [details]
logs - 23.12.14

Tried to reproduce the issue, using JASON-RPC and engine in DEBUG log level. I'm encountering a simillar problem while activating a host. The host should contend for SPM but engine doesn't send spmStart. The DC remains in status 'non-responsive'.

Uploading the logs

Leaving the need-info flag on me, I'll check it also using XML-RPC.


Checked using rhev 3.5 vt13.4

Comment 9 Elad 2014-12-28 12:33:16 UTC
Unable to reproduce using XML-RPC

Comment 10 Allon Mureinik 2014-12-28 12:36:57 UTC
vt13.5 should include a fix to bug 1176407, which according to comment 7 probably also causes this behavior.

Elad - can we retest with JSONRPC on vt13.5 to see if it solved this bug too please?
Thanks!

Comment 11 Elad 2014-12-28 14:42:53 UTC
(In reply to Allon Mureinik from comment #10)
> vt13.5 should include a fix to bug 1176407, which according to comment 7
> probably also causes this behavior.
> 
> Elad - can we retest with JSONRPC on vt13.5 to see if it solved this bug too
> please?
> Thanks!

Tested using vt13.5, with JSON-RPC. I'm not able to reproduce, reconstruct succeeds and DC is recovered.

Comment 12 Allon Mureinik 2014-12-28 14:44:51 UTC
(In reply to Elad from comment #11)
> (In reply to Allon Mureinik from comment #10)
> > vt13.5 should include a fix to bug 1176407, which according to comment 7
> > probably also causes this behavior.
> > 
> > Elad - can we retest with JSONRPC on vt13.5 to see if it solved this bug too
> > please?
> > Thanks!
> 
> Tested using vt13.5, with JSON-RPC. I'm not able to reproduce, reconstruct
> succeeds and DC is recovered.
Elad - thanks!
Setting to VERIFIED based on this comment.

Comment 13 Allon Mureinik 2015-02-16 19:12:13 UTC
RHEV-M 3.5.0 has been released, closing this bug.

Comment 14 Allon Mureinik 2015-02-16 19:12:15 UTC
RHEV-M 3.5.0 has been released, closing this bug.