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

Hi Ian, would it be possible for you to attach both ovirt-engine (manager) & vdsm logs (host) so can investigate further? ----- Original Message -----

----- Original Message ----- 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

----- Original Message ----- the params sent by the manager connecting host to pool fits to what written in metadata, hence, normally, vdsm shouldn't fail. however, could please run the following: - mount command (on host) - if 'cmcd-db-vip.in.hwlab:/vmstore/ovirt' exists, umount it. - restart vdsmd service - try active pool again (from manager) just want to make sure there is no caching issue. please attach logs (vdsm only) after you perform the above.

--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: POOL_DOMAINS=3D82503778-db5d-4ad3-a863-b5484b2a08a1:Active,e12a0f53-ee72-4= 4bc-ad26-93f9b4613c6c:Active written in metadata, hence, normally, vdsm shouldn't fail. exists, umount it.=20 I'm not even seeing the storage domain being passed to the node. I = assume this is because the storage domain is inactive but I can't seem = to figure out why, or what I need to do to reactivate it. The log (vdsm_log.txt) is attached, but it contains no mention of the = storage domain. Also attached (vdsm_log_ref.txt) is a snippet of log = that includes = "/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt" in the mount = list. Thanks, Ian --Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A Content-Disposition: attachment; filename=vdsm_log.txt Content-Type: text/plain; name="vdsm_log.txt" Content-Transfer-Encoding: quoted-printable MainThread::INFO::2012-05-11 14:46:01,783::vdsm::70::vds::(run) I am the = actual vdsm 4.9-0 MainThread::DEBUG::2012-05-11 = 14:46:01,937::resourceManager::379::ResourceManager::(registerNamespace) = Registering namespace 'Storage' MainThread::DEBUG::2012-05-11 = 14:46:01,937::threadPool::45::Misc.ThreadPool::(__init__) Enter - = numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0 MainThread::DEBUG::2012-05-11 = 14:46:01,953::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /bin/kill -9 28103' (cwd None) MainThread::DEBUG::2012-05-11 = 14:46:01,962::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = =3D 'kill 28103: No such process\n'; <rc> =3D 1 MainThread::DEBUG::2012-05-11 = 14:46:01,963::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) = Launching Super Vdsm MainThread::DEBUG::2012-05-11 = 14:46:01,963::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py = 23250a38-2722-40cf-9ade-f8a7c1d41ba8 9290' (cwd None) MainThread::DEBUG::2012-05-11 = 14:46:02,109::supervdsmServer::261::SuperVdsm.Server::(main) Making sure = I'm root MainThread::DEBUG::2012-05-11 = 14:46:02,109::supervdsmServer::265::SuperVdsm.Server::(main) Parsing cmd = args MainThread::DEBUG::2012-05-11 = 14:46:02,109::supervdsmServer::268::SuperVdsm.Server::(main) Creating = PID file MainThread::DEBUG::2012-05-11 = 14:46:02,110::supervdsmServer::272::SuperVdsm.Server::(main) Cleaning = old socket MainThread::DEBUG::2012-05-11 = 14:46:02,110::supervdsmServer::276::SuperVdsm.Server::(main) Setting up = keep alive thread MainThread::DEBUG::2012-05-11 = 14:46:02,110::supervdsmServer::282::SuperVdsm.Server::(main) Creating = remote object manager MainThread::DEBUG::2012-05-11 = 14:46:02,111::supervdsmServer::293::SuperVdsm.Server::(main) Started = serving super vdsm object MainThread::DEBUG::2012-05-11 = 14:46:03,969::supervdsm::113::SuperVdsmProxy::(_connect) Trying to = connect to Super Vdsm MainThread::DEBUG::2012-05-11 = 14:46:03,974::supervdsm::84::SuperVdsmProxy::(__init__) Connected to = Super Vdsm MainThread::DEBUG::2012-05-11 = 14:46:03,975::multipath::102::Storage.Multipath::(isEnabled) Current = revision of multipath.conf detected, preserving MainThread::DEBUG::2012-05-11 = 14:46:03,975::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/lvm dumpconfig global/locking_type' (cwd None) MainThread::DEBUG::2012-05-11 = 14:46:03,986::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 MainThread::DEBUG::2012-05-11 = 14:46:03,987::lvm::335::OperationMutex::(_reloadpvs) Operation 'lvm = reload operation' got the operation mutex MainThread::DEBUG::2012-05-11 = 14:46:03,988::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/lvm pvs --config " devices { preferred_names =3D = [\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 = disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { = locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } = backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units = b --nosuffix --separator | -o = uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,= dev_size' (cwd None) MainThread::DEBUG::2012-05-11 = 14:46:04,006::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 MainThread::DEBUG::2012-05-11 = 14:46:04,006::lvm::358::OperationMutex::(_reloadpvs) Operation 'lvm = reload operation' released the operation mutex MainThread::DEBUG::2012-05-11 = 14:46:04,006::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm = reload operation' got the operation mutex MainThread::DEBUG::2012-05-11 = 14:46:04,007::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/lvm vgs --config " devices { preferred_names =3D = [\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 = disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { = locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } = backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units = b --nosuffix --separator | -o = uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_s= ize,vg_mda_free' (cwd None) MainThread::DEBUG::2012-05-11 = 14:46:04,021::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ' No volume groups found\n'; <rc> =3D 0 MainThread::DEBUG::2012-05-11 = 14:46:04,021::lvm::395::OperationMutex::(_reloadvgs) Operation 'lvm = reload operation' released the operation mutex MainThread::DEBUG::2012-05-11 = 14:46:04,022::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/lvm lvs --config " devices { preferred_names =3D = [\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 = disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { = locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } = backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units = b --nosuffix --separator | -o = uuid,name,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None) MainThread::DEBUG::2012-05-11 = 14:46:04,035::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ' No volume groups found\n'; <rc> =3D 0 Thread-12::DEBUG::2012-05-11 = 14:46:04,036::misc::1068::SamplingMethod::(__call__) Trying to enter = sampling method (storage.sdc.refreshStorage) MainThread::INFO::2012-05-11 = 14:46:04,038::dispatcher::95::Storage.Dispatcher::(__init__) Starting = StorageDispatcher... Thread-12::DEBUG::2012-05-11 = 14:46:04,038::misc::1070::SamplingMethod::(__call__) Got in to sampling = method Thread-12::DEBUG::2012-05-11 = 14:46:04,039::misc::1068::SamplingMethod::(__call__) Trying to enter = sampling method (storage.iscsi.rescan) Thread-12::DEBUG::2012-05-11 = 14:46:04,039::misc::1070::SamplingMethod::(__call__) Got in to sampling = method Thread-12::DEBUG::2012-05-11 = 14:46:04,041::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/iscsiadm -m session -R' (cwd None) MainThread::DEBUG::2012-05-11 = 14:46:04,047::__init__::1164::Storage.Misc.excCmd::(_log) = '/usr/bin/pgrep -xf ksmd' (cwd None) Thread-12::DEBUG::2012-05-11 = 14:46:04,055::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = =3D 'iscsiadm: No session found.\n'; <rc> =3D 21 Thread-12::DEBUG::2012-05-11 = 14:46:04,055::misc::1078::SamplingMethod::(__call__) Returning last = result MainThread::DEBUG::2012-05-11 = 14:46:04,060::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 MainThread::INFO::2012-05-11 = 14:46:04,061::vmChannels::139::vds::(settimeout) Setting channels' = timeout to 30 seconds. VM Channels Listener::INFO::2012-05-11 = 14:46:04,061::vmChannels::127::vds::(run) Starting VM channels listener = thread. Thread-12::DEBUG::2012-05-11 = 14:46:05,989::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/multipath' (cwd None) Thread-12::DEBUG::2012-05-11 = 14:46:06,034::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-12::DEBUG::2012-05-11 = 14:46:06,034::lvm::476::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-12::DEBUG::2012-05-11 = 14:46:06,035::lvm::478::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-12::DEBUG::2012-05-11 = 14:46:06,035::lvm::488::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' got the operation mutex Thread-12::DEBUG::2012-05-11 = 14:46:06,035::lvm::490::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' released the operation mutex Thread-12::DEBUG::2012-05-11 = 14:46:06,035::lvm::509::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-12::DEBUG::2012-05-11 = 14:46:06,036::lvm::511::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-12::DEBUG::2012-05-11 = 14:46:06,036::misc::1078::SamplingMethod::(__call__) Returning last = result Thread-12::DEBUG::2012-05-11 = 14:46:06,036::hsm::360::Storage.HSM::(__cleanStorageRepository) Started = cleaning storage repository at '/rhev/data-center' Thread-12::DEBUG::2012-05-11 = 14:46:06,037::hsm::392::Storage.HSM::(__cleanStorageRepository) White = list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', = '/rhev/data-center/mnt'] Thread-12::DEBUG::2012-05-11 = 14:46:06,037::hsm::393::Storage.HSM::(__cleanStorageRepository) Mount = list: ['/rhev/data-center/mnt/cmcd-heilig.in.hwlab:_exports_iso'] Thread-12::DEBUG::2012-05-11 = 14:46:06,038::hsm::395::Storage.HSM::(__cleanStorageRepository) Cleaning = leftovers Thread-12::DEBUG::2012-05-11 = 14:46:06,038::hsm::438::Storage.HSM::(__cleanStorageRepository) Finished = cleaning storage repository at '/rhev/data-center' Thread-14::DEBUG::2012-05-11 = 14:46:12,314::BindingXMLRPC::864::vds::(wrapper) client = [10.0.8.19]::call getCapabilities with () {} flowID [6ffec560] Thread-14::DEBUG::2012-05-11 = 14:46:12,407::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd = None) Thread-14::DEBUG::2012-05-11 = 14:46:12,423::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-14::DEBUG::2012-05-11 = 14:46:12,424::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd = None) Thread-14::DEBUG::2012-05-11 = 14:46:12,440::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-14::DEBUG::2012-05-11 = 14:46:12,441::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None) Thread-14::DEBUG::2012-05-11 = 14:46:12,456::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-14::DEBUG::2012-05-11 = 14:46:12,456::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' = (cwd None) Thread-14::DEBUG::2012-05-11 = 14:46:12,471::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-14::DEBUG::2012-05-11 = 14:46:12,471::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd = None) Thread-14::DEBUG::2012-05-11 = 14:46:12,487::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-14::DEBUG::2012-05-11 = 14:46:12,693::BindingXMLRPC::870::vds::(wrapper) return getCapabilities = with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': = {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:7d1774a24633'}], = 'FC': []}, 'packages2': {'kernel': {'release': '220.13.1.el6.x86_64', = 'buildtime': 1334721394.0, 'version': '2.6.32'}, 'spice-server': = {'release': '5.el6', 'buildtime': '1323304307', 'version': '0.8.2'}, = 'vdsm': {'release': '0.150.git63061a9.el6', 'buildtime': '1335602535', = 'version': '4.9.6'}, 'qemu-kvm': {'release': '2.209.el6_2.4', = 'buildtime': '1327354003', 'version': '0.12.1.2'}, 'libvirt': = {'release': '23.el6_2.8', 'buildtime': '1334928354', 'version': = '0.9.4'}, 'qemu-img': {'release': '2.209.el6_2.4', 'buildtime': = '1327354003', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM)2 = Quad CPU Q9650 @ 3.00GHz', 'hooks': {}, 'vmTypes': ['kvm'], = 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': = '10.0.10.18', 'cfg': {'IPV6INIT': 'yes', 'MTU': '1500', 'DELAY': '0', = 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'dhcp', 'DEVICE': 'ovirtmgmt', = 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': = '255.255.255.0', 'stp': 'off', 'bridged': 'True', 'gateway': = '10.0.10.254', 'ports': ['eth0']}}, 'uuid': = '295894AA-8E10-4A53-9090-002128263408_00:21:28:26:34:08', = 'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': = '00:21:28:26:34:08', 'netmask': '', 'speed': 1000, 'addr': '', 'mtu': = '1500'}}, 'software_revision': '0', 'management_ip': '', = 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': = u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,mtrr,pge,mca,cmov,pat,pse36,clfl= ush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,lm,constant_tsc,arc= h_perfmon,pebs,bts,rep_good,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,smx,e= st,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,xsave,lahf_lm,dts,tpr_shadow,vnmi,flexp= riority,model_Conroe,model_Penryn', 'ISCSIInitiatorName': = 'iqn.1994-05.com.redhat:7d1774a24633', 'memSize': '1989', 'reservedMem': = '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', = 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': = {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], = 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': = '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, = 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': = [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, = 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': = '00:00:00:00:00:00'}}, 'software_version': '4.9', 'cpuSpeed': = '2997.678', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', = 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], = 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.2.0', u'pc', = u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], = 'operatingSystem': {'release': '2.el6.centos.7', 'version': '6', 'name': = 'oVirt Node'}, 'lastClient': '0.0.0.0'}} Thread-15::DEBUG::2012-05-11 = 14:46:13,984::BindingXMLRPC::864::vds::(wrapper) client = [10.0.8.19]::call getCapabilities with () {} flowID [51e33141] Thread-15::DEBUG::2012-05-11 = 14:46:13,998::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd = None) Thread-15::DEBUG::2012-05-11 = 14:46:14,015::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-15::DEBUG::2012-05-11 = 14:46:14,016::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd = None) Thread-15::DEBUG::2012-05-11 = 14:46:14,032::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-15::DEBUG::2012-05-11 = 14:46:14,033::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None) Thread-15::DEBUG::2012-05-11 = 14:46:14,048::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-15::DEBUG::2012-05-11 = 14:46:14,048::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' = (cwd None) Thread-15::DEBUG::2012-05-11 = 14:46:14,063::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-15::DEBUG::2012-05-11 = 14:46:14,064::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q = --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd = None) Thread-15::DEBUG::2012-05-11 = 14:46:14,079::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-15::DEBUG::2012-05-11 = 14:46:14,080::BindingXMLRPC::870::vds::(wrapper) return getCapabilities = with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': = {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:7d1774a24633'}], = 'FC': []}, 'packages2': {'kernel': {'release': '220.13.1.el6.x86_64', = 'buildtime': 1334721394.0, 'version': '2.6.32'}, 'spice-server': = {'release': '5.el6', 'buildtime': '1323304307', 'version': '0.8.2'}, = 'vdsm': {'release': '0.150.git63061a9.el6', 'buildtime': '1335602535', = 'version': '4.9.6'}, 'qemu-kvm': {'release': '2.209.el6_2.4', = 'buildtime': '1327354003', 'version': '0.12.1.2'}, 'libvirt': = {'release': '23.el6_2.8', 'buildtime': '1334928354', 'version': = '0.9.4'}, 'qemu-img': {'release': '2.209.el6_2.4', 'buildtime': = '1327354003', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM)2 = Quad CPU Q9650 @ 3.00GHz', 'hooks': {}, 'vmTypes': ['kvm'], = 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': = '10.0.10.18', 'cfg': {'IPV6INIT': 'yes', 'MTU': '1500', 'DELAY': '0', = 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'dhcp', 'DEVICE': 'ovirtmgmt', = 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': = '255.255.255.0', 'stp': 'off', 'bridged': 'True', 'gateway': = '10.0.10.254', 'ports': ['eth0']}}, 'uuid': = '295894AA-8E10-4A53-9090-002128263408_00:21:28:26:34:08', = 'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': = '00:21:28:26:34:08', 'netmask': '', 'speed': 1000, 'addr': '', 'mtu': = '1500'}}, 'software_revision': '0', 'management_ip': '', = 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': = u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,mtrr,pge,mca,cmov,pat,pse36,clfl= ush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,lm,constant_tsc,arc= h_perfmon,pebs,bts,rep_good,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,smx,e= st,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,xsave,lahf_lm,dts,tpr_shadow,vnmi,flexp= riority,model_Conroe,model_Penryn', 'ISCSIInitiatorName': = 'iqn.1994-05.com.redhat:7d1774a24633', 'memSize': '1989', 'reservedMem': = '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', = 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': = {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], = 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': = '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, = 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': = [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, = 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': = '00:00:00:00:00:00'}}, 'software_version': '4.9', 'cpuSpeed': = '2997.678', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', = 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], = 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.2.0', u'pc', = u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], = 'operatingSystem': {'release': '2.el6.centos.7', 'version': '6', 'name': = 'oVirt Node'}, 'lastClient': '10.0.8.19'}} Thread-17::DEBUG::2012-05-11 = 14:46:14,243::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19] Thread-17::DEBUG::2012-05-11 = 14:46:14,244::task::588::TaskManager.Task::(_updateState) = Task=3D`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::moving from state init -> = state preparing Thread-17::INFO::2012-05-11 = 14:46:14,244::logUtils::37::dispatcher::(wrapper) Run and protect: = validateStorageServerConnection(domType=3D1, = spUUID=3D'af5bcc86-898a-11e1-9632-003048c85226', conList=3D[{'connection':= 'cmcd-heilig.in.hwlab:/exports/iso', 'iqn': '', 'portal': '', 'user': = '', 'password': '******', 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226', = 'port': ''}], options=3DNone) Thread-17::INFO::2012-05-11 = 14:46:14,244::logUtils::39::dispatcher::(wrapper) Run and protect: = validateStorageServerConnection, Return response: {'statuslist': = [{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]} Thread-17::DEBUG::2012-05-11 = 14:46:14,245::task::1172::TaskManager.Task::(prepare) = Task=3D`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::finished: {'statuslist': = [{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]} Thread-17::DEBUG::2012-05-11 = 14:46:14,245::task::588::TaskManager.Task::(_updateState) = Task=3D`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::moving from state = preparing -> state finished Thread-17::DEBUG::2012-05-11 = 14:46:14,245::resourceManager::809::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {} Thread-17::DEBUG::2012-05-11 = 14:46:14,245::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {} Thread-17::DEBUG::2012-05-11 = 14:46:14,246::task::978::TaskManager.Task::(_decref) = Task=3D`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::ref 0 aborting False Thread-18::DEBUG::2012-05-11 = 14:46:14,256::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19] Thread-18::DEBUG::2012-05-11 = 14:46:14,256::task::588::TaskManager.Task::(_updateState) = Task=3D`3b868a60-fa19-4fb6-a52d-21caecc9435d`::moving from state init -> = state preparing Thread-18::INFO::2012-05-11 = 14:46:14,257::logUtils::37::dispatcher::(wrapper) Run and protect: = connectStorageServer(domType=3D1, = spUUID=3D'af5bcc86-898a-11e1-9632-003048c85226', conList=3D[{'connection':= 'cmcd-heilig.in.hwlab:/exports/iso', 'iqn': '', 'portal': '', 'user': = '', 'password': '******', 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226', = 'port': ''}], options=3DNone) Thread-18::DEBUG::2012-05-11 = 14:46:14,257::lvm::476::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-18::DEBUG::2012-05-11 = 14:46:14,258::lvm::478::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-18::DEBUG::2012-05-11 = 14:46:14,258::lvm::488::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' got the operation mutex Thread-18::DEBUG::2012-05-11 = 14:46:14,258::lvm::490::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' released the operation mutex Thread-18::DEBUG::2012-05-11 = 14:46:14,258::lvm::509::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-18::DEBUG::2012-05-11 = 14:46:14,259::lvm::511::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-18::INFO::2012-05-11 = 14:46:14,259::logUtils::39::dispatcher::(wrapper) Run and protect: = connectStorageServer, Return response: {'statuslist': [{'status': 0, = 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]} Thread-18::DEBUG::2012-05-11 = 14:46:14,259::task::1172::TaskManager.Task::(prepare) = Task=3D`3b868a60-fa19-4fb6-a52d-21caecc9435d`::finished: {'statuslist': = [{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]} Thread-18::DEBUG::2012-05-11 = 14:46:14,259::task::588::TaskManager.Task::(_updateState) = Task=3D`3b868a60-fa19-4fb6-a52d-21caecc9435d`::moving from state = preparing -> state finished Thread-18::DEBUG::2012-05-11 = 14:46:14,260::resourceManager::809::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {} Thread-18::DEBUG::2012-05-11 = 14:46:14,260::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {} Thread-18::DEBUG::2012-05-11 = 14:46:14,260::task::978::TaskManager.Task::(_decref) = Task=3D`3b868a60-fa19-4fb6-a52d-21caecc9435d`::ref 0 aborting False Thread-19::DEBUG::2012-05-11 = 14:46:14,277::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19] Thread-19::DEBUG::2012-05-11 = 14:46:14,278::task::588::TaskManager.Task::(_updateState) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state init -> = state preparing Thread-19::INFO::2012-05-11 = 14:46:14,278::logUtils::37::dispatcher::(wrapper) Run and protect: = connectStoragePool(spUUID=3D'af5bcc86-898a-11e1-9632-003048c85226', = hostID=3D2, scsiKey=3D'af5bcc86-898a-11e1-9632-003048c85226', = msdUUID=3D'e12a0f53-ee72-44bc-ad26-93f9b4613c6c', masterVersion=3D1, = options=3DNone) Thread-19::DEBUG::2012-05-11 = 14:46:14,278::resourceManager::175::ResourceManager.Request::(__init__) = ResName=3D`Storage.af5bcc86-898a-11e1-9632-003048c85226`ReqID=3D`cdef54e1-= af49-4429-aecb-4d0dbf971fb5`::Request was made in = '/usr/share/vdsm/storage/resourceManager.py' line '485' at = 'registerResource' Thread-19::DEBUG::2012-05-11 = 14:46:14,279::resourceManager::486::ResourceManager::(registerResource) = Trying to register resource = 'Storage.af5bcc86-898a-11e1-9632-003048c85226' for lock type 'exclusive' Thread-19::DEBUG::2012-05-11 = 14:46:14,279::resourceManager::528::ResourceManager::(registerResource) = Resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' is free. Now = locking as 'exclusive' (1 active user) Thread-19::DEBUG::2012-05-11 = 14:46:14,279::resourceManager::212::ResourceManager.Request::(grant) = ResName=3D`Storage.af5bcc86-898a-11e1-9632-003048c85226`ReqID=3D`cdef54e1-= af49-4429-aecb-4d0dbf971fb5`::Granted request Thread-19::INFO::2012-05-11 = 14:46:14,280::sp::625::Storage.StoragePool::(connect) Connect host #2 to = the storage pool af5bcc86-898a-11e1-9632-003048c85226 with master = domain: e12a0f53-ee72-44bc-ad26-93f9b4613c6c (ver =3D 1) Thread-19::DEBUG::2012-05-11 = 14:46:14,280::lvm::476::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:14,280::lvm::478::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:14,281::lvm::488::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' got the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:14,281::lvm::490::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' released the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:14,281::lvm::509::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:14,281::lvm::511::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:14,281::misc::1068::SamplingMethod::(__call__) Trying to enter = sampling method (storage.sdc.refreshStorage) Thread-19::DEBUG::2012-05-11 = 14:46:14,282::misc::1070::SamplingMethod::(__call__) Got in to sampling = method Thread-19::DEBUG::2012-05-11 = 14:46:14,282::misc::1068::SamplingMethod::(__call__) Trying to enter = sampling method (storage.iscsi.rescan) Thread-19::DEBUG::2012-05-11 = 14:46:14,282::misc::1070::SamplingMethod::(__call__) Got in to sampling = method Thread-19::DEBUG::2012-05-11 = 14:46:14,282::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/iscsiadm -m session -R' (cwd None) Thread-19::DEBUG::2012-05-11 = 14:46:14,293::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = =3D 'iscsiadm: No session found.\n'; <rc> =3D 21 Thread-19::DEBUG::2012-05-11 = 14:46:14,294::misc::1078::SamplingMethod::(__call__) Returning last = result Thread-19::DEBUG::2012-05-11 = 14:46:16,226::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/multipath' (cwd None) Thread-19::DEBUG::2012-05-11 = 14:46:16,308::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-19::DEBUG::2012-05-11 = 14:46:16,309::lvm::476::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:16,309::lvm::478::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:16,309::lvm::488::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' got the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:16,309::lvm::490::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' released the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:16,310::lvm::509::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:16,310::lvm::511::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:16,310::misc::1078::SamplingMethod::(__call__) Returning last = result Thread-19::DEBUG::2012-05-11 = 14:46:16,310::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm = reload operation' got the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:16,311::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/lvm vgs --config " devices { preferred_names =3D = [\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 = disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { = locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } = backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units = b --nosuffix --separator | -o = uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_s= ize,vg_mda_free e12a0f53-ee72-44bc-ad26-93f9b4613c6c' (cwd None) Thread-19::DEBUG::2012-05-11 = 14:46:16,328::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = =3D ' Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found\n'; = <rc> =3D 5 Thread-19::WARNING::2012-05-11 = 14:46:16,328::lvm::372::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] = [' Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found'] Thread-19::DEBUG::2012-05-11 = 14:46:16,329::lvm::395::OperationMutex::(_reloadvgs) Operation 'lvm = reload operation' released the operation mutex Thread-19::DEBUG::2012-05-11 = 14:46:16,833::resourceManager::538::ResourceManager::(releaseResource) = Trying to release resource = 'Storage.af5bcc86-898a-11e1-9632-003048c85226' Thread-19::DEBUG::2012-05-11 = 14:46:16,834::resourceManager::553::ResourceManager::(releaseResource) = Released resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' (0 = active users) Thread-19::DEBUG::2012-05-11 = 14:46:16,834::resourceManager::558::ResourceManager::(releaseResource) = Resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' is free, finding = out if anyone is waiting for it. Thread-19::DEBUG::2012-05-11 = 14:46:16,834::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource = 'Storage.af5bcc86-898a-11e1-9632-003048c85226', Clearing records. Thread-19::ERROR::2012-05-11 = 14:46:16,835::task::853::TaskManager.Task::(_setError) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 861, in _run return fn(*args, **kargs) File "/usr/share/vdsm/logUtils.py", line 38, in wrapper res =3D f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 815, in connectStoragePool return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, = masterVersion, options) File "/usr/share/vdsm/storage/hsm.py", line 857, in = _connectStoragePool res =3D pool.connect(hostID, scsiKey, msdUUID, masterVersion) File "/usr/share/vdsm/storage/sp.py", line 641, in connect self.__rebuild(msdUUID=3DmsdUUID, masterVersion=3DmasterVersion) File "/usr/share/vdsm/storage/sp.py", line 1109, in __rebuild self.masterDomain =3D self.getMasterDomain(msdUUID=3DmsdUUID, = masterVersion=3DmasterVersion) File "/usr/share/vdsm/storage/sp.py", line 1448, in getMasterDomain raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID) StoragePoolMasterNotFound: Cannot find master domain: = 'spUUID=3Daf5bcc86-898a-11e1-9632-003048c85226, = msdUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c' Thread-19::DEBUG::2012-05-11 = 14:46:16,837::task::872::TaskManager.Task::(_run) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::Task._run: = 5616c854-e704-4014-bb58-8ca757e8137f = ('af5bcc86-898a-11e1-9632-003048c85226', 2, = 'af5bcc86-898a-11e1-9632-003048c85226', = 'e12a0f53-ee72-44bc-ad26-93f9b4613c6c', 1) {} failed - stopping task Thread-19::DEBUG::2012-05-11 = 14:46:16,837::task::1199::TaskManager.Task::(stop) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::stopping in state = preparing (force False) Thread-19::DEBUG::2012-05-11 = 14:46:16,838::task::978::TaskManager.Task::(_decref) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::ref 1 aborting True Thread-19::INFO::2012-05-11 = 14:46:16,838::task::1157::TaskManager.Task::(prepare) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::aborting: Task is = aborted: 'Cannot find master domain' - code 304 Thread-19::DEBUG::2012-05-11 = 14:46:16,838::task::1162::TaskManager.Task::(prepare) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::Prepare: aborted: Cannot = find master domain Thread-19::DEBUG::2012-05-11 = 14:46:16,838::task::978::TaskManager.Task::(_decref) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::ref 0 aborting True Thread-19::DEBUG::2012-05-11 = 14:46:16,839::task::913::TaskManager.Task::(_doAbort) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::Task._doAbort: force = False Thread-19::DEBUG::2012-05-11 = 14:46:16,839::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {} Thread-19::DEBUG::2012-05-11 = 14:46:16,839::task::588::TaskManager.Task::(_updateState) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state = preparing -> state aborting Thread-19::DEBUG::2012-05-11 = 14:46:16,839::task::537::TaskManager.Task::(__state_aborting) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::_aborting: recover policy = none Thread-19::DEBUG::2012-05-11 = 14:46:16,839::task::588::TaskManager.Task::(_updateState) = Task=3D`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state = aborting -> state failed Thread-19::DEBUG::2012-05-11 = 14:46:16,840::resourceManager::809::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {} Thread-19::DEBUG::2012-05-11 = 14:46:16,840::resourceManager::844::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {} Thread-19::ERROR::2012-05-11 = 14:46:16,840::dispatcher::66::Storage.Dispatcher.Protect::(run) = {'status': {'message': "Cannot find master domain: = 'spUUID=3Daf5bcc86-898a-11e1-9632-003048c85226, = msdUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c'", 'code': 304}} --Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A Content-Disposition: attachment; filename=vdsm_log_ref.txt Content-Type: text/plain; name="vdsm_log_ref.txt" Content-Transfer-Encoding: quoted-printable Thread-12::DEBUG::2012-04-19 = 12:29:53,779::hsm::359::Storage.HSM::(__cleanStorageRepository) Started = cleaning storage repository at '/rhev/data-center' Thread-18::DEBUG::2012-04-19 = 12:29:53,780::misc::1101::SamplingMethod::(__call__) Trying to enter = sampling method (storage.iscsi.rescan) Thread-12::DEBUG::2012-04-19 = 12:29:53,781::hsm::391::Storage.HSM::(__cleanStorageRepository) White = list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', = '/rhev/data-center/mnt'] Thread-18::DEBUG::2012-04-19 = 12:29:53,781::misc::1103::SamplingMethod::(__call__) Got in to sampling = method Thread-12::DEBUG::2012-04-19 = 12:29:53,781::hsm::392::Storage.HSM::(__cleanStorageRepository) Mount = list: ['/rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt'] Thread-18::DEBUG::2012-04-19 = 12:29:53,781::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/iscsiadm -m session -R' (cwd None) Thread-12::DEBUG::2012-04-19 = 12:29:53,781::hsm::394::Storage.HSM::(__cleanStorageRepository) Cleaning = leftovers Thread-12::DEBUG::2012-04-19 = 12:29:53,786::hsm::437::Storage.HSM::(__cleanStorageRepository) Finished = cleaning storage repository at '/rhev/data-center' Thread-18::DEBUG::2012-04-19 = 12:29:53,794::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = =3D 'iscsiadm: No session found.\n'; <rc> =3D 21 Thread-18::DEBUG::2012-04-19 = 12:29:53,795::misc::1111::SamplingMethod::(__call__) Returning last = result Thread-18::DEBUG::2012-04-19 = 12:29:55,715::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/multipath' (cwd None) Thread-18::DEBUG::2012-04-19 = 12:29:55,760::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ''; <rc> =3D 0 Thread-18::DEBUG::2012-04-19 = 12:29:55,760::lvm::474::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:55,761::lvm::476::OperationMutex::(_invalidateAllPvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:55,761::lvm::486::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' got the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:55,761::lvm::488::OperationMutex::(_invalidateAllVgs) Operation = 'lvm invalidate operation' released the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:55,761::lvm::507::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' got the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:55,762::lvm::509::OperationMutex::(_invalidateAllLvs) Operation = 'lvm invalidate operation' released the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:55,762::misc::1111::SamplingMethod::(__call__) Returning last = result Thread-18::DEBUG::2012-04-19 = 12:29:55,762::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm = reload operation' got the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:55,763::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/lvm vgs --config " devices { preferred_names =3D = [\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 = disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { = locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } = backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units = b --nosuffix --separator | -o = uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_s= ize,vg_mda_free e12a0f53-ee72-44bc-ad26-93f9b4613c6c' (cwd None) Thread-18::DEBUG::2012-04-19 = 12:29:55,781::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = =3D ' Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found\n'; = <rc> =3D 5 Thread-18::WARNING::2012-04-19 = 12:29:55,782::lvm::370::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] = [' Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found'] Thread-18::DEBUG::2012-04-19 = 12:29:55,782::lvm::393::OperationMutex::(_reloadvgs) Operation 'lvm = reload operation' released the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:56,392::fileSD::101::Storage.StorageDomain::(__init__) Reading = domain in path = /rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt/e12a0f53-ee72-44= bc-ad26-93f9b4613c6c Thread-18::DEBUG::2012-04-19 = 12:29:56,393::persistentDict::175::Storage.PersistentDict::(__init__) = Created a persistant dict with FileMetadataRW backend Thread-18::DEBUG::2012-04-19 = 12:29:56,403::persistentDict::216::Storage.PersistentDict::(refresh) = read lines (FileMetadataRW)=3D['CLASS=3DData', 'DESCRIPTION=3Dglusternfs',= 'IOOPTIMEOUTSEC=3D10', 'LEASERETRIES=3D3', 'LEASETIMESEC=3D60', = 'LOCKPOLICY=3D', 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION=3D1', = 'POOL_DESCRIPTION=3DDefault', = 'POOL_DOMAINS=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active', = 'POOL_SPM_ID=3D1', 'POOL_SPM_LVER=3D0', = 'POOL_UUID=3Daf5bcc86-898a-11e1-9632-003048c85226', = 'REMOTE_PATH=3Dcmcd-db-vip.in.hwlab:/vmstore/ovirt', 'ROLE=3DMaster', = 'SDUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c', 'TYPE=3DNFS', = 'VERSION=3D0', '_SHA_CKSUM=3D3b71084c285a0ba4f74aaba162dae64224b6d8ff'] Thread-18::DEBUG::2012-04-19 = 12:29:56,407::fileSD::324::Storage.StorageDomain::(imageGarbageCollector) = Removing remnants of deleted images [] Thread-18::DEBUG::2012-04-19 = 12:29:56,407::resourceManager::379::ResourceManager::(registerNamespace) = Registering namespace 'e12a0f53-ee72-44bc-ad26-93f9b4613c6c_imageNS' Thread-18::DEBUG::2012-04-19 = 12:29:56,408::resourceManager::379::ResourceManager::(registerNamespace) = Registering namespace 'e12a0f53-ee72-44bc-ad26-93f9b4613c6c_volumeNS' Thread-18::DEBUG::2012-04-19 = 12:29:56,408::sp::1460::Storage.StoragePool::(getMasterDomain) Master = domain e12a0f53-ee72-44bc-ad26-93f9b4613c6c verified, version 1 Thread-18::DEBUG::2012-04-19 = 12:29:56,408::misc::1101::SamplingMethod::(__call__) Trying to enter = sampling method (storage.sp.updateMonitoringThreads) Thread-18::DEBUG::2012-04-19 = 12:29:56,409::misc::1103::SamplingMethod::(__call__) Got in to sampling = method Thread-18::DEBUG::2012-04-19 = 12:29:56,413::persistentDict::216::Storage.PersistentDict::(refresh) = read lines (FileMetadataRW)=3D['CLASS=3DData', 'DESCRIPTION=3Dglusternfs',= 'IOOPTIMEOUTSEC=3D10', 'LEASERETRIES=3D3', 'LEASETIMESEC=3D60', = 'LOCKPOLICY=3D', 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION=3D1', = 'POOL_DESCRIPTION=3DDefault', = 'POOL_DOMAINS=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c:Active', = 'POOL_SPM_ID=3D1', 'POOL_SPM_LVER=3D0', = 'POOL_UUID=3Daf5bcc86-898a-11e1-9632-003048c85226', = 'REMOTE_PATH=3Dcmcd-db-vip.in.hwlab:/vmstore/ovirt', 'ROLE=3DMaster', = 'SDUUID=3De12a0f53-ee72-44bc-ad26-93f9b4613c6c', 'TYPE=3DNFS', = 'VERSION=3D0', '_SHA_CKSUM=3D3b71084c285a0ba4f74aaba162dae64224b6d8ff'] Thread-18::DEBUG::2012-04-19 = 12:29:56,414::sp::1490::Storage.StoragePool::(updateMonitoringThreads) = sp `af5bcc86-898a-11e1-9632-003048c85226` started monitoring domain = `e12a0f53-ee72-44bc-ad26-93f9b4613c6c` Thread-18::DEBUG::2012-04-19 = 12:29:56,415::misc::1111::SamplingMethod::(__call__) Returning last = result Thread-18::DEBUG::2012-04-19 = 12:29:56,417::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm = reload operation' got the operation mutex Thread-18::DEBUG::2012-04-19 = 12:29:56,417::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo = -n /sbin/lvm vgs --config " devices { preferred_names =3D = [\\"^/dev/mapper/\\"] ignore_suspended_devices=3D1 write_cache_state=3D0 = disable_after_error_count=3D3 filter =3D [ \\"r%.*%\\" ] } global { = locking_type=3D1 prioritise_write_locks=3D1 wait_for_locks=3D1 } = backup { retain_min =3D 50 retain_days =3D 0 } " --noheadings --units = b --nosuffix --separator | -o = uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_s= ize,vg_mda_free' (cwd None) Thread-18::DEBUG::2012-04-19 = 12:29:56,444::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = =3D ' No volume groups found\n'; <rc> =3D 0 Thread-18::DEBUG::2012-04-19 = 12:29:56,444::lvm::393::OperationMutex::(_reloadvgs) Operation 'lvm = reload operation' released the operation mutex Thread-18::INFO::2012-04-19 = 12:29:56,447::sp::1062::Storage.StoragePool::(_linkStorageDomain) = Linking = /rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt/e12a0f53-ee72-44= bc-ad26-93f9b4613c6c to = /rhev/data-center/af5bcc86-898a-11e1-9632-003048c85226/e12a0f53-ee72-44bc-= ad26-93f9b4613c6c Thread-18::INFO::2012-04-19 = 12:29:56,448::sp::1062::Storage.StoragePool::(_linkStorageDomain) = Linking = /rhev/data-center/mnt/cmcd-db-vip.in.hwlab:_vmstore_ovirt/e12a0f53-ee72-44= bc-ad26-93f9b4613c6c to = /rhev/data-center/af5bcc86-898a-11e1-9632-003048c85226/mastersd Thread-18::DEBUG::2012-04-19 = 12:29:56,448::resourceManager::538::ResourceManager::(releaseResource) = Trying to release resource = 'Storage.af5bcc86-898a-11e1-9632-003048c85226' Thread-18::DEBUG::2012-04-19 = 12:29:56,449::resourceManager::553::ResourceManager::(releaseResource) = Released resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' (0 = active users) Thread-18::DEBUG::2012-04-19 = 12:29:56,449::resourceManager::558::ResourceManager::(releaseResource) = Resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' is free, finding = out if anyone is waiting for it. Thread-18::DEBUG::2012-04-19 = 12:29:56,449::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource = 'Storage.af5bcc86-898a-11e1-9632-003048c85226', Clearing records. Thread-18::INFO::2012-04-19 = 12:29:56,449::logUtils::39::dispatcher::(wrapper) Run and protect: = connectStoragePool, Return response: True Thread-18::DEBUG::2012-04-19 = 12:29:56,450::task::1172::TaskManager.Task::(prepare) = Task=3D`7f46d378-c3b9-41ed-9ede-33e7e69cd440`::finished: True Thread-18::DEBUG::2012-04-19 = 12:29:56,450::task::588::TaskManager.Task::(_updateState) = Task=3D`7f46d378-c3b9-41ed-9ede-33e7e69cd440`::moving from state = preparing -> state finished= --Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=us-ascii --Apple-Mail=_F8D56058-7ED6-475C-845C-01F4F3ECE10A--

On May 11, 2012, at 3:09 PM, Ian Levesque wrote: Is there any further troubleshooting I can do before giving up on this? Thanks, Ian