11 May
2012
11 May
'12
9: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--