5:24 p.m.
--------------030406020605090601060306
Content-Type: text/plain; charset="ISO-8859-1"; format=flowed
Content-Transfer-Encoding: 7bit
On 1/26/2014 5:17 PM, Itamar Heim wrote:
On 01/27/2014 12:00 AM, Ted Miller wrote:
>
> On 1/26/2014 4:00 PM, Itamar Heim wrote:
>> On 01/26/2014 10:51 PM, Ted Miller wrote:
>>>
>>> On 1/26/2014 3:10 PM, Itamar Heim wrote:
>>>> On 01/26/2014 10:08 PM, Ted Miller wrote:
>>>>> My Data Center is down, and won't come back up.
>>>>>
>>>>> Data Center Status on the GUI flips between "Non
Responsive" and
>>>>> "Contending"
>>>>>
>>>>> Also noted:
>>>>> Host sometimes seen flipping between "Low" and
"Contending" in SPM
>>>>> column.
>>>>> Storage VM2 "Data (Master)" is in "Cross Data-Center
Status" = Unknown
>>>>> VM2 is "up" under "Volumes" tab
>>>>>
>>>>> Created another volume for VM storage. It shows up in
"volumes" tab,
>>>>> but when I try to add "New Domain" in storage tab, says
that "There
>>>>> are
>>>>> No Data Centers to which the Storage Domain can be attached"
>>>>>
>>>>> Setup:
>>>>> 2 hosts w/ glusterfs storage
>>>>> 1 engine
>>>>> all 3 computers Centos 6.5, just updated
>>>>> ovirt-engine 3.3.0.1-1.el6
>>>>> ovirt-engine-lib 3.3.2-1.el6
>>>>> ovirt-host-deploy.noarch 1.1.3-1.el6
>>>>> glusterfs.x86_64 3.4.2-1.el6
>>>>>
>>>>> This loop seems to repeat in the ovirt-engine log (grep of log
showing
>>>>> only DefaultQuartzScheduler_Worker-79 thread:
>>>>>
>>>>> 2014-01-26 14:44:58,416 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) Irs placed on server
>>>>> 9a591103-83be-4ca9-b207-06929223b541 failed. Proceed Failover
>>>>> 2014-01-26 14:44:58,511 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) hostFromVds::selectedVds -
>>>>> office4a,
>>>>> spmStatus Free, storage pool mill
>>>>> 2014-01-26 14:44:58,550 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) SpmStatus on vds
>>>>> 127ed939-34af-41a8-87a0-e2f6174b1877: Free
>>>>> 2014-01-26 14:44:58,571 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) starting spm on vds office4a,
>>>>> storage
>>>>> pool mill, prevId 2, LVER 15
>>>>> 2014-01-26 14:44:58,579 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) START,
>>>>> SpmStartVDSCommand(HostName =
>>>>> office4a, HostId = 127ed939-34af-41a8-87a0-e2f6174b1877,
>>>>> storagePoolId =
>>>>> 536a864d-83aa-473a-a675-e38aafdd9071, prevId=2, prevLVER=15,
>>>>> storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false),
log
>>>>> id: 74c38eb7
>>>>> 2014-01-26 14:44:58,617 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) spmStart polling started: taskId
=
>>>>> e8986753-fc80-4b11-a11d-6d3470b1728c
>>>>> 2014-01-26 14:45:00,662 ERROR
>>>>>
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) Failed in HSMGetTaskStatusVDS
>>>>> method
>>>>> 2014-01-26 14:45:00,664 ERROR
>>>>>
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) Error code AcquireHostIdFailure
and
>>>>> error message VDSGenericException: VDSErrorException: Failed to
>>>>> HSMGetTaskStatusVDS, error = Cannot acquire host id
>>>>> 2014-01-26 14:45:00,665 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) spmStart polling ended: taskId =
>>>>> e8986753-fc80-4b11-a11d-6d3470b1728c task status = finished
>>>>> 2014-01-26 14:45:00,666 ERROR
>>>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) Start SPM Task failed - result:
>>>>> cleanSuccess, message: VDSGenericException: VDSErrorException:
>>>>> Failed to
>>>>> HSMGetTaskStatusVDS, error = Cannot acquire host id
>>>>> 2014-01-26 14:45:00,695 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) spmStart polling ended, spm
>>>>> status: Free
>>>>> 2014-01-26 14:45:00,702 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) START,
>>>>> HSMClearTaskVDSCommand(HostName = office4a, HostId =
>>>>> 127ed939-34af-41a8-87a0-e2f6174b1877,
>>>>> taskId=e8986753-fc80-4b11-a11d-6d3470b1728c), log id: 336ec5a6
>>>>> 2014-01-26 14:45:00,722 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) FINISH, HSMClearTaskVDSCommand,
log
>>>>> id: 336ec5a6
>>>>> 2014-01-26 14:45:00,724 INFO
>>>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) FINISH, SpmStartVDSCommand,
return:
>>>>>
org.ovirt.engine.core.common.businessentities.SpmStatusResult@13652652,
>>>>>
>>>>> log id: 74c38eb7
>>>>> 2014-01-26 14:45:00,733 INFO
>>>>> [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand]
>>>>> (DefaultQuartzScheduler_Worker-79) Running command:
>>>>> SetStoragePoolStatusCommand internal: true. Entities affected : ID:
>>>>> 536a864d-83aa-473a-a675-e38aafdd9071 Type: StoragePool
>>>>> 2014-01-26 14:45:00,778 ERROR
>>>>> [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>>>> (DefaultQuartzScheduler_Worker-79)
>>>>> IrsBroker::Failed::GetStoragePoolInfoVDS due to:
>>>>> IrsSpmStartFailedException: IRSGenericException: IRSErrorException:
>>>>> SpmStart failed
>>>>>
>>>>> Ted Miller
>>>>> Elkhart, IN, USA
>>>>>
>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> Users mailing list
>>>>> Users(a)ovirt.org
>>>>> http://lists.ovirt.org/mailman/listinfo/users
>>>>>
>>>>
>>>> is this gluster storage (guessing sunce you mentioned a
'volume')
>>> yes (mentioned under "setup" above)
>>>> does it have a quorum?
>>> Volume Name: VM2
>>> Type: Replicate
>>> Volume ID: 7bea8d3b-ec2a-4939-8da8-a82e6bda841e
>>> Status: Started
>>> Number of Bricks: 1 x 3 = 3
>>> Transport-type: tcp
>>> Bricks:
>>> Brick1: 10.41.65.2:/bricks/01/VM2
>>> Brick2: 10.41.65.4:/bricks/01/VM2
>>> Brick3: 10.41.65.4:/bricks/101/VM2
>>> Options Reconfigured:
>>> cluster.server-quorum-type: server
>>> storage.owner-gid: 36
>>> storage.owner-uid: 36
>>> auth.allow: *
>>> user.cifs: off
>>> nfs.disa
>>>> (there were reports of split brain on the domain metadata before when
>>>> no quorum exist for gluster)
>>> after full heal:
>>>
>>> [root@office4a ~]$ gluster volume heal VM2 info
>>> Gathering Heal info on volume VM2 has been successful
>>>
>>> Brick 10.41.65.2:/bricks/01/VM2
>>> Number of entries: 0
>>>
>>> Brick 10.41.65.4:/bricks/01/VM2
>>> Number of entries: 0
>>>
>>> Brick 10.41.65.4:/bricks/101/VM2
>>> Number of entries: 0
>>> [root@office4a ~]$ gluster volume heal VM2 info split-brain
>>> Gathering Heal info on volume VM2 has been successful
>>>
>>> Brick 10.41.65.2:/bricks/01/VM2
>>> Number of entries: 0
>>>
>>> Brick 10.41.65.4:/bricks/01/VM2
>>> Number of entries: 0
>>>
>>> Brick 10.41.65.4:/bricks/101/VM2
>>> Number of entries: 0
>>>
>>> noticed this in host /var/log/messages (while looking for something
>>> else). Loop seems to repeat over and over.
>>>
>>> Jan 26 15:35:52 office4a sanlock[3763]: 2014-01-26 15:35:52-0500 14678
>>> [30419]: read_sectors delta_leader offset 512 rv -90
>>>
/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids
>>>
>>>
>>>
>>> Jan 26 15:35:53 office4a sanlock[3763]: 2014-01-26 15:35:53-0500 14679
>>> [3771]: s1997 add_lockspace fail result -90
>>> Jan 26 15:35:58 office4a vdsm TaskManager.Task ERROR
>>> Task=`89885661-88eb-4ea3-8793-00438735e4ab`::Unexpected
>>> error#012Traceback
>>> (most recent call last):#012 File
"/usr/share/vdsm/storage/task.py",
>>> line
>>> 857, in _run#012 return fn(*args, **kargs)#012 File
>>> "/usr/share/vdsm/logUtils.py", line 45, in wrapper#012 res =
f(*args,
>>> **kwargs)#012 File "/usr/share/vdsm/storage/hsm.py", line 2111,
in
>>> getAllTasksStatuses#012 allTasksStatus = sp.getAllTasksStatuses()#012
>>> File "/usr/share/vdsm/storage/securable.py", line 66, in
wrapper#012
>>> raise
>>> SecureError()#012SecureError
>>> Jan 26 15:35:59 office4a sanlock[3763]: 2014-01-26 15:35:59-0500 14686
>>> [30495]: read_sectors delta_leader offset 512 rv -90
>>>
/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids
>>>
>>>
>>>
>>> Jan 26 15:36:00 office4a sanlock[3763]: 2014-01-26 15:36:00-0500 14687
>>> [3772]: s1998 add_lockspace fail result -90
>>> Jan 26 15:36:00 office4a vdsm TaskManager.Task ERROR
>>> Task=`8db9ff1a-2894-407a-915a-279f6a7eb205`::Unexpected
>>> error#012Traceback
>>> (most recent call last):#012 File
"/usr/share/vdsm/storage/task.py",
>>> line
>>> 857, in _run#012 return fn(*args, **kargs)#012 File
>>> "/usr/share/vdsm/storage/task.py", line 318, in run#012 return
>>> self.cmd(*self.argslist, **self.argsdict)#012 File
>>> "/usr/share/vdsm/storage/sp.py", line 273, in startSpm#012
>>> self.masterDomain.acquireHostId(self.id)#012 File
>>> "/usr/share/vdsm/storage/sd.py", line 458, in acquireHostId#012
>>> self._clusterLock.acquireHostId(hostId, async)#012 File
>>> "/usr/share/vdsm/storage/clusterlock.py", line 189, in
>>> acquireHostId#012 raise se.AcquireHostIdFailure(self._sdUUID,
>>> e)#012AcquireHostIdFailure: Cannot acquire host id:
>>> ('0322a407-2b16-40dc-ac67-13d387c6eb4c', SanlockException(90,
'Sanlock
>>> lockspace add failure', 'Message too long'))
fede - thoughts on above?
(vojtech reported something similar, but it sorted out for him after some
retries)
>>>
>>> Ted Miller
>>> Elkhart, IN, USA
>>>
>>
>> this is the new storage domain? what about the previous volume for the
>> first SD?
>
> The default/default data center/cluster had to be abandoned because of a
> split-brain that could not be healed. Can't remove old storage from
> database, can't get data center up due to corrupt storage, ends up a
> circular argument.
>
> I started over with same hosts, totally new storage in new data center.
> This mill/one data center/cluster was working fine with VM2 storage,
> then died.
>
> Ted Miller
Looking at the problems with Sanlock, I read the page on it, then
went poking
around.
I find the sanlock.log is full of:
2014-01-26 17:26:30-0500 21316 [3772]: s3071 lockspace
0322a407-2b16-40dc-ac67-13d387c6eb4c:2:/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids:0
2014-01-26 17:26:30-0500 21316 [11733]: 0322a407 aio collect 0
0x7f97380008c0:0x7f97380008d0:0x7f9738101000 result 0:0 match len 512
2014-01-26 17:26:30-0500 21316 [11733]: read_sectors delta_leader offset 512
rv -90
/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids
2014-01-26 17:26:31-0500 21317 [3772]: s3071 add_lockspace fail result -90
Just looking at the log, it looks like sanlock is trying to "read_sectors
delta_leader offset 512", probably in this file:
/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids
Well, I can see why it fails -- the ids file is empty.
[root@office4a ~]$ ls
/rhev/data-center/mnt/glusterSD/10.41.65.2\:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/
-l
total 1029
-rw-rw---- 1 vdsm kvm 0 Jan 22 00:44 ids
-rw-rw---- 1 vdsm kvm 0 Jan 16 18:50 inbox
-rw-rw---- 1 vdsm kvm 2097152 Jan 21 18:20 leases
-rw-r--r-- 1 vdsm kvm 491 Jan 21 18:20 metadata
-rw-rw---- 1 vdsm kvm 0 Jan 16 18:50 outbox
I have no idea why it is empty, or what is supposed to be there, but anything
trying to read with an offset of 512 is going to kick back an error on a 0
length file. :(
I recall that on the previous ids file, on the domain that went up in smoke
(improperly recovered split-brain), the file was about 1 megabyte.
The date on the 'ids' file is probably about when the Data Center went belly-up.
I hope this helps someone figure out what I can do to get out of this endless
circle of trying to start the Data Center. Maybe there is a way to force an
initialization of the ids file, and then everyone could be happy?
Ted Miller
--------------030406020605090601060306
Content-Type: text/html; charset="ISO-8859-1"
Content-Transfer-Encoding: 7bit
<html>
<head>
<meta content="text/html; charset=ISO-8859-1"
http-equiv="Content-Type">
</head>
<body text="#000000" bgcolor="#FFFFFF">
On 1/26/2014 5:17 PM, Itamar Heim wrote:<br>
<blockquote cite="mid:52E58960.4060607@redhat.com"
type="cite">On
01/27/2014 12:00 AM, Ted Miller wrote:
<br>
<blockquote type="cite">
<br>
On 1/26/2014 4:00 PM, Itamar Heim wrote:
<br>
<blockquote type="cite">On 01/26/2014 10:51 PM, Ted Miller
wrote:
<br>
<blockquote type="cite">
<br>
On 1/26/2014 3:10 PM, Itamar Heim wrote:
<br>
<blockquote type="cite">On 01/26/2014 10:08 PM, Ted Miller
wrote:
<br>
<blockquote type="cite">My Data Center is down, and
won't
come back up.
<br>
<br>
Data Center Status on the GUI flips between "Non
Responsive" and
<br>
"Contending"
<br>
<br>
Also noted:
<br>
Host sometimes seen flipping between "Low" and
"Contending" in SPM
<br>
column.
<br>
Storage VM2 "Data (Master)" is in "Cross Data-Center
Status" = Unknown
<br>
VM2 is "up" under "Volumes" tab
<br>
<br>
Created another volume for VM storage. It shows up in
"volumes" tab,
<br>
but when I try to add "New Domain" in storage tab, says
that "There
<br>
are
<br>
No Data Centers to which the Storage Domain can be
attached"
<br>
<br>
Setup:
<br>
2 hosts w/ glusterfs storage
<br>
1 engine
<br>
all 3 computers Centos 6.5, just updated
<br>
ovirt-engine
3.3.0.1-1.el6
<br>
ovirt-engine-lib
3.3.2-1.el6
<br>
ovirt-host-deploy.noarch 1.1.3-1.el6
<br>
glusterfs.x86_64
3.4.2-1.el6
<br>
<br>
This loop seems to repeat in the ovirt-engine log (grep
of log showing
<br>
only DefaultQuartzScheduler_Worker-79 thread:
<br>
<br>
2014-01-26 14:44:58,416 INFO
<br>
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
<br>
(DefaultQuartzScheduler_Worker-79) Irs placed on server
<br>
9a591103-83be-4ca9-b207-06929223b541 failed. Proceed
Failover
<br>
2014-01-26 14:44:58,511 INFO
<br>
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
<br>
(DefaultQuartzScheduler_Worker-79)
hostFromVds::selectedVds -
<br>
office4a,
<br>
spmStatus Free, storage pool mill
<br>
2014-01-26 14:44:58,550 INFO
<br>
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
<br>
(DefaultQuartzScheduler_Worker-79) SpmStatus on vds
<br>
127ed939-34af-41a8-87a0-e2f6174b1877: Free
<br>
2014-01-26 14:44:58,571 INFO
<br>
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
<br>
(DefaultQuartzScheduler_Worker-79) starting spm on vds
office4a,
<br>
storage
<br>
pool mill, prevId 2, LVER 15
<br>
2014-01-26 14:44:58,579 INFO
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) START,
<br>
SpmStartVDSCommand(HostName =
<br>
office4a, HostId = 127ed939-34af-41a8-87a0-e2f6174b1877,
<br>
storagePoolId =
<br>
536a864d-83aa-473a-a675-e38aafdd9071, prevId=2,
prevLVER=15,
<br>
storagePoolFormatType=V3, recoveryMode=Manual,
SCSIFencing=false), log
<br>
id: 74c38eb7
<br>
2014-01-26 14:44:58,617 INFO
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) spmStart polling
started: taskId =
<br>
e8986753-fc80-4b11-a11d-6d3470b1728c
<br>
2014-01-26 14:45:00,662 ERROR
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) Failed in
HSMGetTaskStatusVDS
<br>
method
<br>
2014-01-26 14:45:00,664 ERROR
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) Error code
AcquireHostIdFailure and
<br>
error message VDSGenericException: VDSErrorException:
Failed to
<br>
HSMGetTaskStatusVDS, error = Cannot acquire host id
<br>
2014-01-26 14:45:00,665 INFO
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) spmStart polling
ended: taskId =
<br>
e8986753-fc80-4b11-a11d-6d3470b1728c task status =
finished
<br>
2014-01-26 14:45:00,666 ERROR
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) Start SPM Task failed
- result:
<br>
cleanSuccess, message: VDSGenericException:
VDSErrorException:
<br>
Failed to
<br>
HSMGetTaskStatusVDS, error = Cannot acquire host id
<br>
2014-01-26 14:45:00,695 INFO
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) spmStart polling
ended, spm
<br>
status: Free
<br>
2014-01-26 14:45:00,702 INFO
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) START,
<br>
HSMClearTaskVDSCommand(HostName = office4a, HostId =
<br>
127ed939-34af-41a8-87a0-e2f6174b1877,
<br>
taskId=e8986753-fc80-4b11-a11d-6d3470b1728c), log id:
336ec5a6
<br>
2014-01-26 14:45:00,722 INFO
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) FINISH,
HSMClearTaskVDSCommand, log
<br>
id: 336ec5a6
<br>
2014-01-26 14:45:00,724 INFO
<br>
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
<br>
(DefaultQuartzScheduler_Worker-79) FINISH,
SpmStartVDSCommand, return:
<br>
org.ovirt.engine.core.common.businessentities.SpmStatusResult@13652652,
<br>
<br>
log id: 74c38eb7
<br>
2014-01-26 14:45:00,733 INFO
<br>
[org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand]
<br>
(DefaultQuartzScheduler_Worker-79) Running command:
<br>
SetStoragePoolStatusCommand internal: true. Entities
affected : ID:
<br>
536a864d-83aa-473a-a675-e38aafdd9071 Type: StoragePool
<br>
2014-01-26 14:45:00,778 ERROR
<br>
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
<br>
(DefaultQuartzScheduler_Worker-79)
<br>
IrsBroker::Failed::GetStoragePoolInfoVDS due to:
<br>
IrsSpmStartFailedException: IRSGenericException:
IRSErrorException:
<br>
SpmStart failed
<br>
<br>
Ted Miller
<br>
Elkhart, IN, USA
<br>
<br>
<br>
<br>
_______________________________________________
<br>
Users mailing list
<br>
<a class="moz-txt-link-abbreviated"
href="mailto:Users@ovirt.org">Users@ovirt.org</a>
<br>
<a class="moz-txt-link-freetext"
href="http://lists.ovirt.org/mailman/listinfo/users">http://...
<br>
<br>
</blockquote>
<br>
is this gluster storage (guessing sunce you mentioned a
'volume')
<br>
</blockquote>
yes (mentioned under "setup" above)
<br>
<blockquote type="cite">does it have a quorum?
<br>
</blockquote>
Volume Name: VM2
<br>
Type: Replicate
<br>
Volume ID: 7bea8d3b-ec2a-4939-8da8-a82e6bda841e
<br>
Status: Started
<br>
Number of Bricks: 1 x 3 = 3
<br>
Transport-type: tcp
<br>
Bricks:
<br>
Brick1: 10.41.65.2:/bricks/01/VM2
<br>
Brick2: 10.41.65.4:/bricks/01/VM2
<br>
Brick3: 10.41.65.4:/bricks/101/VM2
<br>
Options Reconfigured:
<br>
cluster.server-quorum-type: server
<br>
storage.owner-gid: 36
<br>
storage.owner-uid: 36
<br>
auth.allow: *
<br>
user.cifs: off
<br>
nfs.disa
<br>
<blockquote type="cite">(there were reports of split brain
on the domain metadata before when
<br>
no quorum exist for gluster)
<br>
</blockquote>
after full heal:
<br>
<br>
[root@office4a ~]$ gluster volume heal VM2 info
<br>
Gathering Heal info on volume VM2 has been successful
<br>
<br>
Brick 10.41.65.2:/bricks/01/VM2
<br>
Number of entries: 0
<br>
<br>
Brick 10.41.65.4:/bricks/01/VM2
<br>
Number of entries: 0
<br>
<br>
Brick 10.41.65.4:/bricks/101/VM2
<br>
Number of entries: 0
<br>
[root@office4a ~]$ gluster volume heal VM2 info split-brain
<br>
Gathering Heal info on volume VM2 has been successful
<br>
<br>
Brick 10.41.65.2:/bricks/01/VM2
<br>
Number of entries: 0
<br>
<br>
Brick 10.41.65.4:/bricks/01/VM2
<br>
Number of entries: 0
<br>
<br>
Brick 10.41.65.4:/bricks/101/VM2
<br>
Number of entries: 0
<br>
<br>
noticed this in host /var/log/messages (while looking for
something
<br>
else). Loop seems to repeat over and over.
<br>
<br>
Jan 26 15:35:52 office4a sanlock[3763]: 2014-01-26
15:35:52-0500 14678
<br>
[30419]: read_sectors delta_leader offset 512 rv -90
<br>
/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids
<br>
<br>
<br>
Jan 26 15:35:53 office4a sanlock[3763]: 2014-01-26
15:35:53-0500 14679
<br>
[3771]: s1997 add_lockspace fail result -90
<br>
Jan 26 15:35:58 office4a vdsm TaskManager.Task ERROR
<br>
Task=`89885661-88eb-4ea3-8793-00438735e4ab`::Unexpected
<br>
error#012Traceback
<br>
(most recent call last):#012 File
"/usr/share/vdsm/storage/task.py",
<br>
line
<br>
857, in _run#012 return fn(*args, **kargs)#012 File
<br>
"/usr/share/vdsm/logUtils.py", line 45, in
wrapper#012
res = f(*args,
<br>
**kwargs)#012 File "/usr/share/vdsm/storage/hsm.py", line
2111, in
<br>
getAllTasksStatuses#012 allTasksStatus =
sp.getAllTasksStatuses()#012
<br>
File "/usr/share/vdsm/storage/securable.py", line 66, in
wrapper#012
<br>
raise
<br>
SecureError()#012SecureError
<br>
Jan 26 15:35:59 office4a sanlock[3763]: 2014-01-26
15:35:59-0500 14686
<br>
[30495]: read_sectors delta_leader offset 512 rv -90
<br>
/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids
<br>
<br>
<br>
Jan 26 15:36:00 office4a sanlock[3763]: 2014-01-26
15:36:00-0500 14687
<br>
[3772]: s1998 add_lockspace fail result -90
<br>
Jan 26 15:36:00 office4a vdsm TaskManager.Task ERROR
<br>
Task=`8db9ff1a-2894-407a-915a-279f6a7eb205`::Unexpected
<br>
error#012Traceback
<br>
(most recent call last):#012 File
"/usr/share/vdsm/storage/task.py",
<br>
line
<br>
857, in _run#012 return fn(*args, **kargs)#012 File
<br>
"/usr/share/vdsm/storage/task.py", line 318, in
run#012
return
<br>
self.cmd(*self.argslist, **self.argsdict)#012 File
<br>
"/usr/share/vdsm/storage/sp.py", line 273, in startSpm#012
<br>
self.masterDomain.acquireHostId(self.id)#012 File
<br>
"/usr/share/vdsm/storage/sd.py", line 458, in
acquireHostId#012
<br>
self._clusterLock.acquireHostId(hostId, async)#012 File
<br>
"/usr/share/vdsm/storage/clusterlock.py", line 189, in
<br>
acquireHostId#012 raise
se.AcquireHostIdFailure(self._sdUUID,
<br>
e)#012AcquireHostIdFailure: Cannot acquire host id:
<br>
('0322a407-2b16-40dc-ac67-13d387c6eb4c',
SanlockException(90, 'Sanlock
<br>
lockspace add failure', 'Message too long'))
<br>
</blockquote>
</blockquote>
</blockquote>
<br>
fede - thoughts on above?
<br>
(vojtech reported something similar, but it sorted out for him
after some retries)
<br>
<br>
<blockquote type="cite">
<blockquote type="cite">
<blockquote type="cite">
<br>
Ted Miller
<br>
Elkhart, IN, USA
<br>
<br>
</blockquote>
<br>
this is the new storage domain? what about the previous volume
for the
<br>
first SD?
<br>
</blockquote>
<br>
The default/default data center/cluster had to be abandoned
because of a
<br>
split-brain that could not be healed. Can't remove old storage
from
<br>
database, can't get data center up due to corrupt storage, ends
up a
<br>
circular argument.
<br>
<br>
I started over with same hosts, totally new storage in new data
center.
<br>
This mill/one data center/cluster was working fine with VM2
storage,
<br>
then died.
<br>
<br>
Ted Miller
</blockquote>
</blockquote>
Looking at the problems with Sanlock, I read the page on it, then
went poking around.<br>
<br>
I find the sanlock.log is full of:<br>
<br>
<font face="Courier New, Courier, monospace">2014-01-26
17:26:30-0500 21316 [3772]: s3071 lockspace
0322a407-2b16-40dc-ac67-13d387c6eb4c:2:/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids:0<br>
2014-01-26 17:26:30-0500 21316 [11733]: 0322a407 aio collect 0
0x7f97380008c0:0x7f97380008d0:0x7f9738101000 result 0:0 match len
512<br>
2014-01-26 17:26:30-0500 21316 [11733]: read_sectors delta_leader
offset 512 rv -90
/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids<br>
2014-01-26 17:26:31-0500 21317 [3772]: s3071 add_lockspace fail
result -90<br>
</font><br>
Just looking at the log, it looks like sanlock is trying to
"read_sectors delta_leader offset 512", probably in this file:
/rhev/data-center/mnt/glusterSD/10.41.65.2:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/ids<br>
<br>
Well, I can see why it fails -- the ids file is empty.<br>
<font face="Courier New, Courier, monospace">[root@office4a ~]$ ls
/rhev/data-center/mnt/glusterSD/10.41.65.2\:VM2/0322a407-2b16-40dc-ac67-13d387c6eb4c/dom_md/
-l<br>
total 1029<br>
-rw-rw---- 1 vdsm kvm 0
Jan 22 00:44 ids<br>
-rw-rw---- 1 vdsm kvm 0
Jan 16 18:50 inbox<br>
-rw-rw---- 1 vdsm kvm 2097152 Jan 21 18:20 leases<br>
-rw-r--r-- 1 vdsm kvm 491 Jan 21 18:20
metadata<br>
-rw-rw---- 1 vdsm kvm 0
Jan 16 18:50 outbox</font><br>
<br>
I have no idea why it is empty, or what is supposed to be there, but
anything trying to read with an offset of 512 is going to kick back
an error on a 0 length file. :(<br>
<br>
I recall that on the previous ids file, on the domain that went up
in smoke (improperly recovered split-brain), the file was about 1
megabyte.<br>
<br>
The date on the 'ids' file is probably about when the Data Center
went belly-up.<br>
<br>
I hope this helps someone figure out what I can do to get out of
this endless circle of trying to start the Data Center. Maybe there
is a way to force an initialization of the ids file, and then
everyone could be happy?<br>
<br>
Ted Miller<br>
<br>
</body>
</html>
--------------030406020605090601060306--