[Users] Default storage pool won't activate after reboot
Hello, Since a recent reboot, my default data storage pool has been inactive and attempts to activate it fail. Installed RPMs: vdsm-4.9.6-0.150.git63061a9.el6.x86_64 ovirt-engine-3.1.0_0001-1.8.el6.x86_64 Relevant-looking output in the vdsm.log file (more @ http://pastebin.com/raw.php?i=cYaFLPEF): Thread-68465::ERROR::2012-05-09 14:05:00,491::task::853::TaskManager.Task::(_setError) Task=`937d1fa9-4636-42f1-a6cb-c4cc56b9f2fd`::Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 861, in _run return fn(*args, **kargs) File "/usr/share/vdsm/logUtils.py", line 38, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 526, in getSpmStatus pool = self.getPool(spUUID) File "/usr/share/vdsm/storage/hsm.py", line 263, in getPool raise se.StoragePoolUnknown(spUUID) StoragePoolUnknown: Unknown pool id, pool not connected: ('af5bcc86-898a-11e1-9632-003048c85226',) Thread-68465::DEBUG::2012-05-09 14:05:00,491::task::872::TaskManager.Task::(_run) Task=`937d1fa9-4636-42f1-a6cb-c4cc56b9f2fd`::Task._run: 937d1fa9-4636-42f1-a6cb-c4cc56b9f2fd ('af5bcc86-898a-11e1-9632-003048c85226',) {} failed - stopping task The share /is/ mounted on the node: # mount | grep cmcd-db-vip cmcd-db-vip.in.hwlab:/vmstore/ovirt on /rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt type nfs (rw,soft,nosharecache,timeo=600,retrans=6,nfsvers=3,addr=10.0.10.13) # ls -l /rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt/ total 0 drwxr-xr-x 5 vdsm kvm 45 Apr 13 12:23 4ddb9dce-1ede-459a-9b9f-52b035622517 drwxr-xr-x 5 vdsm kvm 45 Apr 12 16:17 4ea29e75-ab27-4bc9-bc46-1740d07f4cba drwxr-xr-x 5 vdsm kvm 45 Apr 19 11:40 e12a0f53-ee72-44bc-ad26-93f9b4613c6c The closest google turns up is a thread from March, in which there was some mention of a change in the way metadata is read. Might be a red herring, but here's that thread: http://lists.ovirt.org/pipermail/users/2012-March/001423.html Thanks for any insight! Ian
Hi, I'm new to oVirt myself but I thought that the top level directory name was the UUID of the storage pool. In that case the UUID it lists (af5bcc86-898a-11e1-9632-003048c85226) isn't there. Have you looked directly on the storage machine itself? Perhaps the node can't see that directory due to permission issues? -Jacob ________________________________________ From: users-bounces@ovirt.org [users-bounces@ovirt.org] on behalf of Ian Levesque [ian@crystal.harvard.edu] Sent: Wednesday, May 09, 2012 2:31 PM To: users@ovirt.org Subject: [Users] Default storage pool won't activate after reboot Hello, Since a recent reboot, my default data storage pool has been inactive and attempts to activate it fail. Installed RPMs: vdsm-4.9.6-0.150.git63061a9.el6.x86_64 ovirt-engine-3.1.0_0001-1.8.el6.x86_64 Relevant-looking output in the vdsm.log file (more @ http://pastebin.com/raw.php?i=cYaFLPEF): Thread-68465::ERROR::2012-05-09 14:05:00,491::task::853::TaskManager.Task::(_setError) Task=`937d1fa9-4636-42f1-a6cb-c4cc56b9f2fd`::Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 861, in _run return fn(*args, **kargs) File "/usr/share/vdsm/logUtils.py", line 38, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 526, in getSpmStatus pool = self.getPool(spUUID) File "/usr/share/vdsm/storage/hsm.py", line 263, in getPool raise se.StoragePoolUnknown(spUUID) StoragePoolUnknown: Unknown pool id, pool not connected: ('af5bcc86-898a-11e1-9632-003048c85226',) Thread-68465::DEBUG::2012-05-09 14:05:00,491::task::872::TaskManager.Task::(_run) Task=`937d1fa9-4636-42f1-a6cb-c4cc56b9f2fd`::Task._run: 937d1fa9-4636-42f1-a6cb-c4cc56b9f2fd ('af5bcc86-898a-11e1-9632-003048c85226',) {} failed - stopping task The share /is/ mounted on the node: # mount | grep cmcd-db-vip cmcd-db-vip.in.hwlab:/vmstore/ovirt on /rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt type nfs (rw,soft,nosharecache,timeo=600,retrans=6,nfsvers=3,addr=10.0.10.13) # ls -l /rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt/ total 0 drwxr-xr-x 5 vdsm kvm 45 Apr 13 12:23 4ddb9dce-1ede-459a-9b9f-52b035622517 drwxr-xr-x 5 vdsm kvm 45 Apr 12 16:17 4ea29e75-ab27-4bc9-bc46-1740d07f4cba drwxr-xr-x 5 vdsm kvm 45 Apr 19 11:40 e12a0f53-ee72-44bc-ad26-93f9b4613c6c The closest google turns up is a thread from March, in which there was some mention of a change in the way metadata is read. Might be a red herring, but here's that thread: http://lists.ovirt.org/pipermail/users/2012-March/001423.html Thanks for any insight! Ian _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
On May 9, 2012, at 2:40 PM, Jacob Wyatt wrote:
StoragePoolUnknown: Unknown pool id, pool not connected: ('af5bcc86-898a-11e1-9632-003048c85226',)
I'm new to oVirt myself but I thought that the top level directory name was the UUID of the storage pool. In that case the UUID it lists (af5bcc86-898a-11e1-9632-003048c85226) isn't there. Have you looked directly on the storage machine itself? Perhaps the node can't see that directory due to permission issues?
Hi Jacob - thanks for the response. The thought crossed my mind as well but I'm not sure if that UUID should indeed directly correspond to a directory. I haven't poked around the storage pools before. If that's the case, I do wonder what happened to my pool, and also what those other directories are... Best, Ian
Hi Ian, would it be possible for you to attach both ovirt-engine (manager) & vdsm logs (host) so can investigate further? ----- Original Message -----
From: "Ian Levesque" <ian@crystal.harvard.edu> To: "Jacob Wyatt" <jwyatt@ggc.edu> Cc: users@ovirt.org Sent: Wednesday, May 9, 2012 9:53:54 PM Subject: Re: [Users] Default storage pool won't activate after reboot
On May 9, 2012, at 2:40 PM, Jacob Wyatt wrote:
StoragePoolUnknown: Unknown pool id, pool not connected: ('af5bcc86-898a-11e1-9632-003048c85226',)
I'm new to oVirt myself but I thought that the top level directory name was the UUID of the storage pool. In that case the UUID it lists (af5bcc86-898a-11e1-9632-003048c85226) isn't there. Have you looked directly on the storage machine itself? Perhaps the node can't see that directory due to permission issues?
Hi Jacob - thanks for the response. The thought crossed my mind as well but I'm not sure if that UUID should indeed directly correspond to a directory. I haven't poked around the storage pools before. If that's the case, I do wonder what happened to my pool, and also what those other directories are...
Best, Ian _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
On May 9, 2012, at 2:59 PM, Haim Ateya wrote:
Hi Ian,
would it be possible for you to attach both ovirt-engine (manager) & vdsm logs (host) so can investigate further?
Sure -- you can download a zip of both logs here: http://cl.ly/1h3u322S3f1Y1W0p1T3E/logs.zip Thanks, Ian
----- Original Message -----
From: "Ian Levesque" <ian@crystal.harvard.edu> To: "Haim Ateya" <hateya@redhat.com> Cc: users@ovirt.org, "Jacob Wyatt" <jwyatt@ggc.edu> Sent: Wednesday, May 9, 2012 10:08:17 PM Subject: Re: [Users] Default storage pool won't activate after reboot
On May 9, 2012, at 2:59 PM, Haim Ateya wrote:
Hi Ian,
would it be possible for you to attach both ovirt-engine (manager) & vdsm logs (host) so can investigate further?
Sure -- you can downl load a zip of both logs here: http://cl.ly/1h3u322S3f1Y1W0p1T3E/logs.zip
it appears that connectStoragePool command fails with the following error: Thread-65664::ERROR::2012-05-09 13:17:46,922::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=af5bcc86-898a-11e1-96 32-003048c85226, msdUUID=e12a0f53-ee72-44bc-ad26-93f9b4613c6c'", 'code': 304}} and that's the reason your pool doesn't turn active. in order to understand why, I would like to get a view of your domain metadata: what kind of storage are you using ? NFS or local-domain ? - please access your NFS storage - change dir to export directory - /vmstore/ovirt - cat the following e12a0f53-ee72-44bc-ad26-93f9b4613c6c/dom_md/metadata
Thanks, Ian
On May 9, 2012, at 3:34 PM, Haim Ateya wrote:
what kind of storage are you using ? NFS or local-domain ?
NFS (gluster in the backend). This worked fine until the recent reboot.
- please access your NFS storage - change dir to export directory - /vmstore/ovirt - cat the following e12a0f53-ee72-44bc-ad26-93f9b4613c6c/dom_md/metadata
CLASS=Data DESCRIPTION=glusternfs IOOPTIMEOUTSEC=10 LEASERETRIES=3 LEASETIMESEC=60 LOCKPOLICY= LOCKRENEWALINTERVALSEC=5 MASTER_VERSION=1 POOL_DESCRIPTION=Default POOL_DOMAINS=82503778-db5d-4ad3-a863-b5484b2a08a1:Active,e12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active POOL_SPM_ID=3 POOL_SPM_LVER=5 POOL_UUID=af5bcc86-898a-11e1-9632-003048c85226 REMOTE_PATH=cmcd-db-vip.in.hwlab:/vmstore/ovirt ROLE=Master SDUUID=e12a0f53-ee72-44bc-ad26-93f9b4613c6c TYPE=NFS VERSION=0 _SHA_CKSUM=c193c6426fd840770124c2b1db81c6138337f2ef Best, Ian
----- Original Message -----
From: "Ian Levesque" <ian@crystal.harvard.edu> To: "Haim Ateya" <hateya@redhat.com> Cc: users@ovirt.org, "Jacob Wyatt" <jwyatt@ggc.edu> Sent: Wednesday, May 9, 2012 10:45:40 PM Subject: Re: [Users] Default storage pool won't activate after reboot
On May 9, 2012, at 3:34 PM, Haim Ateya wrote:
what kind of storage are you using ? NFS or local-domain ?
NFS (gluster in the backend). This worked fine until the recent reboot.
- please access your NFS storage - change dir to export directory - /vmstore/ovirt - cat the following e12a0f53-ee72-44bc-ad26-93f9b4613c6c/dom_md/metadata
CLASS=Data DESCRIPTION=glusternfs IOOPTIMEOUTSEC=10 LEASERETRIES=3 LEASETIMESEC=60 LOCKPOLICY= LOCKRENEWALINTERVALSEC=5 MASTER_VERSION=1 POOL_DESCRIPTION=Default POOL_DOMAINS=82503778-db5d-4ad3-a863-b5484b2a08a1:Active,e12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active POOL_SPM_ID=3 POOL_SPM_LVER=5 POOL_UUID=af5bcc86-898a-11e1-9632-003048c85226 REMOTE_PATH=cmcd-db-vip.in.hwlab:/vmstore/ovirt ROLE=Master SDUUID=e12a0f53-ee72-44bc-ad26-93f9b4613c6c TYPE=NFS VERSION=0 _SHA_CKSUM=c193c6426fd840770124c2b1db81c6138337f2ef
the params sent by the manager connecting host to pool fits to what written in metadata, hence, normally, vdsm shouldn't fail. however, could please run the following: - mount command (on host) - if 'cmcd-db-vip.in.hwlab:/vmstore/ovirt' exists, umount it. - restart vdsmd service - try active pool again (from manager) just want to make sure there is no caching issue. please attach logs (vdsm only) after you perform the above.
Best, Ian
On 2012-5-10 4:02, Haim Ateya wrote:
From: "Ian Levesque"<ian@crystal.harvard.edu> To: "Haim Ateya"<hateya@redhat.com> Cc: users@ovirt.org, "Jacob Wyatt"<jwyatt@ggc.edu> Sent: Wednesday, May 9, 2012 10:45:40 PM Subject: Re: [Users] Default storage pool won't activate after reboot
On May 9, 2012, at 3:34 PM, Haim Ateya wrote:
what kind of storage are you using ? NFS or local-domain ? NFS (gluster in the backend). This worked fine until the recent reboot.
- please access your NFS storage - change dir to export directory - /vmstore/ovirt - cat the following e12a0f53-ee72-44bc-ad26-93f9b4613c6c/dom_md/metadata CLASS=Data DESCRIPTION=glusternfs IOOPTIMEOUTSEC=10 LEASERETRIES=3 LEASETIMESEC=60 LOCKPOLICY= LOCKRENEWALINTERVALSEC=5 MASTER_VERSION=1 POOL_DESCRIPTION=Default POOL_DOMAINS=82503778-db5d-4ad3-a863-b5484b2a08a1:Active,e12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active POOL_SPM_ID=3 POOL_SPM_LVER=5 POOL_UUID=af5bcc86-898a-11e1-9632-003048c85226 REMOTE_PATH=cmcd-db-vip.in.hwlab:/vmstore/ovirt ROLE=Master SDUUID=e12a0f53-ee72-44bc-ad26-93f9b4613c6c TYPE=NFS VERSION=0 _SHA_CKSUM=c193c6426fd840770124c2b1db81c6138337f2ef
----- Original Message ----- the params sent by the manager connecting host to pool fits to what written in metadata, hence, normally, vdsm shouldn't fail. however, could please run the following:
- mount command (on host) - if 'cmcd-db-vip.in.hwlab:/vmstore/ovirt' exists, umount it. - restart vdsmd service - try active pool again (from manager)
just want to make sure there is no caching issue.
please attach logs (vdsm only) after you perform the above.
Also, I would like to know the rw attribute of cmcd-db-vip.in.hwlab:/vmstore/ovirt -- Shu Ming<shuming@linux.vnet.ibm.com> IBM China Systems and Technology Laboratory
On May 9, 2012, at 8:54 PM, Shu Ming wrote:
the params sent by the manager connecting host to pool fits to what written in metadata, hence, normally, vdsm shouldn't fail. however, could please run the following:
- mount command (on host) - if 'cmcd-db-vip.in.hwlab:/vmstore/ovirt' exists, umount it. - restart vdsmd service - try active pool again (from manager)
just want to make sure there is no caching issue.
please attach logs (vdsm only) after you perform the above.
Also, I would like to know the rw attribute of
cmcd-db-vip.in.hwlab:/vmstore/ovirt
The node isn't mounting this NFS export at all. Prior to this issue, it was being mounted read-write and I was successfully running a test VM. Best, Ian
--Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain;
charset=us-ascii
On May 9, 2012, at 4:02 PM, Haim Ateya wrote:
>>> - please access your NFS storage
>>> - change dir to export directory - /vmstore/ovirt
>>> - cat the following
>>> e12a0f53-ee72-44bc-ad26-93f9b4613c6c/dom_md/metadata
>>=20
>> CLASS=3DData
>> DESCRIPTION=3Dglusternfs
>> IOOPTIMEOUTSEC=3D10
>> LEASERETRIES=3D3
>> LEASETIMESEC=3D60
>> LOCKPOLICY=3D
>> LOCKRENEWALINTERVALSEC=3D5
>> MASTER_VERSION=3D1
>> POOL_DESCRIPTION=3DDefault
>> =
POOL_DOMAINS=3D82503778-db5d-4ad3-a863-b5484b2a08a1:Active,e12a0f53-ee72-4=
4bc-ad26-93f9b4613c6c:Active
>> POOL_SPM_ID=3D3
>> POOL_SPM_LVER=3D5
>> POOL_UUID=3Daf5bcc86-898a-11e1-9632-003048c85226
>> REMOTE_PATH=3Dcmcd-db-vip.in.hwlab:/vmstore/ovirt
>> ROLE=3DMaster
>> SDUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c
>> TYPE=3DNFS
>> VERSION=3D0
>> _SHA_CKSUM=3Dc193c6426fd840770124c2b1db81c6138337f2ef
>=20
> the params sent by the manager connecting host to pool fits to what =
written in metadata, hence, normally, vdsm shouldn't fail.
> however, could please run the following:=20
>=20
> - mount command (on host) - if 'cmcd-db-vip.in.hwlab:/vmstore/ovirt' =
exists, umount it.=20
> - restart vdsmd service
> - try active pool again (from manager)
>=20
> just want to make sure there is no caching issue.
>=20
> please attach logs (vdsm only) after you perform the above.
I'm not even seeing the storage domain being passed to the node. I =
assume this is because the storage domain is inactive but I can't seem =
to figure out why, or what I need to do to reactivate it.
The log (vdsm_log.txt) is attached, but it contains no mention of the =
storage domain. Also attached (vdsm_log_ref.txt) is a snippet of log =
that includes =
"/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt" in the mount =
list.
Thanks,
Ian
--Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A
Content-Disposition: attachment;
filename=vdsm_log.txt
Content-Type: text/plain;
name="vdsm_log.txt"
Content-Transfer-Encoding: quoted-printable
MainThread::INFO::2012-05-11 14:46:01,783::vdsm::70::vds::(run) I am the =
actual vdsm 4.9-0
MainThread::DEBUG::2012-05-11 =
14:46:01,937::resourceManager::379::ResourceManager::(registerNamespace) =
Registering namespace 'Storage'
MainThread::DEBUG::2012-05-11 =
14:46:01,937::threadPool::45::Misc.ThreadPool::(__init__) Enter - =
numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-05-11 =
14:46:01,953::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /bin/kill -9 28103' (cwd None)
MainThread::DEBUG::2012-05-11 =
14:46:01,962::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> =
=3D 'kill 28103: No such process\n'; <rc> =3D 1
MainThread::DEBUG::2012-05-11 =
14:46:01,963::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) =
Launching Super Vdsm
MainThread::DEBUG::2012-05-11 =
14:46:01,963::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /usr/bin/python /usr/share/vdsm/supervdsmServer.py =
23250a38-2722-40cf-9ade-f8a7c1d41ba8 9290' (cwd None)
MainThread::DEBUG::2012-05-11 =
14:46:02,109::supervdsmServer::261::SuperVdsm.Server::(main) Making sure =
I'm root
MainThread::DEBUG::2012-05-11 =
14:46:02,109::supervdsmServer::265::SuperVdsm.Server::(main) Parsing cmd =
args
MainThread::DEBUG::2012-05-11 =
14:46:02,109::supervdsmServer::268::SuperVdsm.Server::(main) Creating =
PID file
MainThread::DEBUG::2012-05-11 =
14:46:02,110::supervdsmServer::272::SuperVdsm.Server::(main) Cleaning =
old socket
MainThread::DEBUG::2012-05-11 =
14:46:02,110::supervdsmServer::276::SuperVdsm.Server::(main) Setting up =
keep alive thread
MainThread::DEBUG::2012-05-11 =
14:46:02,110::supervdsmServer::282::SuperVdsm.Server::(main) Creating =
remote object manager
MainThread::DEBUG::2012-05-11 =
14:46:02,111::supervdsmServer::293::SuperVdsm.Server::(main) Started =
serving super vdsm object
MainThread::DEBUG::2012-05-11 =
14:46:03,969::supervdsm::113::SuperVdsmProxy::(_connect) Trying to =
connect to Super Vdsm
MainThread::DEBUG::2012-05-11 =
14:46:03,974::supervdsm::84::SuperVdsmProxy::(__init__) Connected to =
Super Vdsm
MainThread::DEBUG::2012-05-11 =
14:46:03,975::multipath::102::Storage.Multipath::(isEnabled) Current =
revision of multipath.conf detected, preserving
MainThread::DEBUG::2012-05-11 =
14:46:03,975::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-05-11 =
14:46:03,986::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
MainThread::DEBUG::2012-05-11 =
14:46:03,987::lvm::335::OperationMutex::(_reloadpvs) Operation 'lvm =
reload operation' got the operation mutex
MainThread::DEBUG::2012-05-11 =
14:46:03,988::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/lvm pvs --config " devices { preferred_names =3D =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 =
disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { =
locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } =
backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units =
b --nosuffix --separator | -o =
uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,=
dev_size' (cwd None)
MainThread::DEBUG::2012-05-11 =
14:46:04,006::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
MainThread::DEBUG::2012-05-11 =
14:46:04,006::lvm::358::OperationMutex::(_reloadpvs) Operation 'lvm =
reload operation' released the operation mutex
MainThread::DEBUG::2012-05-11 =
14:46:04,006::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm =
reload operation' got the operation mutex
MainThread::DEBUG::2012-05-11 =
14:46:04,007::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/lvm vgs --config " devices { preferred_names =3D =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 =
disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { =
locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } =
backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units =
b --nosuffix --separator | -o =
uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_s=
ize,vg_mda_free' (cwd None)
MainThread::DEBUG::2012-05-11 =
14:46:04,021::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ' No volume groups found\n'; <rc> =3D 0
MainThread::DEBUG::2012-05-11 =
14:46:04,021::lvm::395::OperationMutex::(_reloadvgs) Operation 'lvm =
reload operation' released the operation mutex
MainThread::DEBUG::2012-05-11 =
14:46:04,022::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/lvm lvs --config " devices { preferred_names =3D =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 =
disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { =
locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } =
backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units =
b --nosuffix --separator | -o =
uuid,name,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None)
MainThread::DEBUG::2012-05-11 =
14:46:04,035::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ' No volume groups found\n'; <rc> =3D 0
Thread-12::DEBUG::2012-05-11 =
14:46:04,036::misc::1068::SamplingMethod::(__call__) Trying to enter =
sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-05-11 =
14:46:04,038::dispatcher::95::Storage.Dispatcher::(__init__) Starting =
StorageDispatcher...
Thread-12::DEBUG::2012-05-11 =
14:46:04,038::misc::1070::SamplingMethod::(__call__) Got in to sampling =
method
Thread-12::DEBUG::2012-05-11 =
14:46:04,039::misc::1068::SamplingMethod::(__call__) Trying to enter =
sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-05-11 =
14:46:04,039::misc::1070::SamplingMethod::(__call__) Got in to sampling =
method
Thread-12::DEBUG::2012-05-11 =
14:46:04,041::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-05-11 =
14:46:04,047::__init__::1164::Storage.Misc.excCmd::(_log) =
'/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-05-11 =
14:46:04,055::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> =
=3D 'iscsiadm: No session found.\n'; <rc> =3D 21
Thread-12::DEBUG::2012-05-11 =
14:46:04,055::misc::1078::SamplingMethod::(__call__) Returning last =
result
MainThread::DEBUG::2012-05-11 =
14:46:04,060::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
MainThread::INFO::2012-05-11 =
14:46:04,061::vmChannels::139::vds::(settimeout) Setting channels' =
timeout to 30 seconds.
VM Channels Listener::INFO::2012-05-11 =
14:46:04,061::vmChannels::127::vds::(run) Starting VM channels listener =
thread.
Thread-12::DEBUG::2012-05-11 =
14:46:05,989::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/multipath' (cwd None)
Thread-12::DEBUG::2012-05-11 =
14:46:06,034::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-12::DEBUG::2012-05-11 =
14:46:06,034::lvm::476::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-11 =
14:46:06,035::lvm::478::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-11 =
14:46:06,035::lvm::488::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-11 =
14:46:06,035::lvm::490::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-11 =
14:46:06,035::lvm::509::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-11 =
14:46:06,036::lvm::511::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-11 =
14:46:06,036::misc::1078::SamplingMethod::(__call__) Returning last =
result
Thread-12::DEBUG::2012-05-11 =
14:46:06,036::hsm::360::Storage.HSM::(__cleanStorageRepository) Started =
cleaning storage repository at '/rhev/data-center'
Thread-12::DEBUG::2012-05-11 =
14:46:06,037::hsm::392::Storage.HSM::(__cleanStorageRepository) White =
list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', =
'/rhev/data-center/mnt']
Thread-12::DEBUG::2012-05-11 =
14:46:06,037::hsm::393::Storage.HSM::(__cleanStorageRepository) Mount =
list: ['/rhev/data-center/mnt/cmcd-heilig.in.hwlab:_exports_iso']
Thread-12::DEBUG::2012-05-11 =
14:46:06,038::hsm::395::Storage.HSM::(__cleanStorageRepository) Cleaning =
leftovers
Thread-12::DEBUG::2012-05-11 =
14:46:06,038::hsm::438::Storage.HSM::(__cleanStorageRepository) Finished =
cleaning storage repository at '/rhev/data-center'
Thread-14::DEBUG::2012-05-11 =
14:46:12,314::BindingXMLRPC::864::vds::(wrapper) client =
[10.0.8.19]::call getCapabilities with () {} flowID [6ffec560]
Thread-14::DEBUG::2012-05-11 =
14:46:12,407::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd =
None)
Thread-14::DEBUG::2012-05-11 =
14:46:12,423::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-14::DEBUG::2012-05-11 =
14:46:12,424::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd =
None)
Thread-14::DEBUG::2012-05-11 =
14:46:12,440::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-14::DEBUG::2012-05-11 =
14:46:12,441::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-14::DEBUG::2012-05-11 =
14:46:12,456::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-14::DEBUG::2012-05-11 =
14:46:12,456::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' =
(cwd None)
Thread-14::DEBUG::2012-05-11 =
14:46:12,471::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-14::DEBUG::2012-05-11 =
14:46:12,471::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd =
None)
Thread-14::DEBUG::2012-05-11 =
14:46:12,487::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-14::DEBUG::2012-05-11 =
14:46:12,693::BindingXMLRPC::870::vds::(wrapper) return getCapabilities =
with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': =
{'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:7d1774a24633'}], =
'FC': []}, 'packages2': {'kernel': {'release': '220.13.1.el6.x86_64', =
'buildtime': 1334721394.0, 'version': '2.6.32'}, 'spice-server': =
{'release': '5.el6', 'buildtime': '1323304307', 'version': '0.8.2'}, =
'vdsm': {'release': '0.150.git63061a9.el6', 'buildtime': '1335602535', =
'version': '4.9.6'}, 'qemu-kvm': {'release': '2.209.el6_2.4', =
'buildtime': '1327354003', 'version': '0.12.1.2'}, 'libvirt': =
{'release': '23.el6_2.8', 'buildtime': '1334928354', 'version': =
'0.9.4'}, 'qemu-img': {'release': '2.209.el6_2.4', 'buildtime': =
'1327354003', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM)2 =
Quad CPU Q9650 @ 3.00GHz', 'hooks': {}, 'vmTypes': ['kvm'], =
'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': =
'10.0.10.18', 'cfg': {'IPV6INIT': 'yes', 'MTU': '1500', 'DELAY': '0', =
'NM_CONTROLLED': 'no', 'BOOTPROTO': 'dhcp', 'DEVICE': 'ovirtmgmt', =
'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': =
'255.255.255.0', 'stp': 'off', 'bridged': 'True', 'gateway': =
'10.0.10.254', 'ports': ['eth0']}}, 'uuid': =
'295894AA-8E10-4A53-9090-002128263408_00:21:28:26:34:08', =
'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': =
'00:21:28:26:34:08', 'netmask': '', 'speed': 1000, 'addr': '', 'mtu': =
'1500'}}, 'software_revision': '0', 'management_ip': '', =
'clusterLevels': ['3.0', '3.1'], 'cpuFlags': =
u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,mtrr,pge,mca,cmov,pat,pse36,clfl=
ush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,lm,constant_tsc,arc=
h_perfmon,pebs,bts,rep_good,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,smx,e=
st,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,xsave,lahf_lm,dts,tpr_shadow,vnmi,flexp=
riority,model_Conroe,model_Penryn', 'ISCSIInitiatorName': =
'iqn.1994-05.com.redhat:7d1774a24633', 'memSize': '1989', 'reservedMem': =
'321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', =
'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': =
{'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], =
'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': =
'1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, =
'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': =
[], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, =
'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': =
'00:00:00:00:00:00'}}, 'software_version': '4.9', 'cpuSpeed': =
'2997.678', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', =
'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], =
'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.2.0', u'pc', =
u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], =
'operatingSystem': {'release': '2.el6.centos.7', 'version': '6', 'name': =
'oVirt Node'}, 'lastClient': '0.0.0.0'}}
Thread-15::DEBUG::2012-05-11 =
14:46:13,984::BindingXMLRPC::864::vds::(wrapper) client =
[10.0.8.19]::call getCapabilities with () {} flowID [51e33141]
Thread-15::DEBUG::2012-05-11 =
14:46:13,998::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd =
None)
Thread-15::DEBUG::2012-05-11 =
14:46:14,015::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-15::DEBUG::2012-05-11 =
14:46:14,016::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd =
None)
Thread-15::DEBUG::2012-05-11 =
14:46:14,032::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-15::DEBUG::2012-05-11 =
14:46:14,033::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-15::DEBUG::2012-05-11 =
14:46:14,048::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-15::DEBUG::2012-05-11 =
14:46:14,048::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' =
(cwd None)
Thread-15::DEBUG::2012-05-11 =
14:46:14,063::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-15::DEBUG::2012-05-11 =
14:46:14,064::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q =
--qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd =
None)
Thread-15::DEBUG::2012-05-11 =
14:46:14,079::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-15::DEBUG::2012-05-11 =
14:46:14,080::BindingXMLRPC::870::vds::(wrapper) return getCapabilities =
with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': =
{'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:7d1774a24633'}], =
'FC': []}, 'packages2': {'kernel': {'release': '220.13.1.el6.x86_64', =
'buildtime': 1334721394.0, 'version': '2.6.32'}, 'spice-server': =
{'release': '5.el6', 'buildtime': '1323304307', 'version': '0.8.2'}, =
'vdsm': {'release': '0.150.git63061a9.el6', 'buildtime': '1335602535', =
'version': '4.9.6'}, 'qemu-kvm': {'release': '2.209.el6_2.4', =
'buildtime': '1327354003', 'version': '0.12.1.2'}, 'libvirt': =
{'release': '23.el6_2.8', 'buildtime': '1334928354', 'version': =
'0.9.4'}, 'qemu-img': {'release': '2.209.el6_2.4', 'buildtime': =
'1327354003', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM)2 =
Quad CPU Q9650 @ 3.00GHz', 'hooks': {}, 'vmTypes': ['kvm'], =
'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': =
'10.0.10.18', 'cfg': {'IPV6INIT': 'yes', 'MTU': '1500', 'DELAY': '0', =
'NM_CONTROLLED': 'no', 'BOOTPROTO': 'dhcp', 'DEVICE': 'ovirtmgmt', =
'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': =
'255.255.255.0', 'stp': 'off', 'bridged': 'True', 'gateway': =
'10.0.10.254', 'ports': ['eth0']}}, 'uuid': =
'295894AA-8E10-4A53-9090-002128263408_00:21:28:26:34:08', =
'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': =
'00:21:28:26:34:08', 'netmask': '', 'speed': 1000, 'addr': '', 'mtu': =
'1500'}}, 'software_revision': '0', 'management_ip': '', =
'clusterLevels': ['3.0', '3.1'], 'cpuFlags': =
u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,mtrr,pge,mca,cmov,pat,pse36,clfl=
ush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,lm,constant_tsc,arc=
h_perfmon,pebs,bts,rep_good,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,smx,e=
st,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,xsave,lahf_lm,dts,tpr_shadow,vnmi,flexp=
riority,model_Conroe,model_Penryn', 'ISCSIInitiatorName': =
'iqn.1994-05.com.redhat:7d1774a24633', 'memSize': '1989', 'reservedMem': =
'321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', =
'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': =
{'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], =
'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': =
'1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, =
'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': =
[], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, =
'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': =
'00:00:00:00:00:00'}}, 'software_version': '4.9', 'cpuSpeed': =
'2997.678', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', =
'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], =
'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.2.0', u'pc', =
u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], =
'operatingSystem': {'release': '2.el6.centos.7', 'version': '6', 'name': =
'oVirt Node'}, 'lastClient': '10.0.8.19'}}
Thread-17::DEBUG::2012-05-11 =
14:46:14,243::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19]
Thread-17::DEBUG::2012-05-11 =
14:46:14,244::task::588::TaskManager.Task::(_updateState) =
Task=3D`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::moving from state init -> =
state preparing
Thread-17::INFO::2012-05-11 =
14:46:14,244::logUtils::37::dispatcher::(wrapper) Run and protect: =
validateStorageServerConnection(domType=3D1, =
spUUID=3D'af5bcc86-898a-11e1-9632-003048c85226', conList=3D[{'connection':=
'cmcd-heilig.in.hwlab:/exports/iso', 'iqn': '', 'portal': '', 'user': =
'', 'password': '******', 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226', =
'port': ''}], options=3DNone)
Thread-17::INFO::2012-05-11 =
14:46:14,244::logUtils::39::dispatcher::(wrapper) Run and protect: =
validateStorageServerConnection, Return response: {'statuslist': =
[{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]}
Thread-17::DEBUG::2012-05-11 =
14:46:14,245::task::1172::TaskManager.Task::(prepare) =
Task=3D`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::finished: {'statuslist': =
[{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]}
Thread-17::DEBUG::2012-05-11 =
14:46:14,245::task::588::TaskManager.Task::(_updateState) =
Task=3D`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::moving from state =
preparing -> state finished
Thread-17::DEBUG::2012-05-11 =
14:46:14,245::resourceManager::809::ResourceManager.Owner::(releaseAll) =
Owner.releaseAll requests {} resources {}
Thread-17::DEBUG::2012-05-11 =
14:46:14,245::resourceManager::844::ResourceManager.Owner::(cancelAll) =
Owner.cancelAll requests {}
Thread-17::DEBUG::2012-05-11 =
14:46:14,246::task::978::TaskManager.Task::(_decref) =
Task=3D`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::ref 0 aborting False
Thread-18::DEBUG::2012-05-11 =
14:46:14,256::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19]
Thread-18::DEBUG::2012-05-11 =
14:46:14,256::task::588::TaskManager.Task::(_updateState) =
Task=3D`3b868a60-fa19-4fb6-a52d-21caecc9435d`::moving from state init -> =
state preparing
Thread-18::INFO::2012-05-11 =
14:46:14,257::logUtils::37::dispatcher::(wrapper) Run and protect: =
connectStorageServer(domType=3D1, =
spUUID=3D'af5bcc86-898a-11e1-9632-003048c85226', conList=3D[{'connection':=
'cmcd-heilig.in.hwlab:/exports/iso', 'iqn': '', 'portal': '', 'user': =
'', 'password': '******', 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226', =
'port': ''}], options=3DNone)
Thread-18::DEBUG::2012-05-11 =
14:46:14,257::lvm::476::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-05-11 =
14:46:14,258::lvm::478::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-18::DEBUG::2012-05-11 =
14:46:14,258::lvm::488::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-05-11 =
14:46:14,258::lvm::490::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-18::DEBUG::2012-05-11 =
14:46:14,258::lvm::509::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-05-11 =
14:46:14,259::lvm::511::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-18::INFO::2012-05-11 =
14:46:14,259::logUtils::39::dispatcher::(wrapper) Run and protect: =
connectStorageServer, Return response: {'statuslist': [{'status': 0, =
'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]}
Thread-18::DEBUG::2012-05-11 =
14:46:14,259::task::1172::TaskManager.Task::(prepare) =
Task=3D`3b868a60-fa19-4fb6-a52d-21caecc9435d`::finished: {'statuslist': =
[{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]}
Thread-18::DEBUG::2012-05-11 =
14:46:14,259::task::588::TaskManager.Task::(_updateState) =
Task=3D`3b868a60-fa19-4fb6-a52d-21caecc9435d`::moving from state =
preparing -> state finished
Thread-18::DEBUG::2012-05-11 =
14:46:14,260::resourceManager::809::ResourceManager.Owner::(releaseAll) =
Owner.releaseAll requests {} resources {}
Thread-18::DEBUG::2012-05-11 =
14:46:14,260::resourceManager::844::ResourceManager.Owner::(cancelAll) =
Owner.cancelAll requests {}
Thread-18::DEBUG::2012-05-11 =
14:46:14,260::task::978::TaskManager.Task::(_decref) =
Task=3D`3b868a60-fa19-4fb6-a52d-21caecc9435d`::ref 0 aborting False
Thread-19::DEBUG::2012-05-11 =
14:46:14,277::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19]
Thread-19::DEBUG::2012-05-11 =
14:46:14,278::task::588::TaskManager.Task::(_updateState) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state init -> =
state preparing
Thread-19::INFO::2012-05-11 =
14:46:14,278::logUtils::37::dispatcher::(wrapper) Run and protect: =
connectStoragePool(spUUID=3D'af5bcc86-898a-11e1-9632-003048c85226', =
hostID=3D2, scsiKey=3D'af5bcc86-898a-11e1-9632-003048c85226', =
msdUUID=3D'e12a0f53-ee72-44bc-ad26-93f9b4613c6c', masterVersion=3D1, =
options=3DNone)
Thread-19::DEBUG::2012-05-11 =
14:46:14,278::resourceManager::175::ResourceManager.Request::(__init__) =
ResName=3D`Storage.af5bcc86-898a-11e1-9632-003048c85226`ReqID=3D`cdef54e1-=
af49-4429-aecb-4d0dbf971fb5`::Request was made in =
'/usr/share/vdsm/storage/resourceManager.py' line '485' at =
'registerResource'
Thread-19::DEBUG::2012-05-11 =
14:46:14,279::resourceManager::486::ResourceManager::(registerResource) =
Trying to register resource =
'Storage.af5bcc86-898a-11e1-9632-003048c85226' for lock type 'exclusive'
Thread-19::DEBUG::2012-05-11 =
14:46:14,279::resourceManager::528::ResourceManager::(registerResource) =
Resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' is free. Now =
locking as 'exclusive' (1 active user)
Thread-19::DEBUG::2012-05-11 =
14:46:14,279::resourceManager::212::ResourceManager.Request::(grant) =
ResName=3D`Storage.af5bcc86-898a-11e1-9632-003048c85226`ReqID=3D`cdef54e1-=
af49-4429-aecb-4d0dbf971fb5`::Granted request
Thread-19::INFO::2012-05-11 =
14:46:14,280::sp::625::Storage.StoragePool::(connect) Connect host #2 to =
the storage pool af5bcc86-898a-11e1-9632-003048c85226 with master =
domain: e12a0f53-ee72-44bc-ad26-93f9b4613c6c (ver =3D 1)
Thread-19::DEBUG::2012-05-11 =
14:46:14,280::lvm::476::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:14,280::lvm::478::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:14,281::lvm::488::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:14,281::lvm::490::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:14,281::lvm::509::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:14,281::lvm::511::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:14,281::misc::1068::SamplingMethod::(__call__) Trying to enter =
sampling method (storage.sdc.refreshStorage)
Thread-19::DEBUG::2012-05-11 =
14:46:14,282::misc::1070::SamplingMethod::(__call__) Got in to sampling =
method
Thread-19::DEBUG::2012-05-11 =
14:46:14,282::misc::1068::SamplingMethod::(__call__) Trying to enter =
sampling method (storage.iscsi.rescan)
Thread-19::DEBUG::2012-05-11 =
14:46:14,282::misc::1070::SamplingMethod::(__call__) Got in to sampling =
method
Thread-19::DEBUG::2012-05-11 =
14:46:14,282::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/iscsiadm -m session -R' (cwd None)
Thread-19::DEBUG::2012-05-11 =
14:46:14,293::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> =
=3D 'iscsiadm: No session found.\n'; <rc> =3D 21
Thread-19::DEBUG::2012-05-11 =
14:46:14,294::misc::1078::SamplingMethod::(__call__) Returning last =
result
Thread-19::DEBUG::2012-05-11 =
14:46:16,226::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/multipath' (cwd None)
Thread-19::DEBUG::2012-05-11 =
14:46:16,308::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-19::DEBUG::2012-05-11 =
14:46:16,309::lvm::476::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:16,309::lvm::478::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:16,309::lvm::488::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:16,309::lvm::490::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:16,310::lvm::509::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:16,310::lvm::511::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:16,310::misc::1078::SamplingMethod::(__call__) Returning last =
result
Thread-19::DEBUG::2012-05-11 =
14:46:16,310::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm =
reload operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:16,311::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/lvm vgs --config " devices { preferred_names =3D =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 =
disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { =
locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } =
backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units =
b --nosuffix --separator | -o =
uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_s=
ize,vg_mda_free e12a0f53-ee72-44bc-ad26-93f9b4613c6c' (cwd None)
Thread-19::DEBUG::2012-05-11 =
14:46:16,328::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> =
=3D ' Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found\n'; =
<rc> =3D 5
Thread-19::WARNING::2012-05-11 =
14:46:16,328::lvm::372::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] =
[' Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found']
Thread-19::DEBUG::2012-05-11 =
14:46:16,329::lvm::395::OperationMutex::(_reloadvgs) Operation 'lvm =
reload operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 =
14:46:16,833::resourceManager::538::ResourceManager::(releaseResource) =
Trying to release resource =
'Storage.af5bcc86-898a-11e1-9632-003048c85226'
Thread-19::DEBUG::2012-05-11 =
14:46:16,834::resourceManager::553::ResourceManager::(releaseResource) =
Released resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' (0 =
active users)
Thread-19::DEBUG::2012-05-11 =
14:46:16,834::resourceManager::558::ResourceManager::(releaseResource) =
Resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' is free, finding =
out if anyone is waiting for it.
Thread-19::DEBUG::2012-05-11 =
14:46:16,834::resourceManager::565::ResourceManager::(releaseResource) =
No one is waiting for resource =
'Storage.af5bcc86-898a-11e1-9632-003048c85226', Clearing records.
Thread-19::ERROR::2012-05-11 =
14:46:16,835::task::853::TaskManager.Task::(_setError) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::Unexpected error
Traceback (most recent call last):
File "/usr/share/vdsm/storage/task.py", line 861, in _run
return fn(*args, **kargs)
File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
res =3D f(*args, **kwargs)
File "/usr/share/vdsm/storage/hsm.py", line 815, in connectStoragePool
return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, =
masterVersion, options)
File "/usr/share/vdsm/storage/hsm.py", line 857, in =
_connectStoragePool
res =3D pool.connect(hostID, scsiKey, msdUUID, masterVersion)
File "/usr/share/vdsm/storage/sp.py", line 641, in connect
self.__rebuild(msdUUID=3DmsdUUID, masterVersion=3DmasterVersion)
File "/usr/share/vdsm/storage/sp.py", line 1109, in __rebuild
self.masterDomain =3D self.getMasterDomain(msdUUID=3DmsdUUID, =
masterVersion=3DmasterVersion)
File "/usr/share/vdsm/storage/sp.py", line 1448, in getMasterDomain
raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
StoragePoolMasterNotFound: Cannot find master domain: =
'spUUID=3Daf5bcc86-898a-11e1-9632-003048c85226, =
msdUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c'
Thread-19::DEBUG::2012-05-11 =
14:46:16,837::task::872::TaskManager.Task::(_run) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::Task._run: =
5616c854-e704-4014-bb58-8ca757e8137f =
('af5bcc86-898a-11e1-9632-003048c85226', 2, =
'af5bcc86-898a-11e1-9632-003048c85226', =
'e12a0f53-ee72-44bc-ad26-93f9b4613c6c', 1) {} failed - stopping task
Thread-19::DEBUG::2012-05-11 =
14:46:16,837::task::1199::TaskManager.Task::(stop) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::stopping in state =
preparing (force False)
Thread-19::DEBUG::2012-05-11 =
14:46:16,838::task::978::TaskManager.Task::(_decref) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::ref 1 aborting True
Thread-19::INFO::2012-05-11 =
14:46:16,838::task::1157::TaskManager.Task::(prepare) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::aborting: Task is =
aborted: 'Cannot find master domain' - code 304
Thread-19::DEBUG::2012-05-11 =
14:46:16,838::task::1162::TaskManager.Task::(prepare) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::Prepare: aborted: Cannot =
find master domain
Thread-19::DEBUG::2012-05-11 =
14:46:16,838::task::978::TaskManager.Task::(_decref) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::ref 0 aborting True
Thread-19::DEBUG::2012-05-11 =
14:46:16,839::task::913::TaskManager.Task::(_doAbort) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::Task._doAbort: force =
False
Thread-19::DEBUG::2012-05-11 =
14:46:16,839::resourceManager::844::ResourceManager.Owner::(cancelAll) =
Owner.cancelAll requests {}
Thread-19::DEBUG::2012-05-11 =
14:46:16,839::task::588::TaskManager.Task::(_updateState) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state =
preparing -> state aborting
Thread-19::DEBUG::2012-05-11 =
14:46:16,839::task::537::TaskManager.Task::(__state_aborting) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::_aborting: recover policy =
none
Thread-19::DEBUG::2012-05-11 =
14:46:16,839::task::588::TaskManager.Task::(_updateState) =
Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state =
aborting -> state failed
Thread-19::DEBUG::2012-05-11 =
14:46:16,840::resourceManager::809::ResourceManager.Owner::(releaseAll) =
Owner.releaseAll requests {} resources {}
Thread-19::DEBUG::2012-05-11 =
14:46:16,840::resourceManager::844::ResourceManager.Owner::(cancelAll) =
Owner.cancelAll requests {}
Thread-19::ERROR::2012-05-11 =
14:46:16,840::dispatcher::66::Storage.Dispatcher.Protect::(run) =
{'status': {'message': "Cannot find master domain: =
'spUUID=3Daf5bcc86-898a-11e1-9632-003048c85226, =
msdUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c'", 'code': 304}}
--Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A
Content-Disposition: attachment;
filename=vdsm_log_ref.txt
Content-Type: text/plain;
name="vdsm_log_ref.txt"
Content-Transfer-Encoding: quoted-printable
Thread-12::DEBUG::2012-04-19 =
12:29:53,779::hsm::359::Storage.HSM::(__cleanStorageRepository) Started =
cleaning storage repository at '/rhev/data-center'
Thread-18::DEBUG::2012-04-19 =
12:29:53,780::misc::1101::SamplingMethod::(__call__) Trying to enter =
sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-04-19 =
12:29:53,781::hsm::391::Storage.HSM::(__cleanStorageRepository) White =
list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', =
'/rhev/data-center/mnt']
Thread-18::DEBUG::2012-04-19 =
12:29:53,781::misc::1103::SamplingMethod::(__call__) Got in to sampling =
method
Thread-12::DEBUG::2012-04-19 =
12:29:53,781::hsm::392::Storage.HSM::(__cleanStorageRepository) Mount =
list: ['/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt']
Thread-18::DEBUG::2012-04-19 =
12:29:53,781::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/iscsiadm -m session -R' (cwd None)
Thread-12::DEBUG::2012-04-19 =
12:29:53,781::hsm::394::Storage.HSM::(__cleanStorageRepository) Cleaning =
leftovers
Thread-12::DEBUG::2012-04-19 =
12:29:53,786::hsm::437::Storage.HSM::(__cleanStorageRepository) Finished =
cleaning storage repository at '/rhev/data-center'
Thread-18::DEBUG::2012-04-19 =
12:29:53,794::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> =
=3D 'iscsiadm: No session found.\n'; <rc> =3D 21
Thread-18::DEBUG::2012-04-19 =
12:29:53,795::misc::1111::SamplingMethod::(__call__) Returning last =
result
Thread-18::DEBUG::2012-04-19 =
12:29:55,715::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/multipath' (cwd None)
Thread-18::DEBUG::2012-04-19 =
12:29:55,760::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ''; <rc> =3D 0
Thread-18::DEBUG::2012-04-19 =
12:29:55,760::lvm::474::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:55,761::lvm::476::OperationMutex::(_invalidateAllPvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:55,761::lvm::486::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:55,761::lvm::488::OperationMutex::(_invalidateAllVgs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:55,761::lvm::507::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:55,762::lvm::509::OperationMutex::(_invalidateAllLvs) Operation =
'lvm invalidate operation' released the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:55,762::misc::1111::SamplingMethod::(__call__) Returning last =
result
Thread-18::DEBUG::2012-04-19 =
12:29:55,762::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm =
reload operation' got the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:55,763::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/lvm vgs --config " devices { preferred_names =3D =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 =
disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { =
locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } =
backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units =
b --nosuffix --separator | -o =
uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_s=
ize,vg_mda_free e12a0f53-ee72-44bc-ad26-93f9b4613c6c' (cwd None)
Thread-18::DEBUG::2012-04-19 =
12:29:55,781::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> =
=3D ' Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found\n'; =
<rc> =3D 5
Thread-18::WARNING::2012-04-19 =
12:29:55,782::lvm::370::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] =
[' Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found']
Thread-18::DEBUG::2012-04-19 =
12:29:55,782::lvm::393::OperationMutex::(_reloadvgs) Operation 'lvm =
reload operation' released the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:56,392::fileSD::101::Storage.StorageDomain::(__init__) Reading =
domain in path =
/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt/e12a0f53-ee72-44=
bc-ad26-93f9b4613c6c
Thread-18::DEBUG::2012-04-19 =
12:29:56,393::persistentDict::175::Storage.PersistentDict::(__init__) =
Created a persistant dict with FileMetadataRW backend
Thread-18::DEBUG::2012-04-19 =
12:29:56,403::persistentDict::216::Storage.PersistentDict::(refresh) =
read lines (FileMetadataRW)=3D['CLASS=3DData', 'DESCRIPTION=3Dglusternfs',=
'IOOPTIMEOUTSEC=3D10', 'LEASERETRIES=3D3', 'LEASETIMESEC=3D60', =
'LOCKPOLICY=3D', 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION=3D1', =
'POOL_DESCRIPTION=3DDefault', =
'POOL_DOMAINS=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active', =
'POOL_SPM_ID=3D1', 'POOL_SPM_LVER=3D0', =
'POOL_UUID=3Daf5bcc86-898a-11e1-9632-003048c85226', =
'REMOTE_PATH=3Dcmcd-db-vip.in.hwlab:/vmstore/ovirt', 'ROLE=3DMaster', =
'SDUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c', 'TYPE=3DNFS', =
'VERSION=3D0', '_SHA_CKSUM=3D3b71084c285a0ba4f74aaba162dae64224b6d8ff']
Thread-18::DEBUG::2012-04-19 =
12:29:56,407::fileSD::324::Storage.StorageDomain::(imageGarbageCollector) =
Removing remnants of deleted images []
Thread-18::DEBUG::2012-04-19 =
12:29:56,407::resourceManager::379::ResourceManager::(registerNamespace) =
Registering namespace 'e12a0f53-ee72-44bc-ad26-93f9b4613c6c_imageNS'
Thread-18::DEBUG::2012-04-19 =
12:29:56,408::resourceManager::379::ResourceManager::(registerNamespace) =
Registering namespace 'e12a0f53-ee72-44bc-ad26-93f9b4613c6c_volumeNS'
Thread-18::DEBUG::2012-04-19 =
12:29:56,408::sp::1460::Storage.StoragePool::(getMasterDomain) Master =
domain e12a0f53-ee72-44bc-ad26-93f9b4613c6c verified, version 1
Thread-18::DEBUG::2012-04-19 =
12:29:56,408::misc::1101::SamplingMethod::(__call__) Trying to enter =
sampling method (storage.sp.updateMonitoringThreads)
Thread-18::DEBUG::2012-04-19 =
12:29:56,409::misc::1103::SamplingMethod::(__call__) Got in to sampling =
method
Thread-18::DEBUG::2012-04-19 =
12:29:56,413::persistentDict::216::Storage.PersistentDict::(refresh) =
read lines (FileMetadataRW)=3D['CLASS=3DData', 'DESCRIPTION=3Dglusternfs',=
'IOOPTIMEOUTSEC=3D10', 'LEASERETRIES=3D3', 'LEASETIMESEC=3D60', =
'LOCKPOLICY=3D', 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION=3D1', =
'POOL_DESCRIPTION=3DDefault', =
'POOL_DOMAINS=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active', =
'POOL_SPM_ID=3D1', 'POOL_SPM_LVER=3D0', =
'POOL_UUID=3Daf5bcc86-898a-11e1-9632-003048c85226', =
'REMOTE_PATH=3Dcmcd-db-vip.in.hwlab:/vmstore/ovirt', 'ROLE=3DMaster', =
'SDUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c', 'TYPE=3DNFS', =
'VERSION=3D0', '_SHA_CKSUM=3D3b71084c285a0ba4f74aaba162dae64224b6d8ff']
Thread-18::DEBUG::2012-04-19 =
12:29:56,414::sp::1490::Storage.StoragePool::(updateMonitoringThreads) =
sp `af5bcc86-898a-11e1-9632-003048c85226` started monitoring domain =
`e12a0f53-ee72-44bc-ad26-93f9b4613c6c`
Thread-18::DEBUG::2012-04-19 =
12:29:56,415::misc::1111::SamplingMethod::(__call__) Returning last =
result
Thread-18::DEBUG::2012-04-19 =
12:29:56,417::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm =
reload operation' got the operation mutex
Thread-18::DEBUG::2012-04-19 =
12:29:56,417::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo =
-n /sbin/lvm vgs --config " devices { preferred_names =3D =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 =
disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { =
locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } =
backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units =
b --nosuffix --separator | -o =
uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_s=
ize,vg_mda_free' (cwd None)
Thread-18::DEBUG::2012-04-19 =
12:29:56,444::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> =
=3D ' No volume groups found\n'; <rc> =3D 0
Thread-18::DEBUG::2012-04-19 =
12:29:56,444::lvm::393::OperationMutex::(_reloadvgs) Operation 'lvm =
reload operation' released the operation mutex
Thread-18::INFO::2012-04-19 =
12:29:56,447::sp::1062::Storage.StoragePool::(_linkStorageDomain) =
Linking =
/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt/e12a0f53-ee72-44=
bc-ad26-93f9b4613c6c to =
/rhev/data-center/af5bcc86-898a-11e1-9632-003048c85226/e12a0f53-ee72-44bc-=
ad26-93f9b4613c6c
Thread-18::INFO::2012-04-19 =
12:29:56,448::sp::1062::Storage.StoragePool::(_linkStorageDomain) =
Linking =
/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt/e12a0f53-ee72-44=
bc-ad26-93f9b4613c6c to =
/rhev/data-center/af5bcc86-898a-11e1-9632-003048c85226/mastersd
Thread-18::DEBUG::2012-04-19 =
12:29:56,448::resourceManager::538::ResourceManager::(releaseResource) =
Trying to release resource =
'Storage.af5bcc86-898a-11e1-9632-003048c85226'
Thread-18::DEBUG::2012-04-19 =
12:29:56,449::resourceManager::553::ResourceManager::(releaseResource) =
Released resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' (0 =
active users)
Thread-18::DEBUG::2012-04-19 =
12:29:56,449::resourceManager::558::ResourceManager::(releaseResource) =
Resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' is free, finding =
out if anyone is waiting for it.
Thread-18::DEBUG::2012-04-19 =
12:29:56,449::resourceManager::565::ResourceManager::(releaseResource) =
No one is waiting for resource =
'Storage.af5bcc86-898a-11e1-9632-003048c85226', Clearing records.
Thread-18::INFO::2012-04-19 =
12:29:56,449::logUtils::39::dispatcher::(wrapper) Run and protect: =
connectStoragePool, Return response: True
Thread-18::DEBUG::2012-04-19 =
12:29:56,450::task::1172::TaskManager.Task::(prepare) =
Task=3D`7f46d378-c3b9-41ed-9ede-33e7e69cd440`::finished: True
Thread-18::DEBUG::2012-04-19 =
12:29:56,450::task::588::TaskManager.Task::(_updateState) =
Task=3D`7f46d378-c3b9-41ed-9ede-33e7e69cd440`::moving from state =
preparing -> state finished=
--Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A
Content-Transfer-Encoding: 7bit
Content-Type: text/plain;
charset=us-ascii
--Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A--
On May 11, 2012, at 3:09 PM, Ian Levesque wrote:
On May 9, 2012, at 4:02 PM, Haim Ateya wrote:
- please access your NFS storage - change dir to export directory - /vmstore/ovirt - cat the following e12a0f53-ee72-44bc-ad26-93f9b4613c6c/dom_md/metadata
CLASS=Data DESCRIPTION=glusternfs IOOPTIMEOUTSEC=10 LEASERETRIES=3 LEASETIMESEC=60 LOCKPOLICY= LOCKRENEWALINTERVALSEC=5 MASTER_VERSION=1 POOL_DESCRIPTION=Default POOL_DOMAINS=82503778-db5d-4ad3-a863-b5484b2a08a1:Active,e12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active POOL_SPM_ID=3 POOL_SPM_LVER=5 POOL_UUID=af5bcc86-898a-11e1-9632-003048c85226 REMOTE_PATH=cmcd-db-vip.in.hwlab:/vmstore/ovirt ROLE=Master SDUUID=e12a0f53-ee72-44bc-ad26-93f9b4613c6c TYPE=NFS VERSION=0 _SHA_CKSUM=c193c6426fd840770124c2b1db81c6138337f2ef
the params sent by the manager connecting host to pool fits to what written in metadata, hence, normally, vdsm shouldn't fail. however, could please run the following:
- mount command (on host) - if 'cmcd-db-vip.in.hwlab:/vmstore/ovirt' exists, umount it. - restart vdsmd service - try active pool again (from manager)
just want to make sure there is no caching issue.
please attach logs (vdsm only) after you perform the above.
I'm not even seeing the storage domain being passed to the node. I assume this is because the storage domain is inactive but I can't seem to figure out why, or what I need to do to reactivate it.
The log (vdsm_log.txt) is attached, but it contains no mention of the storage domain. Also attached (vdsm_log_ref.txt) is a snippet of log that includes "/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt" in the mount list.
Is there any further troubleshooting I can do before giving up on this? Thanks, Ian
----- Original Message -----
From: "Ian Levesque" <ian@crystal.harvard.edu> To: "Haim Ateya" <hateya@redhat.com> Cc: users@ovirt.org Sent: Tuesday, May 15, 2012 10:21:04 PM Subject: Re: [Users] Default storage pool won't activate after reboot
On May 11, 2012, at 3:09 PM, Ian Levesque wrote:
On May 9, 2012, at 4:02 PM, Haim Ateya wrote:
- please access your NFS storage - change dir to export directory - /vmstore/ovirt - cat the following e12a0f53-ee72-44bc-ad26-93f9b4613c6c/dom_md/metadata
CLASS=Data DESCRIPTION=glusternfs IOOPTIMEOUTSEC=10 LEASERETRIES=3 LEASETIMESEC=60 LOCKPOLICY= LOCKRENEWALINTERVALSEC=5 MASTER_VERSION=1 POOL_DESCRIPTION=Default POOL_DOMAINS=82503778-db5d-4ad3-a863-b5484b2a08a1:Active,e12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active POOL_SPM_ID=3 POOL_SPM_LVER=5 POOL_UUID=af5bcc86-898a-11e1-9632-003048c85226 REMOTE_PATH=cmcd-db-vip.in.hwlab:/vmstore/ovirt ROLE=Master SDUUID=e12a0f53-ee72-44bc-ad26-93f9b4613c6c TYPE=NFS VERSION=0 _SHA_CKSUM=c193c6426fd840770124c2b1db81c6138337f2ef
the params sent by the manager connecting host to pool fits to what written in metadata, hence, normally, vdsm shouldn't fail. however, could please run the following:
- mount command (on host) - if 'cmcd-db-vip.in.hwlab:/vmstore/ovirt' exists, umount it. - restart vdsmd service - try active pool again (from manager)
just want to make sure there is no caching issue.
please attach logs (vdsm only) after you perform the above.
I'm not even seeing the storage domain being passed to the node. I assume this is because the storage domain is inactive but I can't seem to figure out why, or what I need to do to reactivate it.
The log (vdsm_log.txt) is attached, but it contains no mention of the storage domain. Also attached (vdsm_log_ref.txt) is a snippet of log that includes "/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt" in the mount list.
Is there any further troubleshooting I can do before giving up on this?
This is extremely odd as everything looks right, I would have blame some caching issues, but you mentioned that vdsm service was restarted. Saggi\Edu\Federico - any insight on this case ? why would connectStoragePool fails on cannot find master domain if command sent by manager uses right params as mentioned in meta-data ? connectStorageServer succeeds as well (although I see no mount command - guess it due to OOP). Ian - you can always use the "Re-initialize data-center" flow which basically means you loss all your current data (iirc) and new master domain is created. let's wait for the guys to give their insight, meantime I would try reboot the host just to make sure there is no stale NFS entry there.
Thanks, Ian
participants (4)
-
Haim Ateya -
Ian Levesque -
Jacob Wyatt -
Shu Ming