1:31 p.m.
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
1:40 p.m.
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(a)ovirt.org [users-bounces(a)ovirt.org] on behalf of Ian Levesque
[ian(a)crystal.harvard.edu]
Sent: Wednesday, May 09, 2012 2:31 PM
To: users(a)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(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
1:53 p.m.
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
1:59 p.m.
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(a)crystal.harvard.edu>
To: "Jacob Wyatt" <jwyatt(a)ggc.edu>
Cc: users(a)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(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
2:08 p.m.
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
2:34 p.m.
----- Original Message -----
From: "Ian Levesque" <ian(a)crystal.harvard.edu>
To: "Haim Ateya" <hateya(a)redhat.com>
Cc: users(a)ovirt.org, "Jacob Wyatt" <jwyatt(a)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
2:45 p.m.
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
3:02 p.m.
----- Original Message -----
From: "Ian Levesque" <ian(a)crystal.harvard.edu>
To: "Haim Ateya" <hateya(a)redhat.com>
Cc: users(a)ovirt.org, "Jacob Wyatt" <jwyatt(a)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
7:54 p.m.
On 2012-5-10 4:02, Haim Ateya wrote:
----- Original Message -----
> From: "Ian Levesque"<ian(a)crystal.harvard.edu>
> To: "Haim Ateya"<hateya(a)redhat.com>
> Cc: users(a)ovirt.org, "Jacob Wyatt"<jwyatt(a)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.
Also, I would like to know the rw attribute of
cmcd-db-vip.in.hwlab:/vmstore/ovirt
--
Shu Ming<shuming(a)linux.vnet.ibm.com>
IBM China Systems and Technology Laboratory
2:12 p.m.
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
2:09 p.m.
--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--
2:21 p.m.
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
3:47 p.m.
----- Original Message -----
From: "Ian Levesque" <ian(a)crystal.harvard.edu>
To: "Haim Ateya" <hateya(a)redhat.com>
Cc: users(a)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
4577
days inactive
4583
days old
12 comments
4 participants
participants (4)
-
Haim Ateya -
Ian Levesque -
Jacob Wyatt -
Shu Ming