4:17 p.m.
One engine with f19 and two nodes with f19.
All with ovirt stable repo for f19.
DC defined as GlusterFS
The volume is ok, but I can't activate the domain.
Relevant logs when I clich activate are below
On engine:
2013-10-03 23:05:10,332 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServicesListVDSCommand]
(pool-6-thread-50) START, GlusterServicesListVDSCommand(HostName =
f18ovn03, HostId = b67bcfd4-f868-49d5-8704-4936ee922249), log id:
5704c54f
2013-10-03 23:05:12,121 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) hostFromVds::selectedVds -
f18ovn01, spmStatus Free, storage pool Gluster
2013-10-03 23:05:12,142 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) SpmStatus on vds
80188ccc-83b2-4bc8-9385-8d07f7458a3c: Free
2013-10-03 23:05:12,144 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) starting spm on vds f18ovn01,
storage pool Gluster, prevId 1, LVER 0
2013-10-03 23:05:12,148 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServicesListVDSCommand]
(pool-6-thread-46) FINISH, GlusterServicesListVDSCommand, return:
[org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@955283ba,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@1ef87397,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@c1b996b6,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@30199726,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@606c4879,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@2b860d38,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@f69fd1f7],
log id: 4a1b4d33
2013-10-03 23:05:12,159 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) START, SpmStartVDSCommand(HostName
= f18ovn01, HostId = 80188ccc-83b2-4bc8-9385-8d07f7458a3c,
storagePoolId = eb679feb-4da2-4fd0-a185-abbe459ffa70, prevId=1,
prevLVER=0, storagePoolFormatType=V3, recoveryMode=Manual,
SCSIFencing=false), log id: 62f11f2d
2013-10-03 23:05:12,169 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) spmStart polling started: taskId =
ab9f2f84-f89b-44e9-b508-a904420635f4
2013-10-03 23:05:12,232 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServicesListVDSCommand]
(pool-6-thread-50) FINISH, GlusterServicesListVDSCommand, return:
[org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@b624c19b,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@3fcab178,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@e28bd497,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@50ebd507,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@813e865a,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@4c584b19,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService@17720fd8],
log id: 5704c54f
2013-10-03 23:05:12,512 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-6) START,
GlusterVolumesListVDSCommand(HostName = f18ovn01, HostId =
80188ccc-83b2-4bc8-9385-8d07f7458a3c), log id: 39a3f45d
2013-10-03 23:05:12,595 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-6) FINISH,
GlusterVolumesListVDSCommand, return:
{97873e57-0cc2-4740-ae38-186a8dd94718=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@a82da199,
d055b38c-2754-4e53-af5c-69cc0b8bf31c=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@ef0c0180},
log id: 39a3f45d
2013-10-03 23:05:14,182 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand]
(DefaultQuartzScheduler_Worker-83) Failed in HSMGetTaskStatusVDS
method
2013-10-03 23:05:14,184 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand]
(DefaultQuartzScheduler_Worker-83) Error code AcquireHostIdFailure and
error message VDSGenericException: VDSErrorException: Failed to
HSMGetTaskStatusVDS, error = Cannot acquire host id
2013-10-03 23:05:14,186 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) spmStart polling ended: taskId =
ab9f2f84-f89b-44e9-b508-a904420635f4 task status = finished
2013-10-03 23:05:14,188 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) Start SPM Task failed - result:
cleanSuccess, message: VDSGenericException: VDSErrorException: Failed
to HSMGetTaskStatusVDS, error = Cannot acquire host id
2013-10-03 23:05:14,214 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) spmStart polling ended, spm status:
Free
2013-10-03 23:05:14,228 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-83) START,
HSMClearTaskVDSCommand(HostName = f18ovn01, HostId =
80188ccc-83b2-4bc8-9385-8d07f7458a3c,
taskId=ab9f2f84-f89b-44e9-b508-a904420635f4), log id: 6e5df07f
2013-10-03 23:05:14,235 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-83) FINISH, HSMClearTaskVDSCommand, log
id: 6e5df07f
2013-10-03 23:05:14,237 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) FINISH, SpmStartVDSCommand, return:
org.ovirt.engine.core.common.businessentities.SpmStatusResult@5191523,
log id: 62f11f2d
2013-10-03 23:05:14,239 INFO
[org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand]
(DefaultQuartzScheduler_Worker-83) Running command:
SetStoragePoolStatusCommand internal: true. Entities affected : ID:
eb679feb-4da2-4fd0-a185-abbe459ffa70 Type: StoragePool
2013-10-03 23:05:14,258 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83)
IrsBroker::Failed::GetStoragePoolInfoVDS due to:
IrsSpmStartFailedException: IRSGenericException: IRSErrorException:
SpmStart failed
2013-10-03 23:05:14,307 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) Irs placed on server
80188ccc-83b2-4bc8-9385-8d07f7458a3c failed. Proceed Failover
2013-10-03 23:05:14,341 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) hostFromVds::selectedVds -
f18ovn03, spmStatus Free, storage pool Gluster
2013-10-03 23:05:14,345 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) SPM Init: could not find reported
vds or not up - pool:Gluster vds_spm_id: 1
2013-10-03 23:05:14,360 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) SPM selection - vds seems as spm
f18ovn01
2013-10-03 23:05:14,375 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand]
(DefaultQuartzScheduler_Worker-83) START, SpmStopVDSCommand(HostName =
f18ovn01, HostId = 80188ccc-83b2-4bc8-9385-8d07f7458a3c, storagePoolId
= eb679feb-4da2-4fd0-a185-abbe459ffa70), log id: 59e35f64
2013-10-03 23:05:14,384 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand]
(DefaultQuartzScheduler_Worker-83) Command
org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand
return value
On first vdsm host:
Thread-22567::DEBUG::2013-10-03
23:05:00,996::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll
requests {}
Thread-22567::DEBUG::2013-10-03
23:05:00,996::task::974::TaskManager.Task::(_decref)
Task=`b00f597e-e73c-49a1-9bb5-14a
5d800c32e`::ref 0 aborting False
4a4a72d1-b1db-4498-aac1-549c986fde24::ERROR::2013-10-03
23:05:01,042::task::850::TaskManager.Task::(_setError)
Task=`4a4a72d1-b1db-4498-aac1-549c986fde24`::Unexpected error
Traceback (most recent call last):
File "/usr/share/vdsm/storage/task.py", line 857, in _run
return fn(*args, **kargs)
File "/usr/share/vdsm/storage/task.py", line 318, in run
return self.cmd(*self.argslist, **self.argsdict)
File "/usr/share/vdsm/storage/sp.py", line 272, in startSpm
self.masterDomain.acquireHostId(self.id)
File "/usr/share/vdsm/storage/sd.py", line 458, in acquireHostId
self._clusterLock.acquireHostId(hostId, async)
File "/usr/share/vdsm/storage/clusterlock.py", line 189, in acquireHostId
raise se.AcquireHostIdFailure(self._sdUUID, e)
AcquireHostIdFailure: Cannot acquire host id:
('d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291', SanlockException(5, 'Sanlock
lockspace add failure', 'Input/output error'))
On second vdsm host:
Thread-15262::DEBUG::2013-10-03
23:05:23,327::task::1168::TaskManager.Task::(prepare)
Task=`654b1197-b3a0-4cff-9859-6515c5a908f4`::finished: {'taskStatus':
{'code': 0, 'message': 'Task is initializing',
'taskState': 'running',
'taskResult': '', 'taskID':
'f8ada879-f322-4135-9803-b5f8217ac58a'}}
Thread-15262::DEBUG::2013-10-03
23:05:23,327::task::579::TaskManager.Task::(_updateState)
Task=`654b1197-b3a0-4cff-9859-6515c5a908f4`::moving from state
preparing -> state finished
Thread-15262::DEBUG::2013-10-03
23:05:23,327::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-15262::DEBUG::2013-10-03
23:05:23,328::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-15262::DEBUG::2013-10-03
23:05:23,328::task::974::TaskManager.Task::(_decref)
Task=`654b1197-b3a0-4cff-9859-6515c5a908f4`::ref 0 aborting False
f8ada879-f322-4135-9803-b5f8217ac58a::ERROR::2013-10-03
23:05:23,356::task::850::TaskManager.Task::(_setError)
Task=`f8ada879-f322-4135-9803-b5f8217ac58a`::Unexpected error
Traceback (most recent call last):
File "/usr/share/vdsm/storage/task.py", line 857, in _run
return fn(*args, **kargs)
File "/usr/share/vdsm/storage/task.py", line 318, in run
return self.cmd(*self.argslist, **self.argsdict)
File "/usr/share/vdsm/storage/sp.py", line 272, in startSpm
self.masterDomain.acquireHostId(self.id)
File "/usr/share/vdsm/storage/sd.py", line 458, in acquireHostId
self._clusterLock.acquireHostId(hostId, async)
File "/usr/share/vdsm/storage/clusterlock.py", line 189, in acquireHostId
raise se.AcquireHostIdFailure(self._sdUUID, e)
AcquireHostIdFailure: Cannot acquire host id:
('d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291', SanlockException(5, 'Sanlock
lockspace add failure', 'Input/output error'))
f8ada879-f322-4135-9803-b5f8217ac58a::DEBUG::2013-10-03
23:05:23,358::task::869::TaskManager.Task::(_run)
Task=`f8ada879-f322-4135-9803-b5f8217ac58a`::Task._run:
f8ada879-f322-4135-9803-b5f8217ac58a () {} failed - stopping task
f8ada879-f322-4135-9803-b5f8217ac58a::DEBUG::2013-10-03
23:05:23,358::task::1194::TaskManager.Task::(stop)
Task=`f8ada879-f322-4135-9803-b5f8217ac58a`::stopping in state running
(force False)
ANy hint?
Thanks,
Gianluca
4:54 p.m.
On messages of vdsm hosts
Oct 3 23:05:57 f18ovn03 sanlock[1146]: 2013-10-03 23:05:57+0200 16624
[13543]: read_sectors delta_leader offset 512 rv
-5
/rhev/data-center/mnt/glusterSD/f18ovn01.mydomain:gvdata/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
Oct 3 23:05:58 f18ovn03 sanlock[1146]: 2013-10-03 23:05:58+0200 16625
[1155]: s2142 add_lockspace fail result -5
Oct 3 23:04:24 f18ovn01 sanlock[1166]: 2013-10-03 23:04:24+0200 16154
[1172]: s2688 add_lockspace fail result -5
Oct 3 23:04:24 f18ovn01 vdsm TaskManager.Task ERROR
Task=`bd6b0848-4550-483e-9002-e3051a2e1074`::Unexpected error
Oct 3 23:04:25 f18ovn01 vdsm TaskManager.Task ERROR
Task=`f2ac595d-cc9d-4125-a7be-7b8706cc9ee3`::Unexpected error
Oct 3 23:04:25 f18ovn01 vdsm TaskManager.Task ERROR
Task=`6c03be35-57f1-405e-b127-bd708defad67`::Unexpected error
Oct 3 23:04:26 f18ovn01 sanlock[1166]: 2013-10-03 23:04:26+0200 16157
[21348]: read_sectors delta_leader offset 0 rv -5
/rhev/data-center/mnt/glusterSD/f18ovn01.mydomain:gvdata/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
Oct 3 23:04:27 f18ovn01 sanlock[1166]: 2013-10-03 23:04:27+0200 16158
[1172]: s2689 add_lockspace fail result -5
But the origin possibly is a split brain detected at gluster level
I see it in rhev-data-center-mnt-glusterSD-f18ovn01.mydomain:gvdata.log
this afternoon around the time I had installed the first guest and ran
a shutdown and a power on.
see:
https://docs.google.com/file/d/0BwoPbcrMv8mvNHNOVlNrOFFabjQ/edit?usp=sharing
Why gluster logs are two hours behind? UTC? Any way to set them with
the current system time?
Gianluca
5:18 p.m.
And in fact after solving the split brain, the gluster domain
automatically activated.
From rhev-data-center-mnt-glusterSD-f18ovn01.mydomain:gvdata.log under
/var/log/glusterfs I found ids file was the one not in sync
As the VM only started on f18ovn03 and I was not able to migrate to
f18ovn01, I decided to delete the file form f18ovn01.
BTW: what does dom_md/ids contain?
[2013-10-03 22:06:33.543730] E
[afr-self-heal-common.c:197:afr_sh_print_split_brain_log]
0-gvdata-replicate-0: Unable to self-heal contents of
'/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids' (possible
split-brain). Please delete the file from all but the preferred
subvolume.- Pending matrix: [ [ 0 2 ] [ 2 0 ] ]
[2013-10-03 22:06:33.544013] E
[afr-self-heal-common.c:2212:afr_self_heal_completion_cbk]
0-gvdata-replicate-0: background data self-heal failed on
/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
[2013-10-03 22:06:33.544522] W [afr-open.c:213:afr_open]
0-gvdata-replicate-0: failed to open as split brain seen, returning
EIO
[2013-10-03 22:06:33.544603] W [page.c:991:__ioc_page_error]
0-gvdata-io-cache: page error for page = 0x7f4b80004910 & waitq =
0x7f4b8001da60
[2013-10-03 22:06:33.544635] W [fuse-bridge.c:2049:fuse_readv_cbk]
0-glusterfs-fuse: 132995: READ => -1 (Input/output error)
[2013-10-03 22:06:33.545070] W
[client-lk.c:367:delete_granted_locks_owner] 0-gvdata-client-0: fdctx
not valid
[2013-10-03 22:06:33.545118] W
[client-lk.c:367:delete_granted_locks_owner] 0-gvdata-client-1: fdctx
not valid
I found that gluster creates hard links, so you have to delete all
copies of conflicting file from the brick directory of the node you
choose to delete from.
Thanks very much to this link:
http://inuits.eu/blog/fixing-glusterfs-split-brain
So these my steps:
locate
[root@f18ovn01 d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291]# find
/gluster/DATA_GLUSTER/brick1/ -samefile
/gluster/DATA_GLUSTER/brick1/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
-print
/gluster/DATA_GLUSTER/brick1/.glusterfs/ae/27/ae27eb8d-c653-4cc0-a054-ea376ce8097d
/gluster/DATA_GLUSTER/brick1/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
and then delete both
[root@f18ovn01 d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291]# find
/gluster/DATA_GLUSTER/brick1/ -samefile
/gluster/DATA_GLUSTER/brick1/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
-print -delete
/gluster/DATA_GLUSTER/brick1/.glusterfs/ae/27/ae27eb8d-c653-4cc0-a054-ea376ce8097d
/gluster/DATA_GLUSTER/brick1/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
An after this step no more " E " lines in gluster log and gluster
domain automatically activated by engine.
Gianluca
4:30 a.m.
On 10/04/2013 12:54 AM, Gianluca Cecchi wrote:
On messages of vdsm hosts
Oct 3 23:05:57 f18ovn03 sanlock[1146]: 2013-10-03 23:05:57+0200 16624
[13543]: read_sectors delta_leader offset 512 rv
-5
/rhev/data-center/mnt/glusterSD/f18ovn01.mydomain:gvdata/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
Oct 3 23:05:58 f18ovn03 sanlock[1146]: 2013-10-03 23:05:58+0200 16625
[1155]: s2142 add_lockspace fail result -5
Oct 3 23:04:24 f18ovn01 sanlock[1166]: 2013-10-03 23:04:24+0200 16154
[1172]: s2688 add_lockspace fail result -5
Oct 3 23:04:24 f18ovn01 vdsm TaskManager.Task ERROR
Task=`bd6b0848-4550-483e-9002-e3051a2e1074`::Unexpected error
Oct 3 23:04:25 f18ovn01 vdsm TaskManager.Task ERROR
Task=`f2ac595d-cc9d-4125-a7be-7b8706cc9ee3`::Unexpected error
Oct 3 23:04:25 f18ovn01 vdsm TaskManager.Task ERROR
Task=`6c03be35-57f1-405e-b127-bd708defad67`::Unexpected error
Oct 3 23:04:26 f18ovn01 sanlock[1166]: 2013-10-03 23:04:26+0200 16157
[21348]: read_sectors delta_leader offset 0 rv -5
/rhev/data-center/mnt/glusterSD/f18ovn01.mydomain:gvdata/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/dom_md/ids
Oct 3 23:04:27 f18ovn01 sanlock[1166]: 2013-10-03 23:04:27+0200 16158
[1172]: s2689 add_lockspace fail result -5
But the origin possibly is a split brain detected at gluster level
I see it in rhev-data-center-mnt-glusterSD-f18ovn01.mydomain:gvdata.log
this afternoon around the time I had installed the first guest and ran
a shutdown and a power on.
see:
https://docs.google.com/file/d/0BwoPbcrMv8mvNHNOVlNrOFFabjQ/edit?usp=sharing
Why gluster logs are two hours behind? UTC? Any way to set them with
the current system time?
Gianluca
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
do you happen to know why it got into a split brain status?
4:35 a.m.
On Fri, Oct 4, 2013 at 11:30 AM, Itamar Heim wrote:
do you happen to know why it got into a split brain status?
I suppose with the fist migration attempt.
But last night I replicated but I only got the heal for ids file, that
gluster apparently solved itself.
Possibly the bug about ide can influence the migration problem and the
possible gluster split brain?
What does it contain dom_md/ids file and when does it get updated?
During install of OS, and "yum update" it seems all was ok and no heal
about disk file itself....
SO I presume the metadata update not correctly managed someway could
induce gluster coherence on this "ids" file....
Gianluca
4069
days inactive
4070
days old
4 comments
2 participants
participants (2)
-
Gianluca Cecchi -
Itamar Heim