Thanks for sharing this experience Latchezar.  Thankfully our engine is up and healthy, just currently bound to one machine.  An attempt to add a second host fails (because, I think, the hosted_engine storage is not present).  We are doing nightly backups of the engine which includes copying the backup file off to stable storage elsewhere.

I do have a machine sitting idle at the moment that I can use as a restore target for the engine.  At this point I am inclined to remain with the hosted engine as it has been stable up to this point. Of course this may change at which point we will re-evaluate a stand-alone engine hosts.


From: Latchezar Filtchev <Latcho@aubg.bg>
Sent: Thursday, March 19, 2020 10:42 AM
To: Brian Youngstrom <BrianY@alleninstitute.org>; users@ovirt.org <users@ovirt.org>
Subject: RE: [ovirt-users] 3.6-- hosted_storage volume not importing
 
CAUTION: This email originated from outside the Allen Institute. Please do not click links or open attachments unless you've validated the sender and know the content is safe.
________________________________

Hello Brian,

A few months ago I was in the following situation:

oVirt 4.2.6 Self hosted engine installed  on iSCSI domain; separate iSCSI data domain for virtual machines. I started getting notifications for storage failure. On the second storage I created new iSCSI domain, attached it to DC and live migrate VM's to new iSCSI data domain. A few days later the first storage failed. I was not able to migrate self-hosted data domain from failed storage (practically I lost it).
So I had all VM's  up and running but no oVirt engine. Several days I spent in attempts to recover oVirt self-hosted engine to new data domain (fortunately I had backups) with no luck.
What worked for me was to return from backup oVirt engine on separate physical machine. Thus I've got back control on running virtual machines and virtualization nodes. Based on lessons learned I decided to have more frequent oVirt engine backups  and continue to operate without self-hosted engine.
So if you have a spare physical machine you can try to recover oVirt engine from backup and upgrade it (virtualization nodes, data centers, clusters)  to the newer oVirt version without taking care of oVirt engine self-hosted data domain.
Please be noted - this may not work in your case!
Thank you!
Best,
Latcho



-----Original Message-----
From: briany@alleninstitute.org <briany@alleninstitute.org>
Sent: Wednesday, March 18, 2020 7:41 PM
To: users@ovirt.org
Subject: [ovirt-users] 3.6-- hosted_storage volume not importing

Hello,

I have been working to upgrade our long-neglected oVirt cluster from v3.5 to v4.3.  Our upgrade from v3.5 to 3.6 is mostly complete except the hosted_storage volume is not importing.  None of the tricks that I have come across have helped so far. I am hoping someone can help us complete this step so we can continue with the next set of upgrades.

Our upgrade to 3.6 was not completely straight forward.  We needed to move the hosted engine itself to new nfs storage.  This was done by performing an in-place upgrade of the engine from 3.5 to 3.6, taking a backup, then restoring this to a new engine appliance hosted on the new nfs storage target.  The new engine was never able to fully import the hosted_engine volume. This volume remained in a locked state.  Following [0], I destroyed the volume from the Admin UI. The volume has yet to be re-imported.

Log snippets and installed rpm lists are below.

We have two Data Centers configured, each with one Cluster and two data domains (all nfs). All components have been updated to v3.6 compatibility levels.

Any ideas on what our next steps should be so we can continue the upgrade process?

Many thanks,
-Brian


[0] https://nam12.safelinks.protection.outlook.com/?url=https%3A%2F%2Faccess.redhat.com%2Fsolutions%2F2592761&amp;data=02%7C01%7C%7Cf044032ed14f4e4d0bd108d7cc2ce5dd%7C32669cd6737f4b398bddd6951120d3fc%7C0%7C1%7C637202365566899917&amp;sdata=vPZBTOjwKxONlpLqfed8Kg6Fb1BnHf8DHYEwzbyUfFg%3D&amp;reserved=0



Installed packages
libgovirt-0.3.3-4.el7.x86_64
ovirt-engine-appliance-3.6-20160623.1.el7.centos.noarch
ovirt-engine-sdk-python-3.6.7.0-1.el7.centos.noarch
ovirt-host-deploy-1.4.1-1.el7.centos.noarch
ovirt-hosted-engine-ha-1.3.5.7-1.el7.centos.noarch
ovirt-hosted-engine-setup-1.3.7.2-1.el7.centos.noarch
ovirt-release36-3.6.7-3.el7.centos.noarch
ovirt-setup-lib-1.0.1-1.el7.centos.noarch
ovirt-vmconsole-1.0.2-1.el7.centos.noarch
ovirt-vmconsole-host-1.0.2-1.el7.centos.noarch
vdsm-4.17.32-1.el7.noarch
vdsm-cli-4.17.32-1.el7.noarch
vdsm-hook-vmfex-dev-4.17.32-1.el7.noarch
vdsm-infra-4.17.32-1.el7.noarch
vdsm-jsonrpc-4.17.32-1.el7.noarch
vdsm-python-4.17.32-1.el7.noarch
vdsm-xmlrpc-4.17.32-1.el7.noarch
vdsm-yajsonrpc-4.17.32-1.el7.noarch


--- agent.log ---
This set of log entries are on repeat

MainThread::INFO::2020-03-18 09:39:48,230::hosted_engine::613::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_initialize_vdsm) Initializing VDSM
MainThread::INFO::2020-03-18 09:39:48,260::hosted_engine::658::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_initialize_storage_images) Connecting the storage
MainThread::INFO::2020-03-18 09:39:48,260::storage_server::218::ovirt_hosted_engine_ha.lib.storage_server.StorageServer::(connect_storage_server) Connecting storage server
MainThread::INFO::2020-03-18 09:39:48,279::storage_server::222::ovirt_hosted_engine_ha.lib.storage_server.StorageServer::(connect_storage_server) Connecting storage server
MainThread::INFO::2020-03-18 09:39:48,287::storage_server::230::ovirt_hosted_engine_ha.lib.storage_server.StorageServer::(connect_storage_server) Refreshing the storage domain
MainThread::INFO::2020-03-18 09:39:48,413::hosted_engine::685::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_initialize_storage_images) Preparing images
MainThread::INFO::2020-03-18 09:39:48,414::image::126::ovirt_hosted_engine_ha.lib.image.Image::(prepare_images) Preparing images
MainThread::INFO::2020-03-18 09:39:48,545::hosted_engine::688::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_initialize_storage_images) Reloading vm.conf from the shared storage domain
MainThread::INFO::2020-03-18 09:39:48,546::config::206::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine.config::(refresh_local_conf_file) Trying to get a fresher copy of vm configuration from the OVF_STORE
MainThread::INFO::2020-03-18 09:39:48,608::ovf_store::100::ovirt_hosted_engine_ha.lib.ovf.ovf_store.OVFStore::(scan) Found OVF_STORE: imgUUID:00ad81a7-5637-40ff-8635-c039347f69ee, volUUID:ec87b10a-e601-44bc-bd87-fbe6de274cd4
MainThread::INFO::2020-03-18 09:39:48,662::ovf_store::100::ovirt_hosted_engine_ha.lib.ovf.ovf_store.OVFStore::(scan) Found OVF_STORE: imgUUID:63491779-c7cf-434c-84c9-7878694a8946, volUUID:2f086a70-e97d-4161-a232-1268bb3145de
MainThread::INFO::2020-03-18 09:39:48,662::ovf_store::109::ovirt_hosted_engine_ha.lib.ovf.ovf_store.OVFStore::(getEngineVMOVF) Extracting Engine VM OVF from the OVF_STORE
MainThread::INFO::2020-03-18 09:39:48,662::ovf_store::116::ovirt_hosted_engine_ha.lib.ovf.ovf_store.OVFStore::(getEngineVMOVF) OVF_STORE volume path: /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de
MainThread::ERROR::2020-03-18 09:39:48,670::ovf_store::121::ovirt_hosted_engine_ha.lib.ovf.ovf_store.OVFStore::(getEngineVMOVF) Unable to extract HEVM OVF
MainThread::ERROR::2020-03-18 09:39:48,670::config::235::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine.config::(refresh_local_conf_file) Unable to get vm.conf from OVF_STORE, falling back to initial vm.conf
MainThread::INFO::2020-03-18 09:39:48,714::hosted_engine::462::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(start_monitoring) Current state EngineUp (score: 3400)
MainThread::INFO::2020-03-18 09:39:58,762::states::421::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(consume) Engine vm running on localhost

--- vsdm.log ---
Reactor thread::INFO::2020-03-18 09:39:48,253::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42646
Reactor thread::DEBUG::2020-03-18 09:39:48,257::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,257::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42646
Reactor thread::DEBUG::2020-03-18 09:39:48,258::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42646)
BindingXMLRPC::INFO::2020-03-18 09:39:48,258::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42646
Thread-450::INFO::2020-03-18 09:39:48,258::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42646 started
Thread-450::DEBUG::2020-03-18 09:39:48,258::bindingxmlrpc::1262::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-450::DEBUG::2020-03-18 09:39:48,259::bindingxmlrpc::1269::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL380 Gen10', 'systemUUID': '32303250-3534-4D32-3239-333730323753', 'systemSerialNumber': '2M2937027S', 'systemFamily': 'ProLiant', 'systemManufacturer': 'HPE'}}
Thread-450::INFO::2020-03-18 09:39:48,260::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42646 stopped
Reactor thread::INFO::2020-03-18 09:39:48,261::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42648
Reactor thread::DEBUG::2020-03-18 09:39:48,264::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,265::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42648
Reactor thread::DEBUG::2020-03-18 09:39:48,265::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42648)
BindingXMLRPC::INFO::2020-03-18 09:39:48,265::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42648
Thread-451::INFO::2020-03-18 09:39:48,265::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42648 started
Thread-451::DEBUG::2020-03-18 09:39:48,265::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-451::DEBUG::2020-03-18 09:39:48,265::task::595::Storage.TaskManager.Task::(_updateState) Task=`084fd462-75f9-4a76-93c8-3e4432d988d9`::moving from state init -> state preparing
Thread-451::INFO::2020-03-18 09:39:48,266::logUtils::48::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', options=None)
Thread-451::INFO::2020-03-18 09:39:48,266::fileSD::357::Storage.StorageDomain::(validate) sdUUID=331e6287-61df-48dd-9733-a8ad236750b1
Thread-451::DEBUG::2020-03-18 09:39:48,267::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=00000002-0002-0002-0002-000000000357', 'REMOTE_PATH=aidc-nap1-n1.corp.alleninstitute.org:/netapp_engine_36', 'ROLE=Regular', 'SDUUID=331e6287-61df-48dd-9733-a8ad236750b1', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=87c4db40d7fcee58986a7e2669f5bd20e99cf807']
Thread-451::DEBUG::2020-03-18 09:39:48,267::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`028654fb-b9a6-4c40-93d6-bc8f223d2681`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2838' at 'getStorageDomainInfo'
Thread-451::DEBUG::2020-03-18 09:39:48,267::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-451::DEBUG::2020-03-18 09:39:48,267::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-451::DEBUG::2020-03-18 09:39:48,267::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`028654fb-b9a6-4c40-93d6-bc8f223d2681`::Granted request
Thread-451::DEBUG::2020-03-18 09:39:48,268::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`084fd462-75f9-4a76-93c8-3e4432d988d9`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-451::DEBUG::2020-03-18 09:39:48,268::task::993::Storage.TaskManager.Task::(_decref) Task=`084fd462-75f9-4a76-93c8-3e4432d988d9`::ref 1 aborting False
Thread-451::INFO::2020-03-18 09:39:48,269::logUtils::51::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': u'331e6287-61df-48dd-9733-a8ad236750b1', 'version': '3', 'role': 'Regular', 'remotePath': 'aidc-nap1-n1.corp.alleninstitute.org:/netapp_engine_36', 'type': 'NFS', 'class': 'Data', 'pool': ['00000002-0002-0002-0002-000000000357'], 'name': 'hosted_storage'}}
Thread-451::DEBUG::2020-03-18 09:39:48,269::task::1191::Storage.TaskManager.Task::(prepare) Task=`084fd462-75f9-4a76-93c8-3e4432d988d9`::finished: {'info': {'uuid': u'331e6287-61df-48dd-9733-a8ad236750b1', 'version': '3', 'role': 'Regular', 'remotePath': 'aidc-nap1-n1.corp.alleninstitute.org:/netapp_engine_36', 'type': 'NFS', 'class': 'Data', 'pool': ['00000002-0002-0002-0002-000000000357'], 'name': 'hosted_storage'}}
Thread-451::DEBUG::2020-03-18 09:39:48,269::task::595::Storage.TaskManager.Task::(_updateState) Task=`084fd462-75f9-4a76-93c8-3e4432d988d9`::moving from state preparing -> state finished
Thread-451::DEBUG::2020-03-18 09:39:48,269::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-451::DEBUG::2020-03-18 09:39:48,270::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-451::DEBUG::2020-03-18 09:39:48,270::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-451::DEBUG::2020-03-18 09:39:48,270::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-451::DEBUG::2020-03-18 09:39:48,270::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-451::DEBUG::2020-03-18 09:39:48,270::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-451::DEBUG::2020-03-18 09:39:48,270::task::993::Storage.TaskManager.Task::(_decref) Task=`084fd462-75f9-4a76-93c8-3e4432d988d9`::ref 0 aborting False
Thread-451::INFO::2020-03-18 09:39:48,270::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42648 stopped
Reactor thread::INFO::2020-03-18 09:39:48,271::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42650
Reactor thread::DEBUG::2020-03-18 09:39:48,274::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,274::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42650
Reactor thread::DEBUG::2020-03-18 09:39:48,274::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42650)
BindingXMLRPC::INFO::2020-03-18 09:39:48,275::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42650
Thread-452::INFO::2020-03-18 09:39:48,275::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42650 started
Thread-452::DEBUG::2020-03-18 09:39:48,275::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-452::DEBUG::2020-03-18 09:39:48,275::task::595::Storage.TaskManager.Task::(_updateState) Task=`5060fa58-3c70-404c-a037-1438228d69c2`::moving from state init -> state preparing
Thread-452::INFO::2020-03-18 09:39:48,275::logUtils::48::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', options=None)
Thread-452::INFO::2020-03-18 09:39:48,275::fileSD::357::Storage.StorageDomain::(validate) sdUUID=331e6287-61df-48dd-9733-a8ad236750b1
Thread-452::DEBUG::2020-03-18 09:39:48,276::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=00000002-0002-0002-0002-000000000357', 'REMOTE_PATH=aidc-nap1-n1.corp.alleninstitute.org:/netapp_engine_36', 'ROLE=Regular', 'SDUUID=331e6287-61df-48dd-9733-a8ad236750b1', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=87c4db40d7fcee58986a7e2669f5bd20e99cf807']
Thread-452::DEBUG::2020-03-18 09:39:48,276::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`222a340e-20b8-4bd0-ade1-9b0ca6cb320d`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2838' at 'getStorageDomainInfo'
Thread-452::DEBUG::2020-03-18 09:39:48,276::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-452::DEBUG::2020-03-18 09:39:48,276::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-452::DEBUG::2020-03-18 09:39:48,277::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`222a340e-20b8-4bd0-ade1-9b0ca6cb320d`::Granted request
Thread-452::DEBUG::2020-03-18 09:39:48,277::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`5060fa58-3c70-404c-a037-1438228d69c2`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-452::DEBUG::2020-03-18 09:39:48,277::task::993::Storage.TaskManager.Task::(_decref) Task=`5060fa58-3c70-404c-a037-1438228d69c2`::ref 1 aborting False
Thread-452::INFO::2020-03-18 09:39:48,278::logUtils::51::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': u'331e6287-61df-48dd-9733-a8ad236750b1', 'version': '3', 'role': 'Regular', 'remotePath': 'aidc-nap1-n1.corp.alleninstitute.org:/netapp_engine_36', 'type': 'NFS', 'class': 'Data', 'pool': ['00000002-0002-0002-0002-000000000357'], 'name': 'hosted_storage'}}
Thread-452::DEBUG::2020-03-18 09:39:48,278::task::1191::Storage.TaskManager.Task::(prepare) Task=`5060fa58-3c70-404c-a037-1438228d69c2`::finished: {'info': {'uuid': u'331e6287-61df-48dd-9733-a8ad236750b1', 'version': '3', 'role': 'Regular', 'remotePath': 'aidc-nap1-n1.corp.alleninstitute.org:/netapp_engine_36', 'type': 'NFS', 'class': 'Data', 'pool': ['00000002-0002-0002-0002-000000000357'], 'name': 'hosted_storage'}}
Thread-452::DEBUG::2020-03-18 09:39:48,278::task::595::Storage.TaskManager.Task::(_updateState) Task=`5060fa58-3c70-404c-a037-1438228d69c2`::moving from state preparing -> state finished
Thread-452::DEBUG::2020-03-18 09:39:48,278::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-452::DEBUG::2020-03-18 09:39:48,279::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-452::DEBUG::2020-03-18 09:39:48,279::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-452::DEBUG::2020-03-18 09:39:48,279::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-452::DEBUG::2020-03-18 09:39:48,279::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-452::DEBUG::2020-03-18 09:39:48,279::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-452::DEBUG::2020-03-18 09:39:48,279::task::993::Storage.TaskManager.Task::(_decref) Task=`5060fa58-3c70-404c-a037-1438228d69c2`::ref 0 aborting False
Thread-452::INFO::2020-03-18 09:39:48,279::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42650 stopped
Reactor thread::INFO::2020-03-18 09:39:48,280::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42652
Reactor thread::DEBUG::2020-03-18 09:39:48,283::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,283::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42652
Reactor thread::DEBUG::2020-03-18 09:39:48,283::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42652)
BindingXMLRPC::INFO::2020-03-18 09:39:48,284::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42652
Thread-453::INFO::2020-03-18 09:39:48,284::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42652 started
Thread-453::DEBUG::2020-03-18 09:39:48,284::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-453::DEBUG::2020-03-18 09:39:48,284::task::595::Storage.TaskManager.Task::(_updateState) Task=`024ef770-6c34-4f8d-bee6-f1828e4a5369`::moving from state init -> state preparing
Thread-453::INFO::2020-03-18 09:39:48,284::logUtils::48::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'protocol_version': 3, 'connection': 'aidc-nap1-n1.corp.alleninstitute.org:/netapp_engine_36', 'user': 'kvm', 'id': 'd24257f1-b48c-44f0-a5cb-9061e7ce30ba'}], options=None)
Thread-453::DEBUG::2020-03-18 09:39:48,286::hsm::2413::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36
Thread-453::DEBUG::2020-03-18 09:39:48,287::hsm::2437::Storage.HSM::(__prefetchDomains) Found SD uuids: (u'331e6287-61df-48dd-9733-a8ad236750b1',)
Thread-453::DEBUG::2020-03-18 09:39:48,287::hsm::2497::Storage.HSM::(connectStorageServer) knownSDs: {331e6287-61df-48dd-9733-a8ad236750b1: storage.nfsSD.findDomain}
Thread-453::INFO::2020-03-18 09:39:48,287::logUtils::51::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'd24257f1-b48c-44f0-a5cb-9061e7ce30ba'}]}
Thread-453::DEBUG::2020-03-18 09:39:48,287::task::1191::Storage.TaskManager.Task::(prepare) Task=`024ef770-6c34-4f8d-bee6-f1828e4a5369`::finished: {'statuslist': [{'status': 0, 'id': 'd24257f1-b48c-44f0-a5cb-9061e7ce30ba'}]}
Thread-453::DEBUG::2020-03-18 09:39:48,287::task::595::Storage.TaskManager.Task::(_updateState) Task=`024ef770-6c34-4f8d-bee6-f1828e4a5369`::moving from state preparing -> state finished
Thread-453::DEBUG::2020-03-18 09:39:48,287::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-453::DEBUG::2020-03-18 09:39:48,287::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-453::DEBUG::2020-03-18 09:39:48,287::task::993::Storage.TaskManager.Task::(_decref) Task=`024ef770-6c34-4f8d-bee6-f1828e4a5369`::ref 0 aborting False
Thread-453::INFO::2020-03-18 09:39:48,287::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42652 stopped
Reactor thread::INFO::2020-03-18 09:39:48,288::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42654
Reactor thread::DEBUG::2020-03-18 09:39:48,291::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,291::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42654
Reactor thread::DEBUG::2020-03-18 09:39:48,292::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42654)
BindingXMLRPC::INFO::2020-03-18 09:39:48,292::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42654
Thread-454::INFO::2020-03-18 09:39:48,292::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42654 started
Thread-454::DEBUG::2020-03-18 09:39:48,292::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-454::DEBUG::2020-03-18 09:39:48,292::task::595::Storage.TaskManager.Task::(_updateState) Task=`87423fea-b0d6-4ce8-8da4-65fe9fdd060f`::moving from state init -> state preparing
Thread-454::INFO::2020-03-18 09:39:48,292::logUtils::48::dispatcher::(wrapper) Run and protect: getStorageDomainStats(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', options=None)
Thread-454::DEBUG::2020-03-18 09:39:48,292::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`bc4187c3-65c8-48d5-90b8-74eac77fd4f0`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2856' at 'getStorageDomainStats'
Thread-454::DEBUG::2020-03-18 09:39:48,292::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-454::DEBUG::2020-03-18 09:39:48,292::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-454::DEBUG::2020-03-18 09:39:48,293::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`bc4187c3-65c8-48d5-90b8-74eac77fd4f0`::Granted request
Thread-454::DEBUG::2020-03-18 09:39:48,293::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`87423fea-b0d6-4ce8-8da4-65fe9fdd060f`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-454::DEBUG::2020-03-18 09:39:48,293::task::993::Storage.TaskManager.Task::(_decref) Task=`87423fea-b0d6-4ce8-8da4-65fe9fdd060f`::ref 1 aborting False
Thread-454::DEBUG::2020-03-18 09:39:48,293::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-454::DEBUG::2020-03-18 09:39:48,293::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-454::DEBUG::2020-03-18 09:39:48,293::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-454::DEBUG::2020-03-18 09:39:48,293::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-454::DEBUG::2020-03-18 09:39:48,293::iscsi::434::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-454::DEBUG::2020-03-18 09:39:48,293::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/taskset --cpu-list 0-31 /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
Thread-454::DEBUG::2020-03-18 09:39:48,305::misc::760::Storage.SamplingMethod::(__call__) Returning last result
Thread-454::DEBUG::2020-03-18 09:39:48,305::misc::750::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
Thread-454::DEBUG::2020-03-18 09:39:48,306::misc::753::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-454::DEBUG::2020-03-18 09:39:48,306::hba::56::Storage.HBA::(rescan) Starting scan
Thread-454::DEBUG::2020-03-18 09:39:48,356::hba::62::Storage.HBA::(rescan) Scan finished
Thread-454::DEBUG::2020-03-18 09:39:48,356::misc::760::Storage.SamplingMethod::(__call__) Returning last result
Thread-454::DEBUG::2020-03-18 09:39:48,357::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/taskset --cpu-list 0-31 /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
Thread-454::DEBUG::2020-03-18 09:39:48,396::multipath::77::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-454::DEBUG::2020-03-18 09:39:48,397::utils::671::root::(execCmd) /usr/bin/taskset --cpu-list 0-31 /sbin/udevadm settle --timeout=5 (cwd None)
Thread-454::DEBUG::2020-03-18 09:39:48,403::utils::689::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-454::DEBUG::2020-03-18 09:39:48,404::lvm::497::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-454::DEBUG::2020-03-18 09:39:48,404::lvm::499::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-454::DEBUG::2020-03-18 09:39:48,404::lvm::508::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-454::DEBUG::2020-03-18 09:39:48,404::lvm::510::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-454::DEBUG::2020-03-18 09:39:48,404::lvm::528::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-454::DEBUG::2020-03-18 09:39:48,404::lvm::530::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-454::DEBUG::2020-03-18 09:39:48,404::misc::760::Storage.SamplingMethod::(__call__) Returning last result
Thread-454::DEBUG::2020-03-18 09:39:48,408::fileSD::157::Storage.StorageDomainManifest::(__init__) Reading domain in path /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1
Thread-454::DEBUG::2020-03-18 09:39:48,409::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-454::DEBUG::2020-03-18 09:39:48,410::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=00000002-0002-0002-0002-000000000357', 'REMOTE_PATH=aidc-nap1-n1.corp.alleninstitute.org:/netapp_engine_36', 'ROLE=Regular', 'SDUUID=331e6287-61df-48dd-9733-a8ad236750b1', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=87c4db40d7fcee58986a7e2669f5bd20e99cf807']
Thread-454::DEBUG::2020-03-18 09:39:48,411::fileSD::671::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-454::INFO::2020-03-18 09:39:48,411::sd::442::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 331e6287-61df-48dd-9733-a8ad236750b1_imageNS already registered
Thread-454::INFO::2020-03-18 09:39:48,411::sd::450::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 331e6287-61df-48dd-9733-a8ad236750b1_volumeNS already registered
Thread-454::INFO::2020-03-18 09:39:48,412::logUtils::51::dispatcher::(wrapper) Run and protect: getStorageDomainStats, Return response: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '98607497216', 'disktotal': '102005473280', 'mdafree': 0}}
Thread-454::DEBUG::2020-03-18 09:39:48,412::task::1191::Storage.TaskManager.Task::(prepare) Task=`87423fea-b0d6-4ce8-8da4-65fe9fdd060f`::finished: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '98607497216', 'disktotal': '102005473280', 'mdafree': 0}}
Thread-454::DEBUG::2020-03-18 09:39:48,412::task::595::Storage.TaskManager.Task::(_updateState) Task=`87423fea-b0d6-4ce8-8da4-65fe9fdd060f`::moving from state preparing -> state finished
Thread-454::DEBUG::2020-03-18 09:39:48,412::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-454::DEBUG::2020-03-18 09:39:48,412::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-454::DEBUG::2020-03-18 09:39:48,412::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-454::DEBUG::2020-03-18 09:39:48,412::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-454::DEBUG::2020-03-18 09:39:48,412::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-454::DEBUG::2020-03-18 09:39:48,412::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-454::DEBUG::2020-03-18 09:39:48,413::task::993::Storage.TaskManager.Task::(_decref) Task=`87423fea-b0d6-4ce8-8da4-65fe9fdd060f`::ref 0 aborting False
Thread-454::INFO::2020-03-18 09:39:48,413::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42654 stopped
Reactor thread::INFO::2020-03-18 09:39:48,414::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42656
Reactor thread::DEBUG::2020-03-18 09:39:48,418::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,418::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42656
Reactor thread::DEBUG::2020-03-18 09:39:48,418::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42656)
BindingXMLRPC::INFO::2020-03-18 09:39:48,418::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42656
Thread-461::INFO::2020-03-18 09:39:48,418::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42656 started
Thread-461::DEBUG::2020-03-18 09:39:48,419::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-461::DEBUG::2020-03-18 09:39:48,419::task::595::Storage.TaskManager.Task::(_updateState) Task=`0e25784b-3d90-414c-906f-9568b6a9e08c`::moving from state init -> state preparing
Thread-461::INFO::2020-03-18 09:39:48,419::logUtils::48::dispatcher::(wrapper) Run and protect: getImagesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', options=None)
Thread-461::DEBUG::2020-03-18 09:39:48,419::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`cd0116aa-4843-41ef-b5f7-fedca913c4de`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3313' at 'getImagesList'
Thread-461::DEBUG::2020-03-18 09:39:48,419::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-461::DEBUG::2020-03-18 09:39:48,419::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-461::DEBUG::2020-03-18 09:39:48,419::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`cd0116aa-4843-41ef-b5f7-fedca913c4de`::Granted request
Thread-461::DEBUG::2020-03-18 09:39:48,419::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`0e25784b-3d90-414c-906f-9568b6a9e08c`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-461::DEBUG::2020-03-18 09:39:48,420::task::993::Storage.TaskManager.Task::(_decref) Task=`0e25784b-3d90-414c-906f-9568b6a9e08c`::ref 1 aborting False
Thread-461::INFO::2020-03-18 09:39:48,420::logUtils::51::dispatcher::(wrapper) Run and protect: getImagesList, Return response: {'imageslist': []}
Thread-461::DEBUG::2020-03-18 09:39:48,420::task::1191::Storage.TaskManager.Task::(prepare) Task=`0e25784b-3d90-414c-906f-9568b6a9e08c`::finished: {'imageslist': []}
Thread-461::DEBUG::2020-03-18 09:39:48,420::task::595::Storage.TaskManager.Task::(_updateState) Task=`0e25784b-3d90-414c-906f-9568b6a9e08c`::moving from state preparing -> state finished
Thread-461::DEBUG::2020-03-18 09:39:48,420::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-461::DEBUG::2020-03-18 09:39:48,420::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-461::DEBUG::2020-03-18 09:39:48,420::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-461::DEBUG::2020-03-18 09:39:48,420::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-461::DEBUG::2020-03-18 09:39:48,420::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-461::DEBUG::2020-03-18 09:39:48,420::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-461::DEBUG::2020-03-18 09:39:48,420::task::993::Storage.TaskManager.Task::(_decref) Task=`0e25784b-3d90-414c-906f-9568b6a9e08c`::ref 0 aborting False
Thread-461::INFO::2020-03-18 09:39:48,421::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42656 stopped
Reactor thread::INFO::2020-03-18 09:39:48,422::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42658
Reactor thread::DEBUG::2020-03-18 09:39:48,425::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,425::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42658
Reactor thread::DEBUG::2020-03-18 09:39:48,425::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42658)
BindingXMLRPC::INFO::2020-03-18 09:39:48,425::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42658
Thread-462::INFO::2020-03-18 09:39:48,425::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42658 started
Thread-462::DEBUG::2020-03-18 09:39:48,426::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-462::DEBUG::2020-03-18 09:39:48,426::task::595::Storage.TaskManager.Task::(_updateState) Task=`21627f7f-0ce8-49d9-858f-bb08682b0915`::moving from state init -> state preparing
Thread-462::INFO::2020-03-18 09:39:48,426::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='b9fd2434-60b0-4a5d-abb2-adc358d0dfd1', options=None)
Thread-462::DEBUG::2020-03-18 09:39:48,426::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`7ed6ca2b-709c-439b-afbc-7782d275d9f7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-462::DEBUG::2020-03-18 09:39:48,426::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-462::DEBUG::2020-03-18 09:39:48,426::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-462::DEBUG::2020-03-18 09:39:48,426::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`7ed6ca2b-709c-439b-afbc-7782d275d9f7`::Granted request
Thread-462::DEBUG::2020-03-18 09:39:48,426::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`21627f7f-0ce8-49d9-858f-bb08682b0915`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-462::DEBUG::2020-03-18 09:39:48,427::task::993::Storage.TaskManager.Task::(_decref) Task=`21627f7f-0ce8-49d9-858f-bb08682b0915`::ref 1 aborting False
Thread-462::INFO::2020-03-18 09:39:48,429::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'53d31c6e-bfc3-4dee-99be-f0fa77006cad']}
Thread-462::DEBUG::2020-03-18 09:39:48,429::task::1191::Storage.TaskManager.Task::(prepare) Task=`21627f7f-0ce8-49d9-858f-bb08682b0915`::finished: {'uuidlist': [u'53d31c6e-bfc3-4dee-99be-f0fa77006cad']}
Thread-462::DEBUG::2020-03-18 09:39:48,429::task::595::Storage.TaskManager.Task::(_updateState) Task=`21627f7f-0ce8-49d9-858f-bb08682b0915`::moving from state preparing -> state finished
Thread-462::DEBUG::2020-03-18 09:39:48,429::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-462::DEBUG::2020-03-18 09:39:48,429::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-462::DEBUG::2020-03-18 09:39:48,430::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-462::DEBUG::2020-03-18 09:39:48,430::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-462::DEBUG::2020-03-18 09:39:48,430::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-462::DEBUG::2020-03-18 09:39:48,430::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-462::DEBUG::2020-03-18 09:39:48,430::task::993::Storage.TaskManager.Task::(_decref) Task=`21627f7f-0ce8-49d9-858f-bb08682b0915`::ref 0 aborting False
Thread-462::INFO::2020-03-18 09:39:48,430::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42658 stopped
Reactor thread::INFO::2020-03-18 09:39:48,431::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42660
Reactor thread::DEBUG::2020-03-18 09:39:48,434::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,434::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42660
Reactor thread::DEBUG::2020-03-18 09:39:48,434::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42660)
BindingXMLRPC::INFO::2020-03-18 09:39:48,434::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42660
Thread-463::INFO::2020-03-18 09:39:48,434::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42660 started
Thread-463::DEBUG::2020-03-18 09:39:48,435::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-463::DEBUG::2020-03-18 09:39:48,435::task::595::Storage.TaskManager.Task::(_updateState) Task=`c62cf17c-ac63-49d1-ac7b-cf1fa5494aee`::moving from state init -> state preparing
Thread-463::INFO::2020-03-18 09:39:48,435::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='b9fd2434-60b0-4a5d-abb2-adc358d0dfd1', leafUUID='53d31c6e-bfc3-4dee-99be-f0fa77006cad')
Thread-463::DEBUG::2020-03-18 09:39:48,435::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`e20d6046-0f92-461d-a221-ddcfae6acd37`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3213' at 'prepareImage'
Thread-463::DEBUG::2020-03-18 09:39:48,435::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-463::DEBUG::2020-03-18 09:39:48,435::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-463::DEBUG::2020-03-18 09:39:48,435::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`e20d6046-0f92-461d-a221-ddcfae6acd37`::Granted request
Thread-463::DEBUG::2020-03-18 09:39:48,435::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`c62cf17c-ac63-49d1-ac7b-cf1fa5494aee`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-463::DEBUG::2020-03-18 09:39:48,435::task::993::Storage.TaskManager.Task::(_decref) Task=`c62cf17c-ac63-49d1-ac7b-cf1fa5494aee`::ref 1 aborting False
Thread-463::DEBUG::2020-03-18 09:39:48,438::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 53d31c6e-bfc3-4dee-99be-f0fa77006cad
Thread-463::DEBUG::2020-03-18 09:39:48,440::fileSD::560::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad
Thread-463::DEBUG::2020-03-18 09:39:48,440::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 mode: None
Thread-463::WARNING::2020-03-18 09:39:48,440::fileUtils::152::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 already exists
Thread-463::DEBUG::2020-03-18 09:39:48,440::fileSD::517::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1 to /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1
Thread-463::DEBUG::2020-03-18 09:39:48,440::fileSD::522::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1
Thread-463::DEBUG::2020-03-18 09:39:48,441::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 53d31c6e-bfc3-4dee-99be-f0fa77006cad
Thread-463::INFO::2020-03-18 09:39:48,441::logUtils::51::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'volumeID': u'53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad.lease', 'imageID': 'b9fd2434-60b0-4a5d-abb2-adc358d0dfd1'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'l
 easeOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'volumeID': u'53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad.lease', 'imageID': 'b9fd2434-60b0-4a5d-abb2-adc358d0dfd1'}]}
Thread-463::DEBUG::2020-03-18 09:39:48,441::task::1191::Storage.TaskManager.Task::(prepare) Task=`c62cf17c-ac63-49d1-ac7b-cf1fa5494aee`::finished: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'volumeID': u'53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad.lease', 'imageID': 'b9fd2434-60b0-4a5d-abb2-adc358d0dfd1'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', '
 volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'volumeID': u'53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad.lease', 'imageID': 'b9fd2434-60b0-4a5d-abb2-adc358d0dfd1'}]}
Thread-463::DEBUG::2020-03-18 09:39:48,441::task::595::Storage.TaskManager.Task::(_updateState) Task=`c62cf17c-ac63-49d1-ac7b-cf1fa5494aee`::moving from state preparing -> state finished
Thread-463::DEBUG::2020-03-18 09:39:48,441::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-463::DEBUG::2020-03-18 09:39:48,441::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-463::DEBUG::2020-03-18 09:39:48,441::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-463::DEBUG::2020-03-18 09:39:48,442::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-463::DEBUG::2020-03-18 09:39:48,442::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-463::DEBUG::2020-03-18 09:39:48,442::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-463::DEBUG::2020-03-18 09:39:48,442::task::993::Storage.TaskManager.Task::(_decref) Task=`c62cf17c-ac63-49d1-ac7b-cf1fa5494aee`::ref 0 aborting False
Thread-463::INFO::2020-03-18 09:39:48,443::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42660 stopped
Reactor thread::INFO::2020-03-18 09:39:48,443::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42662
Reactor thread::DEBUG::2020-03-18 09:39:48,446::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,447::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42662
Reactor thread::DEBUG::2020-03-18 09:39:48,447::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42662)
BindingXMLRPC::INFO::2020-03-18 09:39:48,447::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42662
Thread-464::INFO::2020-03-18 09:39:48,447::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42662 started
Thread-464::DEBUG::2020-03-18 09:39:48,447::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-464::DEBUG::2020-03-18 09:39:48,447::task::595::Storage.TaskManager.Task::(_updateState) Task=`55928ea1-0bb9-434a-839e-e339893ee197`::moving from state init -> state preparing
Thread-464::INFO::2020-03-18 09:39:48,447::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='a667b14a-1f92-40f1-8379-210e0c42fc26', options=None)
Thread-464::DEBUG::2020-03-18 09:39:48,448::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`db8e29d0-dc40-4e30-982c-7040544b86d0`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-464::DEBUG::2020-03-18 09:39:48,448::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-464::DEBUG::2020-03-18 09:39:48,448::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-464::DEBUG::2020-03-18 09:39:48,448::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`db8e29d0-dc40-4e30-982c-7040544b86d0`::Granted request
Thread-464::DEBUG::2020-03-18 09:39:48,448::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`55928ea1-0bb9-434a-839e-e339893ee197`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-464::DEBUG::2020-03-18 09:39:48,448::task::993::Storage.TaskManager.Task::(_decref) Task=`55928ea1-0bb9-434a-839e-e339893ee197`::ref 1 aborting False
Thread-464::INFO::2020-03-18 09:39:48,450::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'43cc29d0-6919-4493-95fe-6d58f97acdfc']}
Thread-464::DEBUG::2020-03-18 09:39:48,450::task::1191::Storage.TaskManager.Task::(prepare) Task=`55928ea1-0bb9-434a-839e-e339893ee197`::finished: {'uuidlist': [u'43cc29d0-6919-4493-95fe-6d58f97acdfc']}
Thread-464::DEBUG::2020-03-18 09:39:48,450::task::595::Storage.TaskManager.Task::(_updateState) Task=`55928ea1-0bb9-434a-839e-e339893ee197`::moving from state preparing -> state finished
Thread-464::DEBUG::2020-03-18 09:39:48,450::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-464::DEBUG::2020-03-18 09:39:48,450::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-464::DEBUG::2020-03-18 09:39:48,450::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-464::DEBUG::2020-03-18 09:39:48,451::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-464::DEBUG::2020-03-18 09:39:48,451::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-464::DEBUG::2020-03-18 09:39:48,451::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-464::DEBUG::2020-03-18 09:39:48,451::task::993::Storage.TaskManager.Task::(_decref) Task=`55928ea1-0bb9-434a-839e-e339893ee197`::ref 0 aborting False
Thread-464::INFO::2020-03-18 09:39:48,451::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42662 stopped
Reactor thread::INFO::2020-03-18 09:39:48,451::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42664
Reactor thread::DEBUG::2020-03-18 09:39:48,455::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,455::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42664
Reactor thread::DEBUG::2020-03-18 09:39:48,455::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42664)
BindingXMLRPC::INFO::2020-03-18 09:39:48,455::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42664
Thread-465::INFO::2020-03-18 09:39:48,455::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42664 started
Thread-465::DEBUG::2020-03-18 09:39:48,456::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-465::DEBUG::2020-03-18 09:39:48,456::task::595::Storage.TaskManager.Task::(_updateState) Task=`d239dab8-78ab-4fc0-8deb-9cd694f7b5c6`::moving from state init -> state preparing
Thread-465::INFO::2020-03-18 09:39:48,456::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='a667b14a-1f92-40f1-8379-210e0c42fc26', leafUUID='43cc29d0-6919-4493-95fe-6d58f97acdfc')
Thread-465::DEBUG::2020-03-18 09:39:48,456::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`9d41db4b-4b09-4805-8cb8-098b391447e6`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3213' at 'prepareImage'
Thread-465::DEBUG::2020-03-18 09:39:48,456::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-465::DEBUG::2020-03-18 09:39:48,456::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-465::DEBUG::2020-03-18 09:39:48,456::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`9d41db4b-4b09-4805-8cb8-098b391447e6`::Granted request
Thread-465::DEBUG::2020-03-18 09:39:48,456::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`d239dab8-78ab-4fc0-8deb-9cd694f7b5c6`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-465::DEBUG::2020-03-18 09:39:48,456::task::993::Storage.TaskManager.Task::(_decref) Task=`d239dab8-78ab-4fc0-8deb-9cd694f7b5c6`::ref 1 aborting False
Thread-465::DEBUG::2020-03-18 09:39:48,459::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 43cc29d0-6919-4493-95fe-6d58f97acdfc
Thread-465::DEBUG::2020-03-18 09:39:48,460::fileSD::560::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc
Thread-465::DEBUG::2020-03-18 09:39:48,460::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 mode: None
Thread-465::WARNING::2020-03-18 09:39:48,461::fileUtils::152::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 already exists
Thread-465::DEBUG::2020-03-18 09:39:48,461::fileSD::517::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26 to /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/a667b14a-1f92-40f1-8379-210e0c42fc26
Thread-465::DEBUG::2020-03-18 09:39:48,461::fileSD::522::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/a667b14a-1f92-40f1-8379-210e0c42fc26
Thread-465::DEBUG::2020-03-18 09:39:48,461::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 43cc29d0-6919-4493-95fe-6d58f97acdfc
Thread-465::INFO::2020-03-18 09:39:48,462::logUtils::51::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc', 'volumeID': u'43cc29d0-6919-4493-95fe-6d58f97acdfc', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc.lease', 'imageID': 'a667b14a-1f92-40f1-8379-210e0c42fc26'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'l
 easeOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc', 'volumeID': u'43cc29d0-6919-4493-95fe-6d58f97acdfc', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc.lease', 'imageID': 'a667b14a-1f92-40f1-8379-210e0c42fc26'}]}
Thread-465::DEBUG::2020-03-18 09:39:48,462::task::1191::Storage.TaskManager.Task::(prepare) Task=`d239dab8-78ab-4fc0-8deb-9cd694f7b5c6`::finished: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc', 'volumeID': u'43cc29d0-6919-4493-95fe-6d58f97acdfc', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc.lease', 'imageID': 'a667b14a-1f92-40f1-8379-210e0c42fc26'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', '
 volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc', 'volumeID': u'43cc29d0-6919-4493-95fe-6d58f97acdfc', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc.lease', 'imageID': 'a667b14a-1f92-40f1-8379-210e0c42fc26'}]}
Thread-465::DEBUG::2020-03-18 09:39:48,462::task::595::Storage.TaskManager.Task::(_updateState) Task=`d239dab8-78ab-4fc0-8deb-9cd694f7b5c6`::moving from state preparing -> state finished
Thread-465::DEBUG::2020-03-18 09:39:48,462::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-465::DEBUG::2020-03-18 09:39:48,462::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-465::DEBUG::2020-03-18 09:39:48,462::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-465::DEBUG::2020-03-18 09:39:48,462::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-465::DEBUG::2020-03-18 09:39:48,462::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-465::DEBUG::2020-03-18 09:39:48,462::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-465::DEBUG::2020-03-18 09:39:48,462::task::993::Storage.TaskManager.Task::(_decref) Task=`d239dab8-78ab-4fc0-8deb-9cd694f7b5c6`::ref 0 aborting False
Thread-465::INFO::2020-03-18 09:39:48,463::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42664 stopped
Reactor thread::INFO::2020-03-18 09:39:48,464::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42666
Reactor thread::DEBUG::2020-03-18 09:39:48,467::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,467::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42666
Reactor thread::DEBUG::2020-03-18 09:39:48,467::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42666)
BindingXMLRPC::INFO::2020-03-18 09:39:48,467::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42666
Thread-466::INFO::2020-03-18 09:39:48,467::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42666 started
Thread-466::DEBUG::2020-03-18 09:39:48,468::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-466::DEBUG::2020-03-18 09:39:48,468::task::595::Storage.TaskManager.Task::(_updateState) Task=`5d96e07f-0897-4066-a15f-33e8900f1cdd`::moving from state init -> state preparing
Thread-466::INFO::2020-03-18 09:39:48,468::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='00ad81a7-5637-40ff-8635-c039347f69ee', options=None)
Thread-466::DEBUG::2020-03-18 09:39:48,468::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`2eb15abe-9a97-437c-a79e-1fb7a8f2a1d9`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-466::DEBUG::2020-03-18 09:39:48,468::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-466::DEBUG::2020-03-18 09:39:48,468::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-466::DEBUG::2020-03-18 09:39:48,468::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`2eb15abe-9a97-437c-a79e-1fb7a8f2a1d9`::Granted request
Thread-466::DEBUG::2020-03-18 09:39:48,468::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`5d96e07f-0897-4066-a15f-33e8900f1cdd`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-466::DEBUG::2020-03-18 09:39:48,468::task::993::Storage.TaskManager.Task::(_decref) Task=`5d96e07f-0897-4066-a15f-33e8900f1cdd`::ref 1 aborting False
Thread-466::INFO::2020-03-18 09:39:48,470::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'ec87b10a-e601-44bc-bd87-fbe6de274cd4']}
Thread-466::DEBUG::2020-03-18 09:39:48,471::task::1191::Storage.TaskManager.Task::(prepare) Task=`5d96e07f-0897-4066-a15f-33e8900f1cdd`::finished: {'uuidlist': [u'ec87b10a-e601-44bc-bd87-fbe6de274cd4']}
Thread-466::DEBUG::2020-03-18 09:39:48,471::task::595::Storage.TaskManager.Task::(_updateState) Task=`5d96e07f-0897-4066-a15f-33e8900f1cdd`::moving from state preparing -> state finished
Thread-466::DEBUG::2020-03-18 09:39:48,471::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-466::DEBUG::2020-03-18 09:39:48,471::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-466::DEBUG::2020-03-18 09:39:48,471::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-466::DEBUG::2020-03-18 09:39:48,471::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-466::DEBUG::2020-03-18 09:39:48,471::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-466::DEBUG::2020-03-18 09:39:48,471::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-466::DEBUG::2020-03-18 09:39:48,471::task::993::Storage.TaskManager.Task::(_decref) Task=`5d96e07f-0897-4066-a15f-33e8900f1cdd`::ref 0 aborting False
Thread-466::INFO::2020-03-18 09:39:48,471::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42666 stopped
Reactor thread::INFO::2020-03-18 09:39:48,472::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42668
Reactor thread::DEBUG::2020-03-18 09:39:48,475::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,475::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42668
Reactor thread::DEBUG::2020-03-18 09:39:48,475::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42668)
BindingXMLRPC::INFO::2020-03-18 09:39:48,476::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42668
Thread-467::INFO::2020-03-18 09:39:48,476::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42668 started
Thread-467::DEBUG::2020-03-18 09:39:48,476::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-467::DEBUG::2020-03-18 09:39:48,476::task::595::Storage.TaskManager.Task::(_updateState) Task=`79c265c9-44b0-49ae-a7d0-df1f1fffbd28`::moving from state init -> state preparing
Thread-467::INFO::2020-03-18 09:39:48,476::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='00ad81a7-5637-40ff-8635-c039347f69ee', leafUUID='ec87b10a-e601-44bc-bd87-fbe6de274cd4')
Thread-467::DEBUG::2020-03-18 09:39:48,476::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`0f37c05b-323f-4806-80c8-bbedbbd79570`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3213' at 'prepareImage'
Thread-467::DEBUG::2020-03-18 09:39:48,476::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-467::DEBUG::2020-03-18 09:39:48,476::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-467::DEBUG::2020-03-18 09:39:48,476::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`0f37c05b-323f-4806-80c8-bbedbbd79570`::Granted request
Thread-467::DEBUG::2020-03-18 09:39:48,477::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`79c265c9-44b0-49ae-a7d0-df1f1fffbd28`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-467::DEBUG::2020-03-18 09:39:48,477::task::993::Storage.TaskManager.Task::(_decref) Task=`79c265c9-44b0-49ae-a7d0-df1f1fffbd28`::ref 1 aborting False
Thread-467::DEBUG::2020-03-18 09:39:48,479::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for ec87b10a-e601-44bc-bd87-fbe6de274cd4
Thread-467::DEBUG::2020-03-18 09:39:48,480::fileSD::560::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4
Thread-467::DEBUG::2020-03-18 09:39:48,481::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 mode: None
Thread-467::WARNING::2020-03-18 09:39:48,481::fileUtils::152::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 already exists
Thread-467::DEBUG::2020-03-18 09:39:48,481::fileSD::517::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee to /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/00ad81a7-5637-40ff-8635-c039347f69ee
Thread-467::DEBUG::2020-03-18 09:39:48,481::fileSD::522::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/00ad81a7-5637-40ff-8635-c039347f69ee
Thread-467::DEBUG::2020-03-18 09:39:48,481::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for ec87b10a-e601-44bc-bd87-fbe6de274cd4
Thread-467::INFO::2020-03-18 09:39:48,482::logUtils::51::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'volumeID': u'ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4.lease', 'imageID': '00ad81a7-5637-40ff-8635-c039347f69ee'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'l
 easeOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'volumeID': u'ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4.lease', 'imageID': '00ad81a7-5637-40ff-8635-c039347f69ee'}]}
Thread-467::DEBUG::2020-03-18 09:39:48,482::task::1191::Storage.TaskManager.Task::(prepare) Task=`79c265c9-44b0-49ae-a7d0-df1f1fffbd28`::finished: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'volumeID': u'ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4.lease', 'imageID': '00ad81a7-5637-40ff-8635-c039347f69ee'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', '
 volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'volumeID': u'ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4.lease', 'imageID': '00ad81a7-5637-40ff-8635-c039347f69ee'}]}
Thread-467::DEBUG::2020-03-18 09:39:48,482::task::595::Storage.TaskManager.Task::(_updateState) Task=`79c265c9-44b0-49ae-a7d0-df1f1fffbd28`::moving from state preparing -> state finished
Thread-467::DEBUG::2020-03-18 09:39:48,482::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-467::DEBUG::2020-03-18 09:39:48,482::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-467::DEBUG::2020-03-18 09:39:48,482::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-467::DEBUG::2020-03-18 09:39:48,482::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-467::DEBUG::2020-03-18 09:39:48,482::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-467::DEBUG::2020-03-18 09:39:48,482::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-467::DEBUG::2020-03-18 09:39:48,482::task::993::Storage.TaskManager.Task::(_decref) Task=`79c265c9-44b0-49ae-a7d0-df1f1fffbd28`::ref 0 aborting False
Thread-467::INFO::2020-03-18 09:39:48,483::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42668 stopped
Reactor thread::INFO::2020-03-18 09:39:48,483::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42670
Reactor thread::DEBUG::2020-03-18 09:39:48,487::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,487::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42670
Reactor thread::DEBUG::2020-03-18 09:39:48,487::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42670)
BindingXMLRPC::INFO::2020-03-18 09:39:48,488::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42670
Thread-468::INFO::2020-03-18 09:39:48,488::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42670 started
Thread-468::DEBUG::2020-03-18 09:39:48,488::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-468::DEBUG::2020-03-18 09:39:48,488::task::595::Storage.TaskManager.Task::(_updateState) Task=`f2658559-934e-4136-a702-50f303954be0`::moving from state init -> state preparing
Thread-468::INFO::2020-03-18 09:39:48,488::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='50cc8c63-9929-4cbc-aec8-f1d196874b72', options=None)
Thread-468::DEBUG::2020-03-18 09:39:48,488::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`f1ae25bc-437f-4971-bee4-bfa8c4ebee45`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-468::DEBUG::2020-03-18 09:39:48,488::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-468::DEBUG::2020-03-18 09:39:48,488::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-468::DEBUG::2020-03-18 09:39:48,489::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`f1ae25bc-437f-4971-bee4-bfa8c4ebee45`::Granted request
Thread-468::DEBUG::2020-03-18 09:39:48,489::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`f2658559-934e-4136-a702-50f303954be0`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-468::DEBUG::2020-03-18 09:39:48,489::task::993::Storage.TaskManager.Task::(_decref) Task=`f2658559-934e-4136-a702-50f303954be0`::ref 1 aborting False
Thread-468::INFO::2020-03-18 09:39:48,491::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0']}
Thread-468::DEBUG::2020-03-18 09:39:48,491::task::1191::Storage.TaskManager.Task::(prepare) Task=`f2658559-934e-4136-a702-50f303954be0`::finished: {'uuidlist': [u'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0']}
Thread-468::DEBUG::2020-03-18 09:39:48,491::task::595::Storage.TaskManager.Task::(_updateState) Task=`f2658559-934e-4136-a702-50f303954be0`::moving from state preparing -> state finished
Thread-468::DEBUG::2020-03-18 09:39:48,492::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-468::DEBUG::2020-03-18 09:39:48,492::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-468::DEBUG::2020-03-18 09:39:48,492::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-468::DEBUG::2020-03-18 09:39:48,492::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-468::DEBUG::2020-03-18 09:39:48,492::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-468::DEBUG::2020-03-18 09:39:48,492::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-468::DEBUG::2020-03-18 09:39:48,492::task::993::Storage.TaskManager.Task::(_decref) Task=`f2658559-934e-4136-a702-50f303954be0`::ref 0 aborting False
Thread-468::INFO::2020-03-18 09:39:48,492::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42670 stopped
Reactor thread::INFO::2020-03-18 09:39:48,493::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42672
Reactor thread::DEBUG::2020-03-18 09:39:48,496::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,496::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42672
Reactor thread::DEBUG::2020-03-18 09:39:48,496::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42672)
BindingXMLRPC::INFO::2020-03-18 09:39:48,496::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42672
Thread-469::INFO::2020-03-18 09:39:48,497::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42672 started
Thread-469::DEBUG::2020-03-18 09:39:48,497::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-469::DEBUG::2020-03-18 09:39:48,497::task::595::Storage.TaskManager.Task::(_updateState) Task=`224a4641-f77a-4fca-9ea7-393a17b105f1`::moving from state init -> state preparing
Thread-469::INFO::2020-03-18 09:39:48,497::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='50cc8c63-9929-4cbc-aec8-f1d196874b72', leafUUID='e8a4e709-0c98-4f1d-a42f-c5f0d499dca0')
Thread-469::DEBUG::2020-03-18 09:39:48,497::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`bc5c6e82-a5d1-43db-87ac-135224c3bcf5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3213' at 'prepareImage'
Thread-469::DEBUG::2020-03-18 09:39:48,497::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-469::DEBUG::2020-03-18 09:39:48,497::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-469::DEBUG::2020-03-18 09:39:48,497::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`bc5c6e82-a5d1-43db-87ac-135224c3bcf5`::Granted request
Thread-469::DEBUG::2020-03-18 09:39:48,498::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`224a4641-f77a-4fca-9ea7-393a17b105f1`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-469::DEBUG::2020-03-18 09:39:48,498::task::993::Storage.TaskManager.Task::(_decref) Task=`224a4641-f77a-4fca-9ea7-393a17b105f1`::ref 1 aborting False
Thread-469::DEBUG::2020-03-18 09:39:48,500::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for e8a4e709-0c98-4f1d-a42f-c5f0d499dca0
Thread-469::DEBUG::2020-03-18 09:39:48,501::fileSD::560::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0
Thread-469::DEBUG::2020-03-18 09:39:48,502::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 mode: None
Thread-469::WARNING::2020-03-18 09:39:48,502::fileUtils::152::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 already exists
Thread-469::DEBUG::2020-03-18 09:39:48,502::fileSD::517::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72 to /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/50cc8c63-9929-4cbc-aec8-f1d196874b72
Thread-469::DEBUG::2020-03-18 09:39:48,502::fileSD::522::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/50cc8c63-9929-4cbc-aec8-f1d196874b72
Thread-469::DEBUG::2020-03-18 09:39:48,502::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for e8a4e709-0c98-4f1d-a42f-c5f0d499dca0
Thread-469::INFO::2020-03-18 09:39:48,503::logUtils::51::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'volumeID': u'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0.lease', 'imageID': '50cc8c63-9929-4cbc-aec8-f1d196874b72'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'l
 easeOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'volumeID': u'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0.lease', 'imageID': '50cc8c63-9929-4cbc-aec8-f1d196874b72'}]}
Thread-469::DEBUG::2020-03-18 09:39:48,503::task::1191::Storage.TaskManager.Task::(prepare) Task=`224a4641-f77a-4fca-9ea7-393a17b105f1`::finished: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'volumeID': u'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0.lease', 'imageID': '50cc8c63-9929-4cbc-aec8-f1d196874b72'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', '
 volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'volumeID': u'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0.lease', 'imageID': '50cc8c63-9929-4cbc-aec8-f1d196874b72'}]}
Thread-469::DEBUG::2020-03-18 09:39:48,503::task::595::Storage.TaskManager.Task::(_updateState) Task=`224a4641-f77a-4fca-9ea7-393a17b105f1`::moving from state preparing -> state finished
Thread-469::DEBUG::2020-03-18 09:39:48,503::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-469::DEBUG::2020-03-18 09:39:48,503::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-469::DEBUG::2020-03-18 09:39:48,503::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-469::DEBUG::2020-03-18 09:39:48,503::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-469::DEBUG::2020-03-18 09:39:48,503::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-469::DEBUG::2020-03-18 09:39:48,503::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-469::DEBUG::2020-03-18 09:39:48,503::task::993::Storage.TaskManager.Task::(_decref) Task=`224a4641-f77a-4fca-9ea7-393a17b105f1`::ref 0 aborting False
Thread-469::INFO::2020-03-18 09:39:48,504::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42672 stopped
Reactor thread::INFO::2020-03-18 09:39:48,504::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42674
Reactor thread::DEBUG::2020-03-18 09:39:48,508::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,508::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42674
Reactor thread::DEBUG::2020-03-18 09:39:48,508::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42674)
BindingXMLRPC::INFO::2020-03-18 09:39:48,508::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42674
Thread-470::INFO::2020-03-18 09:39:48,508::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42674 started
Thread-470::DEBUG::2020-03-18 09:39:48,508::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-470::DEBUG::2020-03-18 09:39:48,509::task::595::Storage.TaskManager.Task::(_updateState) Task=`5a2cb9d9-1806-4370-8c9a-82a5bbc6f55e`::moving from state init -> state preparing
Thread-470::INFO::2020-03-18 09:39:48,509::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='f470821b-d9a9-4835-8ed9-2ab358e06b41', options=None)
Thread-470::DEBUG::2020-03-18 09:39:48,509::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`579eed7d-8b30-484a-b351-8a099e71663c`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-470::DEBUG::2020-03-18 09:39:48,509::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-470::DEBUG::2020-03-18 09:39:48,509::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-470::DEBUG::2020-03-18 09:39:48,509::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`579eed7d-8b30-484a-b351-8a099e71663c`::Granted request
Thread-470::DEBUG::2020-03-18 09:39:48,509::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`5a2cb9d9-1806-4370-8c9a-82a5bbc6f55e`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-470::DEBUG::2020-03-18 09:39:48,509::task::993::Storage.TaskManager.Task::(_decref) Task=`5a2cb9d9-1806-4370-8c9a-82a5bbc6f55e`::ref 1 aborting False
Thread-470::INFO::2020-03-18 09:39:48,512::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'40f29b86-0eaa-4e64-a670-69ed7bc1011d']}
Thread-470::DEBUG::2020-03-18 09:39:48,512::task::1191::Storage.TaskManager.Task::(prepare) Task=`5a2cb9d9-1806-4370-8c9a-82a5bbc6f55e`::finished: {'uuidlist': [u'40f29b86-0eaa-4e64-a670-69ed7bc1011d']}
Thread-470::DEBUG::2020-03-18 09:39:48,512::task::595::Storage.TaskManager.Task::(_updateState) Task=`5a2cb9d9-1806-4370-8c9a-82a5bbc6f55e`::moving from state preparing -> state finished
Thread-470::DEBUG::2020-03-18 09:39:48,512::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-470::DEBUG::2020-03-18 09:39:48,512::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-470::DEBUG::2020-03-18 09:39:48,512::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-470::DEBUG::2020-03-18 09:39:48,512::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-470::DEBUG::2020-03-18 09:39:48,512::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-470::DEBUG::2020-03-18 09:39:48,512::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-470::DEBUG::2020-03-18 09:39:48,512::task::993::Storage.TaskManager.Task::(_decref) Task=`5a2cb9d9-1806-4370-8c9a-82a5bbc6f55e`::ref 0 aborting False
Thread-470::INFO::2020-03-18 09:39:48,513::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42674 stopped
Reactor thread::INFO::2020-03-18 09:39:48,513::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42676
Reactor thread::DEBUG::2020-03-18 09:39:48,516::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,516::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42676
Reactor thread::DEBUG::2020-03-18 09:39:48,517::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42676)
BindingXMLRPC::INFO::2020-03-18 09:39:48,517::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42676
Thread-471::INFO::2020-03-18 09:39:48,517::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42676 started
Thread-471::DEBUG::2020-03-18 09:39:48,517::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-471::DEBUG::2020-03-18 09:39:48,517::task::595::Storage.TaskManager.Task::(_updateState) Task=`0b77417d-7665-446d-9c5d-fa9d774a805b`::moving from state init -> state preparing
Thread-471::INFO::2020-03-18 09:39:48,517::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='f470821b-d9a9-4835-8ed9-2ab358e06b41', leafUUID='40f29b86-0eaa-4e64-a670-69ed7bc1011d')
Thread-471::DEBUG::2020-03-18 09:39:48,517::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`4a1db10f-c03c-412f-9d63-a7edeb6015ac`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3213' at 'prepareImage'
Thread-471::DEBUG::2020-03-18 09:39:48,517::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-471::DEBUG::2020-03-18 09:39:48,518::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-471::DEBUG::2020-03-18 09:39:48,518::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`4a1db10f-c03c-412f-9d63-a7edeb6015ac`::Granted request
Thread-471::DEBUG::2020-03-18 09:39:48,518::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`0b77417d-7665-446d-9c5d-fa9d774a805b`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-471::DEBUG::2020-03-18 09:39:48,518::task::993::Storage.TaskManager.Task::(_decref) Task=`0b77417d-7665-446d-9c5d-fa9d774a805b`::ref 1 aborting False
Thread-471::DEBUG::2020-03-18 09:39:48,520::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 40f29b86-0eaa-4e64-a670-69ed7bc1011d
Thread-471::DEBUG::2020-03-18 09:39:48,521::fileSD::560::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d
Thread-471::DEBUG::2020-03-18 09:39:48,521::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 mode: None
Thread-471::WARNING::2020-03-18 09:39:48,522::fileUtils::152::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 already exists
Thread-471::DEBUG::2020-03-18 09:39:48,522::fileSD::517::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41 to /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/f470821b-d9a9-4835-8ed9-2ab358e06b41
Thread-471::DEBUG::2020-03-18 09:39:48,522::fileSD::522::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/f470821b-d9a9-4835-8ed9-2ab358e06b41
Thread-471::DEBUG::2020-03-18 09:39:48,522::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 40f29b86-0eaa-4e64-a670-69ed7bc1011d
Thread-471::INFO::2020-03-18 09:39:48,523::logUtils::51::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'volumeID': u'40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d.lease', 'imageID': 'f470821b-d9a9-4835-8ed9-2ab358e06b41'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'l
 easeOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'volumeID': u'40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d.lease', 'imageID': 'f470821b-d9a9-4835-8ed9-2ab358e06b41'}]}
Thread-471::DEBUG::2020-03-18 09:39:48,523::task::1191::Storage.TaskManager.Task::(prepare) Task=`0b77417d-7665-446d-9c5d-fa9d774a805b`::finished: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'volumeID': u'40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d.lease', 'imageID': 'f470821b-d9a9-4835-8ed9-2ab358e06b41'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', '
 volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'volumeID': u'40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d.lease', 'imageID': 'f470821b-d9a9-4835-8ed9-2ab358e06b41'}]}
Thread-471::DEBUG::2020-03-18 09:39:48,523::task::595::Storage.TaskManager.Task::(_updateState) Task=`0b77417d-7665-446d-9c5d-fa9d774a805b`::moving from state preparing -> state finished
Thread-471::DEBUG::2020-03-18 09:39:48,523::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-471::DEBUG::2020-03-18 09:39:48,523::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-471::DEBUG::2020-03-18 09:39:48,523::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-471::DEBUG::2020-03-18 09:39:48,523::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-471::DEBUG::2020-03-18 09:39:48,523::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-471::DEBUG::2020-03-18 09:39:48,523::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-471::DEBUG::2020-03-18 09:39:48,523::task::993::Storage.TaskManager.Task::(_decref) Task=`0b77417d-7665-446d-9c5d-fa9d774a805b`::ref 0 aborting False
Thread-471::INFO::2020-03-18 09:39:48,524::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42676 stopped
Reactor thread::INFO::2020-03-18 09:39:48,524::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42678
Reactor thread::DEBUG::2020-03-18 09:39:48,528::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,528::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42678
Reactor thread::DEBUG::2020-03-18 09:39:48,528::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42678)
BindingXMLRPC::INFO::2020-03-18 09:39:48,528::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42678
Thread-472::INFO::2020-03-18 09:39:48,528::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42678 started
Thread-472::DEBUG::2020-03-18 09:39:48,528::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-472::DEBUG::2020-03-18 09:39:48,529::task::595::Storage.TaskManager.Task::(_updateState) Task=`8d6ac831-7be0-411f-be32-1b1455d0c5d1`::moving from state init -> state preparing
Thread-472::INFO::2020-03-18 09:39:48,529::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='63491779-c7cf-434c-84c9-7878694a8946', options=None)
Thread-472::DEBUG::2020-03-18 09:39:48,529::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`10cffda5-c176-4262-871f-c4df5607df89`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-472::DEBUG::2020-03-18 09:39:48,529::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-472::DEBUG::2020-03-18 09:39:48,529::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-472::DEBUG::2020-03-18 09:39:48,529::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`10cffda5-c176-4262-871f-c4df5607df89`::Granted request
Thread-472::DEBUG::2020-03-18 09:39:48,529::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`8d6ac831-7be0-411f-be32-1b1455d0c5d1`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-472::DEBUG::2020-03-18 09:39:48,529::task::993::Storage.TaskManager.Task::(_decref) Task=`8d6ac831-7be0-411f-be32-1b1455d0c5d1`::ref 1 aborting False
Thread-472::INFO::2020-03-18 09:39:48,532::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'2f086a70-e97d-4161-a232-1268bb3145de']}
Thread-472::DEBUG::2020-03-18 09:39:48,533::task::1191::Storage.TaskManager.Task::(prepare) Task=`8d6ac831-7be0-411f-be32-1b1455d0c5d1`::finished: {'uuidlist': [u'2f086a70-e97d-4161-a232-1268bb3145de']}
Thread-472::DEBUG::2020-03-18 09:39:48,533::task::595::Storage.TaskManager.Task::(_updateState) Task=`8d6ac831-7be0-411f-be32-1b1455d0c5d1`::moving from state preparing -> state finished
Thread-472::DEBUG::2020-03-18 09:39:48,533::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-472::DEBUG::2020-03-18 09:39:48,533::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-472::DEBUG::2020-03-18 09:39:48,533::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-472::DEBUG::2020-03-18 09:39:48,533::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-472::DEBUG::2020-03-18 09:39:48,533::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-472::DEBUG::2020-03-18 09:39:48,533::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-472::DEBUG::2020-03-18 09:39:48,533::task::993::Storage.TaskManager.Task::(_decref) Task=`8d6ac831-7be0-411f-be32-1b1455d0c5d1`::ref 0 aborting False
Thread-472::INFO::2020-03-18 09:39:48,534::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42678 stopped
Reactor thread::INFO::2020-03-18 09:39:48,534::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42680
Reactor thread::DEBUG::2020-03-18 09:39:48,537::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,537::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42680
Reactor thread::DEBUG::2020-03-18 09:39:48,537::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42680)
BindingXMLRPC::INFO::2020-03-18 09:39:48,538::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42680
Thread-473::INFO::2020-03-18 09:39:48,538::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42680 started
Thread-473::DEBUG::2020-03-18 09:39:48,538::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-473::DEBUG::2020-03-18 09:39:48,538::task::595::Storage.TaskManager.Task::(_updateState) Task=`023b8d2f-c581-4da4-b03e-7c2b00fb0d51`::moving from state init -> state preparing
Thread-473::INFO::2020-03-18 09:39:48,538::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='63491779-c7cf-434c-84c9-7878694a8946', leafUUID='2f086a70-e97d-4161-a232-1268bb3145de')
Thread-473::DEBUG::2020-03-18 09:39:48,538::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`823a80ee-eaee-4c8c-93a3-711e7eaa0c22`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3213' at 'prepareImage'
Thread-473::DEBUG::2020-03-18 09:39:48,538::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-473::DEBUG::2020-03-18 09:39:48,538::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-473::DEBUG::2020-03-18 09:39:48,539::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`823a80ee-eaee-4c8c-93a3-711e7eaa0c22`::Granted request
Thread-473::DEBUG::2020-03-18 09:39:48,539::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`023b8d2f-c581-4da4-b03e-7c2b00fb0d51`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-473::DEBUG::2020-03-18 09:39:48,539::task::993::Storage.TaskManager.Task::(_decref) Task=`023b8d2f-c581-4da4-b03e-7c2b00fb0d51`::ref 1 aborting False
Thread-473::DEBUG::2020-03-18 09:39:48,541::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2f086a70-e97d-4161-a232-1268bb3145de
Thread-473::DEBUG::2020-03-18 09:39:48,542::fileSD::560::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de
Thread-473::DEBUG::2020-03-18 09:39:48,543::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 mode: None
Thread-473::WARNING::2020-03-18 09:39:48,543::fileUtils::152::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1 already exists
Thread-473::DEBUG::2020-03-18 09:39:48,543::fileSD::517::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946 to /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/63491779-c7cf-434c-84c9-7878694a8946
Thread-473::DEBUG::2020-03-18 09:39:48,543::fileSD::522::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/63491779-c7cf-434c-84c9-7878694a8946
Thread-473::DEBUG::2020-03-18 09:39:48,544::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2f086a70-e97d-4161-a232-1268bb3145de
Thread-473::INFO::2020-03-18 09:39:48,544::logUtils::51::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de', 'volumeID': u'2f086a70-e97d-4161-a232-1268bb3145de', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de.lease', 'imageID': '63491779-c7cf-434c-84c9-7878694a8946'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'l
 easeOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de', 'volumeID': u'2f086a70-e97d-4161-a232-1268bb3145de', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de.lease', 'imageID': '63491779-c7cf-434c-84c9-7878694a8946'}]}
Thread-473::DEBUG::2020-03-18 09:39:48,544::task::1191::Storage.TaskManager.Task::(prepare) Task=`023b8d2f-c581-4da4-b03e-7c2b00fb0d51`::finished: {'info': {'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de', 'volumeID': u'2f086a70-e97d-4161-a232-1268bb3145de', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de.lease', 'imageID': '63491779-c7cf-434c-84c9-7878694a8946'}, 'path': u'/var/run/vdsm/storage/331e6287-61df-48dd-9733-a8ad236750b1/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de', 'imgVolumesInfo': [{'domainID': '331e6287-61df-48dd-9733-a8ad236750b1', '
 volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de', 'volumeID': u'2f086a70-e97d-4161-a232-1268bb3145de', 'leasePath': u'/rhev/data-center/mnt/aidc-nap1-n1.corp.alleninstitute.org:_netapp__engine__36/331e6287-61df-48dd-9733-a8ad236750b1/images/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de.lease', 'imageID': '63491779-c7cf-434c-84c9-7878694a8946'}]}
Thread-473::DEBUG::2020-03-18 09:39:48,544::task::595::Storage.TaskManager.Task::(_updateState) Task=`023b8d2f-c581-4da4-b03e-7c2b00fb0d51`::moving from state preparing -> state finished
Thread-473::DEBUG::2020-03-18 09:39:48,544::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-473::DEBUG::2020-03-18 09:39:48,544::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-473::DEBUG::2020-03-18 09:39:48,544::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-473::DEBUG::2020-03-18 09:39:48,544::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-473::DEBUG::2020-03-18 09:39:48,544::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-473::DEBUG::2020-03-18 09:39:48,544::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-473::DEBUG::2020-03-18 09:39:48,545::task::993::Storage.TaskManager.Task::(_decref) Task=`023b8d2f-c581-4da4-b03e-7c2b00fb0d51`::ref 0 aborting False
Thread-473::INFO::2020-03-18 09:39:48,545::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42680 stopped
Reactor thread::INFO::2020-03-18 09:39:48,546::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42682
Reactor thread::DEBUG::2020-03-18 09:39:48,550::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,550::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42682
Reactor thread::DEBUG::2020-03-18 09:39:48,550::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42682)
BindingXMLRPC::INFO::2020-03-18 09:39:48,550::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42682
Thread-474::INFO::2020-03-18 09:39:48,550::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42682 started
Thread-474::DEBUG::2020-03-18 09:39:48,550::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-474::DEBUG::2020-03-18 09:39:48,550::task::595::Storage.TaskManager.Task::(_updateState) Task=`160804a8-d1cf-4b69-9a07-99c4b4c6f8ff`::moving from state init -> state preparing
Thread-474::INFO::2020-03-18 09:39:48,550::logUtils::48::dispatcher::(wrapper) Run and protect: getImagesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', options=None)
Thread-474::DEBUG::2020-03-18 09:39:48,551::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`fda7ff0a-f3c4-4733-91df-868b9240d625`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3313' at 'getImagesList'
Thread-474::DEBUG::2020-03-18 09:39:48,551::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-474::DEBUG::2020-03-18 09:39:48,551::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-474::DEBUG::2020-03-18 09:39:48,551::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`fda7ff0a-f3c4-4733-91df-868b9240d625`::Granted request
Thread-474::DEBUG::2020-03-18 09:39:48,551::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`160804a8-d1cf-4b69-9a07-99c4b4c6f8ff`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-474::DEBUG::2020-03-18 09:39:48,551::task::993::Storage.TaskManager.Task::(_decref) Task=`160804a8-d1cf-4b69-9a07-99c4b4c6f8ff`::ref 1 aborting False
Thread-474::INFO::2020-03-18 09:39:48,551::logUtils::51::dispatcher::(wrapper) Run and protect: getImagesList, Return response: {'imageslist': []}
Thread-474::DEBUG::2020-03-18 09:39:48,551::task::1191::Storage.TaskManager.Task::(prepare) Task=`160804a8-d1cf-4b69-9a07-99c4b4c6f8ff`::finished: {'imageslist': []}
Thread-474::DEBUG::2020-03-18 09:39:48,551::task::595::Storage.TaskManager.Task::(_updateState) Task=`160804a8-d1cf-4b69-9a07-99c4b4c6f8ff`::moving from state preparing -> state finished
Thread-474::DEBUG::2020-03-18 09:39:48,551::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-474::DEBUG::2020-03-18 09:39:48,552::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-474::DEBUG::2020-03-18 09:39:48,552::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-474::DEBUG::2020-03-18 09:39:48,552::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-474::DEBUG::2020-03-18 09:39:48,552::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-474::DEBUG::2020-03-18 09:39:48,552::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-474::DEBUG::2020-03-18 09:39:48,552::task::993::Storage.TaskManager.Task::(_decref) Task=`160804a8-d1cf-4b69-9a07-99c4b4c6f8ff`::ref 0 aborting False
Thread-474::INFO::2020-03-18 09:39:48,552::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42682 stopped
Reactor thread::INFO::2020-03-18 09:39:48,553::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42684
Reactor thread::DEBUG::2020-03-18 09:39:48,556::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,556::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42684
Reactor thread::DEBUG::2020-03-18 09:39:48,557::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42684)
BindingXMLRPC::INFO::2020-03-18 09:39:48,557::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42684
Thread-475::INFO::2020-03-18 09:39:48,557::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42684 started
Thread-475::DEBUG::2020-03-18 09:39:48,557::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-475::DEBUG::2020-03-18 09:39:48,557::task::595::Storage.TaskManager.Task::(_updateState) Task=`ac68ce82-549c-4165-bc93-52a0ab4869b4`::moving from state init -> state preparing
Thread-475::INFO::2020-03-18 09:39:48,557::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='b9fd2434-60b0-4a5d-abb2-adc358d0dfd1', options=None)
Thread-475::DEBUG::2020-03-18 09:39:48,557::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`93c014c9-1c13-40db-906f-794242525271`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-475::DEBUG::2020-03-18 09:39:48,557::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-475::DEBUG::2020-03-18 09:39:48,558::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-475::DEBUG::2020-03-18 09:39:48,558::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`93c014c9-1c13-40db-906f-794242525271`::Granted request
Thread-475::DEBUG::2020-03-18 09:39:48,558::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`ac68ce82-549c-4165-bc93-52a0ab4869b4`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-475::DEBUG::2020-03-18 09:39:48,558::task::993::Storage.TaskManager.Task::(_decref) Task=`ac68ce82-549c-4165-bc93-52a0ab4869b4`::ref 1 aborting False
Thread-475::INFO::2020-03-18 09:39:48,560::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'53d31c6e-bfc3-4dee-99be-f0fa77006cad']}
Thread-475::DEBUG::2020-03-18 09:39:48,560::task::1191::Storage.TaskManager.Task::(prepare) Task=`ac68ce82-549c-4165-bc93-52a0ab4869b4`::finished: {'uuidlist': [u'53d31c6e-bfc3-4dee-99be-f0fa77006cad']}
Thread-475::DEBUG::2020-03-18 09:39:48,560::task::595::Storage.TaskManager.Task::(_updateState) Task=`ac68ce82-549c-4165-bc93-52a0ab4869b4`::moving from state preparing -> state finished
Thread-475::DEBUG::2020-03-18 09:39:48,560::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-475::DEBUG::2020-03-18 09:39:48,561::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-475::DEBUG::2020-03-18 09:39:48,561::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-475::DEBUG::2020-03-18 09:39:48,561::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-475::DEBUG::2020-03-18 09:39:48,561::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-475::DEBUG::2020-03-18 09:39:48,561::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-475::DEBUG::2020-03-18 09:39:48,561::task::993::Storage.TaskManager.Task::(_decref) Task=`ac68ce82-549c-4165-bc93-52a0ab4869b4`::ref 0 aborting False
Thread-475::INFO::2020-03-18 09:39:48,561::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42684 stopped
Reactor thread::INFO::2020-03-18 09:39:48,562::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42686
Reactor thread::DEBUG::2020-03-18 09:39:48,565::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,565::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42686
Reactor thread::DEBUG::2020-03-18 09:39:48,565::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42686)
BindingXMLRPC::INFO::2020-03-18 09:39:48,565::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42686
Thread-476::INFO::2020-03-18 09:39:48,566::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42686 started
Thread-476::DEBUG::2020-03-18 09:39:48,566::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-476::DEBUG::2020-03-18 09:39:48,566::task::595::Storage.TaskManager.Task::(_updateState) Task=`9ac96c69-475c-4e0d-bf79-71e33f387255`::moving from state init -> state preparing
Thread-476::INFO::2020-03-18 09:39:48,566::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='b9fd2434-60b0-4a5d-abb2-adc358d0dfd1', volUUID='53d31c6e-bfc3-4dee-99be-f0fa77006cad', options=None)
Thread-476::DEBUG::2020-03-18 09:39:48,566::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`07603064-78b1-474c-99ee-43fe7cb23267`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo'
Thread-476::DEBUG::2020-03-18 09:39:48,566::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-476::DEBUG::2020-03-18 09:39:48,566::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-476::DEBUG::2020-03-18 09:39:48,566::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`07603064-78b1-474c-99ee-43fe7cb23267`::Granted request
Thread-476::DEBUG::2020-03-18 09:39:48,567::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`9ac96c69-475c-4e0d-bf79-71e33f387255`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-476::DEBUG::2020-03-18 09:39:48,567::task::993::Storage.TaskManager.Task::(_decref) Task=`9ac96c69-475c-4e0d-bf79-71e33f387255`::ref 1 aborting False
Thread-476::DEBUG::2020-03-18 09:39:48,567::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 53d31c6e-bfc3-4dee-99be-f0fa77006cad
Thread-476::INFO::2020-03-18 09:39:48,568::volume::915::Storage.Volume::(getInfo) Info request: sdUUID=331e6287-61df-48dd-9733-a8ad236750b1 imgUUID=b9fd2434-60b0-4a5d-abb2-adc358d0dfd1 volUUID = 53d31c6e-bfc3-4dee-99be-f0fa77006cad
Thread-476::INFO::2020-03-18 09:39:48,570::volume::943::Storage.Volume::(getInfo) 331e6287-61df-48dd-9733-a8ad236750b1/b9fd2434-60b0-4a5d-abb2-adc358d0dfd1/53d31c6e-bfc3-4dee-99be-f0fa77006cad info is {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'hosted-engine.lockspace', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'b9fd2434-60b0-4a5d-abb2-adc358d0dfd1', 'ctime': '1581543998', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1048576', 'children': [], 'pool': '', 'capacity': '1048576', 'uuid': '53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'truesize': '1056768', 'type': 'PREALLOCATED'}
Thread-476::INFO::2020-03-18 09:39:48,570::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'hosted-engine.lockspace', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'b9fd2434-60b0-4a5d-abb2-adc358d0dfd1', 'ctime': '1581543998', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1048576', 'children': [], 'pool': '', 'capacity': '1048576', 'uuid': '53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'truesize': '1056768', 'type': 'PREALLOCATED'}}
Thread-476::DEBUG::2020-03-18 09:39:48,570::task::1191::Storage.TaskManager.Task::(prepare) Task=`9ac96c69-475c-4e0d-bf79-71e33f387255`::finished: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'hosted-engine.lockspace', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'b9fd2434-60b0-4a5d-abb2-adc358d0dfd1', 'ctime': '1581543998', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1048576', 'children': [], 'pool': '', 'capacity': '1048576', 'uuid': '53d31c6e-bfc3-4dee-99be-f0fa77006cad', 'truesize': '1056768', 'type': 'PREALLOCATED'}}
Thread-476::DEBUG::2020-03-18 09:39:48,570::task::595::Storage.TaskManager.Task::(_updateState) Task=`9ac96c69-475c-4e0d-bf79-71e33f387255`::moving from state preparing -> state finished
Thread-476::DEBUG::2020-03-18 09:39:48,570::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-476::DEBUG::2020-03-18 09:39:48,570::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-476::DEBUG::2020-03-18 09:39:48,570::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-476::DEBUG::2020-03-18 09:39:48,570::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-476::DEBUG::2020-03-18 09:39:48,570::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-476::DEBUG::2020-03-18 09:39:48,570::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-476::DEBUG::2020-03-18 09:39:48,570::task::993::Storage.TaskManager.Task::(_decref) Task=`9ac96c69-475c-4e0d-bf79-71e33f387255`::ref 0 aborting False
Thread-476::INFO::2020-03-18 09:39:48,571::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42686 stopped
Reactor thread::INFO::2020-03-18 09:39:48,572::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42688
Reactor thread::DEBUG::2020-03-18 09:39:48,575::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,575::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42688
Reactor thread::DEBUG::2020-03-18 09:39:48,575::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42688)
BindingXMLRPC::INFO::2020-03-18 09:39:48,575::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42688
Thread-477::INFO::2020-03-18 09:39:48,575::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42688 started
Thread-477::DEBUG::2020-03-18 09:39:48,576::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-477::DEBUG::2020-03-18 09:39:48,576::task::595::Storage.TaskManager.Task::(_updateState) Task=`65f3cb5c-2c78-4256-9ade-d50be15739e0`::moving from state init -> state preparing
Thread-477::INFO::2020-03-18 09:39:48,576::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='a667b14a-1f92-40f1-8379-210e0c42fc26', options=None)
Thread-477::DEBUG::2020-03-18 09:39:48,576::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`c585444c-4f57-4e14-9e1c-d0d2f82e8475`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-477::DEBUG::2020-03-18 09:39:48,576::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-477::DEBUG::2020-03-18 09:39:48,576::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-477::DEBUG::2020-03-18 09:39:48,576::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`c585444c-4f57-4e14-9e1c-d0d2f82e8475`::Granted request
Thread-477::DEBUG::2020-03-18 09:39:48,576::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`65f3cb5c-2c78-4256-9ade-d50be15739e0`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-477::DEBUG::2020-03-18 09:39:48,576::task::993::Storage.TaskManager.Task::(_decref) Task=`65f3cb5c-2c78-4256-9ade-d50be15739e0`::ref 1 aborting False
Thread-477::INFO::2020-03-18 09:39:48,579::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'43cc29d0-6919-4493-95fe-6d58f97acdfc']}
Thread-477::DEBUG::2020-03-18 09:39:48,579::task::1191::Storage.TaskManager.Task::(prepare) Task=`65f3cb5c-2c78-4256-9ade-d50be15739e0`::finished: {'uuidlist': [u'43cc29d0-6919-4493-95fe-6d58f97acdfc']}
Thread-477::DEBUG::2020-03-18 09:39:48,579::task::595::Storage.TaskManager.Task::(_updateState) Task=`65f3cb5c-2c78-4256-9ade-d50be15739e0`::moving from state preparing -> state finished
Thread-477::DEBUG::2020-03-18 09:39:48,579::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-477::DEBUG::2020-03-18 09:39:48,579::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-477::DEBUG::2020-03-18 09:39:48,579::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-477::DEBUG::2020-03-18 09:39:48,579::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-477::DEBUG::2020-03-18 09:39:48,579::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-477::DEBUG::2020-03-18 09:39:48,579::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-477::DEBUG::2020-03-18 09:39:48,579::task::993::Storage.TaskManager.Task::(_decref) Task=`65f3cb5c-2c78-4256-9ade-d50be15739e0`::ref 0 aborting False
Thread-477::INFO::2020-03-18 09:39:48,580::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42688 stopped
Reactor thread::INFO::2020-03-18 09:39:48,580::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42690
Reactor thread::DEBUG::2020-03-18 09:39:48,583::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,583::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42690
Reactor thread::DEBUG::2020-03-18 09:39:48,584::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42690)
BindingXMLRPC::INFO::2020-03-18 09:39:48,584::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42690
Thread-478::INFO::2020-03-18 09:39:48,584::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42690 started
Thread-478::DEBUG::2020-03-18 09:39:48,584::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-478::DEBUG::2020-03-18 09:39:48,584::task::595::Storage.TaskManager.Task::(_updateState) Task=`00ffc02c-e764-416b-85ea-e8cc8944aefb`::moving from state init -> state preparing
Thread-478::INFO::2020-03-18 09:39:48,584::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='a667b14a-1f92-40f1-8379-210e0c42fc26', volUUID='43cc29d0-6919-4493-95fe-6d58f97acdfc', options=None)
Thread-478::DEBUG::2020-03-18 09:39:48,584::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`86ee411e-0888-41ce-a36d-e0544d0f0485`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo'
Thread-478::DEBUG::2020-03-18 09:39:48,584::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-478::DEBUG::2020-03-18 09:39:48,585::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-478::DEBUG::2020-03-18 09:39:48,585::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`86ee411e-0888-41ce-a36d-e0544d0f0485`::Granted request
Thread-478::DEBUG::2020-03-18 09:39:48,585::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`00ffc02c-e764-416b-85ea-e8cc8944aefb`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-478::DEBUG::2020-03-18 09:39:48,585::task::993::Storage.TaskManager.Task::(_decref) Task=`00ffc02c-e764-416b-85ea-e8cc8944aefb`::ref 1 aborting False
Thread-478::DEBUG::2020-03-18 09:39:48,585::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 43cc29d0-6919-4493-95fe-6d58f97acdfc
Thread-478::INFO::2020-03-18 09:39:48,586::volume::915::Storage.Volume::(getInfo) Info request: sdUUID=331e6287-61df-48dd-9733-a8ad236750b1 imgUUID=a667b14a-1f92-40f1-8379-210e0c42fc26 volUUID = 43cc29d0-6919-4493-95fe-6d58f97acdfc
Thread-478::INFO::2020-03-18 09:39:48,588::volume::943::Storage.Volume::(getInfo) 331e6287-61df-48dd-9733-a8ad236750b1/a667b14a-1f92-40f1-8379-210e0c42fc26/43cc29d0-6919-4493-95fe-6d58f97acdfc info is {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'HostedEngineConfigurationImage', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'a667b14a-1f92-40f1-8379-210e0c42fc26', 'ctime': '1581543997', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '20480', 'children': [], 'pool': '', 'capacity': '1073741824', 'uuid': '43cc29d0-6919-4493-95fe-6d58f97acdfc', 'truesize': '20480', 'type': 'PREALLOCATED'}
Thread-478::INFO::2020-03-18 09:39:48,588::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'HostedEngineConfigurationImage', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'a667b14a-1f92-40f1-8379-210e0c42fc26', 'ctime': '1581543997', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '20480', 'children': [], 'pool': '', 'capacity': '1073741824', 'uuid': '43cc29d0-6919-4493-95fe-6d58f97acdfc', 'truesize': '20480', 'type': 'PREALLOCATED'}}
Thread-478::DEBUG::2020-03-18 09:39:48,588::task::1191::Storage.TaskManager.Task::(prepare) Task=`00ffc02c-e764-416b-85ea-e8cc8944aefb`::finished: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'HostedEngineConfigurationImage', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'a667b14a-1f92-40f1-8379-210e0c42fc26', 'ctime': '1581543997', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '20480', 'children': [], 'pool': '', 'capacity': '1073741824', 'uuid': '43cc29d0-6919-4493-95fe-6d58f97acdfc', 'truesize': '20480', 'type': 'PREALLOCATED'}}
Thread-478::DEBUG::2020-03-18 09:39:48,588::task::595::Storage.TaskManager.Task::(_updateState) Task=`00ffc02c-e764-416b-85ea-e8cc8944aefb`::moving from state preparing -> state finished
Thread-478::DEBUG::2020-03-18 09:39:48,588::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-478::DEBUG::2020-03-18 09:39:48,588::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-478::DEBUG::2020-03-18 09:39:48,588::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-478::DEBUG::2020-03-18 09:39:48,588::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-478::DEBUG::2020-03-18 09:39:48,588::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-478::DEBUG::2020-03-18 09:39:48,588::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-478::DEBUG::2020-03-18 09:39:48,589::task::993::Storage.TaskManager.Task::(_decref) Task=`00ffc02c-e764-416b-85ea-e8cc8944aefb`::ref 0 aborting False
Thread-478::INFO::2020-03-18 09:39:48,589::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42690 stopped
Reactor thread::INFO::2020-03-18 09:39:48,590::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42692
Reactor thread::DEBUG::2020-03-18 09:39:48,593::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,593::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42692
Reactor thread::DEBUG::2020-03-18 09:39:48,593::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42692)
BindingXMLRPC::INFO::2020-03-18 09:39:48,593::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42692
Thread-479::INFO::2020-03-18 09:39:48,593::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42692 started
Thread-479::DEBUG::2020-03-18 09:39:48,594::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-479::DEBUG::2020-03-18 09:39:48,594::task::595::Storage.TaskManager.Task::(_updateState) Task=`34f20abc-8aef-4083-a8b9-86c949d7c21e`::moving from state init -> state preparing
Thread-479::INFO::2020-03-18 09:39:48,594::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='00ad81a7-5637-40ff-8635-c039347f69ee', options=None)
Thread-479::DEBUG::2020-03-18 09:39:48,594::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`9f38dff1-8a79-4c6d-8545-24be38b5f3fb`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-479::DEBUG::2020-03-18 09:39:48,594::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-479::DEBUG::2020-03-18 09:39:48,594::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-479::DEBUG::2020-03-18 09:39:48,594::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`9f38dff1-8a79-4c6d-8545-24be38b5f3fb`::Granted request
Thread-479::DEBUG::2020-03-18 09:39:48,594::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`34f20abc-8aef-4083-a8b9-86c949d7c21e`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-479::DEBUG::2020-03-18 09:39:48,594::task::993::Storage.TaskManager.Task::(_decref) Task=`34f20abc-8aef-4083-a8b9-86c949d7c21e`::ref 1 aborting False
Thread-479::INFO::2020-03-18 09:39:48,596::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'ec87b10a-e601-44bc-bd87-fbe6de274cd4']}
Thread-479::DEBUG::2020-03-18 09:39:48,596::task::1191::Storage.TaskManager.Task::(prepare) Task=`34f20abc-8aef-4083-a8b9-86c949d7c21e`::finished: {'uuidlist': [u'ec87b10a-e601-44bc-bd87-fbe6de274cd4']}
Thread-479::DEBUG::2020-03-18 09:39:48,596::task::595::Storage.TaskManager.Task::(_updateState) Task=`34f20abc-8aef-4083-a8b9-86c949d7c21e`::moving from state preparing -> state finished
Thread-479::DEBUG::2020-03-18 09:39:48,597::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-479::DEBUG::2020-03-18 09:39:48,597::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-479::DEBUG::2020-03-18 09:39:48,597::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-479::DEBUG::2020-03-18 09:39:48,597::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-479::DEBUG::2020-03-18 09:39:48,597::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-479::DEBUG::2020-03-18 09:39:48,597::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-479::DEBUG::2020-03-18 09:39:48,597::task::993::Storage.TaskManager.Task::(_decref) Task=`34f20abc-8aef-4083-a8b9-86c949d7c21e`::ref 0 aborting False
Thread-479::INFO::2020-03-18 09:39:48,597::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42692 stopped
Reactor thread::INFO::2020-03-18 09:39:48,598::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42694
Reactor thread::DEBUG::2020-03-18 09:39:48,601::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,601::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42694
Reactor thread::DEBUG::2020-03-18 09:39:48,601::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42694)
BindingXMLRPC::INFO::2020-03-18 09:39:48,601::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42694
Thread-480::INFO::2020-03-18 09:39:48,601::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42694 started
Thread-480::DEBUG::2020-03-18 09:39:48,602::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-480::DEBUG::2020-03-18 09:39:48,602::task::595::Storage.TaskManager.Task::(_updateState) Task=`4b80c7cf-9e00-46fa-bbbf-cd562fa8bd0e`::moving from state init -> state preparing
Thread-480::INFO::2020-03-18 09:39:48,602::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='00ad81a7-5637-40ff-8635-c039347f69ee', volUUID='ec87b10a-e601-44bc-bd87-fbe6de274cd4', options=None)
Thread-480::DEBUG::2020-03-18 09:39:48,602::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`e11c8a21-42f1-40bc-8d40-5ebc2f5dc5ce`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo'
Thread-480::DEBUG::2020-03-18 09:39:48,602::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-480::DEBUG::2020-03-18 09:39:48,602::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-480::DEBUG::2020-03-18 09:39:48,602::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`e11c8a21-42f1-40bc-8d40-5ebc2f5dc5ce`::Granted request
Thread-480::DEBUG::2020-03-18 09:39:48,603::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`4b80c7cf-9e00-46fa-bbbf-cd562fa8bd0e`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-480::DEBUG::2020-03-18 09:39:48,603::task::993::Storage.TaskManager.Task::(_decref) Task=`4b80c7cf-9e00-46fa-bbbf-cd562fa8bd0e`::ref 1 aborting False
Thread-480::DEBUG::2020-03-18 09:39:48,604::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for ec87b10a-e601-44bc-bd87-fbe6de274cd4
Thread-480::INFO::2020-03-18 09:39:48,604::volume::915::Storage.Volume::(getInfo) Info request: sdUUID=331e6287-61df-48dd-9733-a8ad236750b1 imgUUID=00ad81a7-5637-40ff-8635-c039347f69ee volUUID = ec87b10a-e601-44bc-bd87-fbe6de274cd4
Thread-480::INFO::2020-03-18 09:39:48,607::volume::943::Storage.Volume::(getInfo) 331e6287-61df-48dd-9733-a8ad236750b1/00ad81a7-5637-40ff-8635-c039347f69ee/ec87b10a-e601-44bc-bd87-fbe6de274cd4 info is {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': '{"Updated":true,"Size":10240,"Last Updated":"Tue Mar 03 10:33:30 PST 2020","Storage Domains":[{"uuid":"331e6287-61df-48dd-9733-a8ad236750b1"}],"Disk Description":"OVF_STORE"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '00ad81a7-5637-40ff-8635-c039347f69ee', 'ctime': '1583260407', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10240', 'children': [], 'pool': '', 'capacity': '134217728', 'uuid': 'ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'truesize': '12288', 'type': 'PREALLOCATED'}
Thread-480::INFO::2020-03-18 09:39:48,607::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': '{"Updated":true,"Size":10240,"Last Updated":"Tue Mar 03 10:33:30 PST 2020","Storage Domains":[{"uuid":"331e6287-61df-48dd-9733-a8ad236750b1"}],"Disk Description":"OVF_STORE"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '00ad81a7-5637-40ff-8635-c039347f69ee', 'ctime': '1583260407', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10240', 'children': [], 'pool': '', 'capacity': '134217728', 'uuid': 'ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'truesize': '12288', 'type': 'PREALLOCATED'}}
Thread-480::DEBUG::2020-03-18 09:39:48,607::task::1191::Storage.TaskManager.Task::(prepare) Task=`4b80c7cf-9e00-46fa-bbbf-cd562fa8bd0e`::finished: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': '{"Updated":true,"Size":10240,"Last Updated":"Tue Mar 03 10:33:30 PST 2020","Storage Domains":[{"uuid":"331e6287-61df-48dd-9733-a8ad236750b1"}],"Disk Description":"OVF_STORE"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '00ad81a7-5637-40ff-8635-c039347f69ee', 'ctime': '1583260407', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10240', 'children': [], 'pool': '', 'capacity': '134217728', 'uuid': 'ec87b10a-e601-44bc-bd87-fbe6de274cd4', 'truesize': '12288', 'type': 'PREALLOCATED'}}
Thread-480::DEBUG::2020-03-18 09:39:48,607::task::595::Storage.TaskManager.Task::(_updateState) Task=`4b80c7cf-9e00-46fa-bbbf-cd562fa8bd0e`::moving from state preparing -> state finished
Thread-480::DEBUG::2020-03-18 09:39:48,607::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-480::DEBUG::2020-03-18 09:39:48,607::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-480::DEBUG::2020-03-18 09:39:48,607::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-480::DEBUG::2020-03-18 09:39:48,607::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-480::DEBUG::2020-03-18 09:39:48,607::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-480::DEBUG::2020-03-18 09:39:48,607::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-480::DEBUG::2020-03-18 09:39:48,607::task::993::Storage.TaskManager.Task::(_decref) Task=`4b80c7cf-9e00-46fa-bbbf-cd562fa8bd0e`::ref 0 aborting False
Thread-480::INFO::2020-03-18 09:39:48,608::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42694 stopped
Reactor thread::INFO::2020-03-18 09:39:48,609::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42696
Reactor thread::DEBUG::2020-03-18 09:39:48,612::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,612::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42696
Reactor thread::DEBUG::2020-03-18 09:39:48,612::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42696)
BindingXMLRPC::INFO::2020-03-18 09:39:48,612::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42696
Thread-481::INFO::2020-03-18 09:39:48,613::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42696 started
Thread-481::DEBUG::2020-03-18 09:39:48,613::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-481::DEBUG::2020-03-18 09:39:48,613::task::595::Storage.TaskManager.Task::(_updateState) Task=`2e2c57c4-a55c-4bab-bf5e-2f534e3677bc`::moving from state init -> state preparing
Thread-481::INFO::2020-03-18 09:39:48,613::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='50cc8c63-9929-4cbc-aec8-f1d196874b72', options=None)
Thread-481::DEBUG::2020-03-18 09:39:48,613::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`b17a1185-64d3-4916-8bc9-a0a6054efd6a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-481::DEBUG::2020-03-18 09:39:48,613::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-481::DEBUG::2020-03-18 09:39:48,613::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-481::DEBUG::2020-03-18 09:39:48,613::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`b17a1185-64d3-4916-8bc9-a0a6054efd6a`::Granted request
Thread-481::DEBUG::2020-03-18 09:39:48,614::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`2e2c57c4-a55c-4bab-bf5e-2f534e3677bc`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-481::DEBUG::2020-03-18 09:39:48,614::task::993::Storage.TaskManager.Task::(_decref) Task=`2e2c57c4-a55c-4bab-bf5e-2f534e3677bc`::ref 1 aborting False
Thread-481::INFO::2020-03-18 09:39:48,615::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0']}
Thread-481::DEBUG::2020-03-18 09:39:48,615::task::1191::Storage.TaskManager.Task::(prepare) Task=`2e2c57c4-a55c-4bab-bf5e-2f534e3677bc`::finished: {'uuidlist': [u'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0']}
Thread-481::DEBUG::2020-03-18 09:39:48,615::task::595::Storage.TaskManager.Task::(_updateState) Task=`2e2c57c4-a55c-4bab-bf5e-2f534e3677bc`::moving from state preparing -> state finished
Thread-481::DEBUG::2020-03-18 09:39:48,616::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-481::DEBUG::2020-03-18 09:39:48,616::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-481::DEBUG::2020-03-18 09:39:48,616::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-481::DEBUG::2020-03-18 09:39:48,616::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-481::DEBUG::2020-03-18 09:39:48,616::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-481::DEBUG::2020-03-18 09:39:48,616::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-481::DEBUG::2020-03-18 09:39:48,616::task::993::Storage.TaskManager.Task::(_decref) Task=`2e2c57c4-a55c-4bab-bf5e-2f534e3677bc`::ref 0 aborting False
Thread-481::INFO::2020-03-18 09:39:48,616::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42696 stopped
Reactor thread::INFO::2020-03-18 09:39:48,617::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42698
Reactor thread::DEBUG::2020-03-18 09:39:48,620::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,620::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42698
Reactor thread::DEBUG::2020-03-18 09:39:48,620::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42698)
BindingXMLRPC::INFO::2020-03-18 09:39:48,620::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42698
Thread-482::INFO::2020-03-18 09:39:48,620::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42698 started
Thread-482::DEBUG::2020-03-18 09:39:48,621::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-482::DEBUG::2020-03-18 09:39:48,621::task::595::Storage.TaskManager.Task::(_updateState) Task=`a684e482-3427-417b-8b21-54d1d5565f5e`::moving from state init -> state preparing
Thread-482::INFO::2020-03-18 09:39:48,621::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='50cc8c63-9929-4cbc-aec8-f1d196874b72', volUUID='e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', options=None)
Thread-482::DEBUG::2020-03-18 09:39:48,621::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`2f072630-b931-4da7-9829-4722fa60b0b4`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo'
Thread-482::DEBUG::2020-03-18 09:39:48,621::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-482::DEBUG::2020-03-18 09:39:48,621::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-482::DEBUG::2020-03-18 09:39:48,621::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`2f072630-b931-4da7-9829-4722fa60b0b4`::Granted request
Thread-482::DEBUG::2020-03-18 09:39:48,621::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`a684e482-3427-417b-8b21-54d1d5565f5e`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-482::DEBUG::2020-03-18 09:39:48,621::task::993::Storage.TaskManager.Task::(_decref) Task=`a684e482-3427-417b-8b21-54d1d5565f5e`::ref 1 aborting False
Thread-482::DEBUG::2020-03-18 09:39:48,622::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for e8a4e709-0c98-4f1d-a42f-c5f0d499dca0
Thread-482::INFO::2020-03-18 09:39:48,622::volume::915::Storage.Volume::(getInfo) Info request: sdUUID=331e6287-61df-48dd-9733-a8ad236750b1 imgUUID=50cc8c63-9929-4cbc-aec8-f1d196874b72 volUUID = e8a4e709-0c98-4f1d-a42f-c5f0d499dca0
Thread-482::INFO::2020-03-18 09:39:48,625::volume::943::Storage.Volume::(getInfo) 331e6287-61df-48dd-9733-a8ad236750b1/50cc8c63-9929-4cbc-aec8-f1d196874b72/e8a4e709-0c98-4f1d-a42f-c5f0d499dca0 info is {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'hosted-engine.metadata', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '50cc8c63-9929-4cbc-aec8-f1d196874b72', 'ctime': '1581543999', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1028096', 'children': [], 'pool': '', 'capacity': '1028096', 'uuid': 'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'truesize': '1032192', 'type': 'PREALLOCATED'}
Thread-482::INFO::2020-03-18 09:39:48,625::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'hosted-engine.metadata', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '50cc8c63-9929-4cbc-aec8-f1d196874b72', 'ctime': '1581543999', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1028096', 'children': [], 'pool': '', 'capacity': '1028096', 'uuid': 'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'truesize': '1032192', 'type': 'PREALLOCATED'}}
Thread-482::DEBUG::2020-03-18 09:39:48,625::task::1191::Storage.TaskManager.Task::(prepare) Task=`a684e482-3427-417b-8b21-54d1d5565f5e`::finished: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'hosted-engine.metadata', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '50cc8c63-9929-4cbc-aec8-f1d196874b72', 'ctime': '1581543999', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1028096', 'children': [], 'pool': '', 'capacity': '1028096', 'uuid': 'e8a4e709-0c98-4f1d-a42f-c5f0d499dca0', 'truesize': '1032192', 'type': 'PREALLOCATED'}}
Thread-482::DEBUG::2020-03-18 09:39:48,625::task::595::Storage.TaskManager.Task::(_updateState) Task=`a684e482-3427-417b-8b21-54d1d5565f5e`::moving from state preparing -> state finished
Thread-482::DEBUG::2020-03-18 09:39:48,625::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-482::DEBUG::2020-03-18 09:39:48,625::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-482::DEBUG::2020-03-18 09:39:48,625::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-482::DEBUG::2020-03-18 09:39:48,625::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-482::DEBUG::2020-03-18 09:39:48,625::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-482::DEBUG::2020-03-18 09:39:48,625::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-482::DEBUG::2020-03-18 09:39:48,625::task::993::Storage.TaskManager.Task::(_decref) Task=`a684e482-3427-417b-8b21-54d1d5565f5e`::ref 0 aborting False
Thread-482::INFO::2020-03-18 09:39:48,626::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42698 stopped
Reactor thread::INFO::2020-03-18 09:39:48,626::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42700
Reactor thread::DEBUG::2020-03-18 09:39:48,630::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,630::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42700
Reactor thread::DEBUG::2020-03-18 09:39:48,630::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42700)
BindingXMLRPC::INFO::2020-03-18 09:39:48,630::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42700
Thread-483::INFO::2020-03-18 09:39:48,630::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42700 started
Thread-483::DEBUG::2020-03-18 09:39:48,631::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-483::DEBUG::2020-03-18 09:39:48,631::task::595::Storage.TaskManager.Task::(_updateState) Task=`badbadac-bf40-4a17-9309-90bcafab3508`::moving from state init -> state preparing
Thread-483::INFO::2020-03-18 09:39:48,631::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='f470821b-d9a9-4835-8ed9-2ab358e06b41', options=None)
Thread-483::DEBUG::2020-03-18 09:39:48,631::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`7fdf501c-e758-4e3c-8a63-b801f2f28777`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-483::DEBUG::2020-03-18 09:39:48,631::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-483::DEBUG::2020-03-18 09:39:48,631::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-483::DEBUG::2020-03-18 09:39:48,631::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`7fdf501c-e758-4e3c-8a63-b801f2f28777`::Granted request
Thread-483::DEBUG::2020-03-18 09:39:48,631::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`badbadac-bf40-4a17-9309-90bcafab3508`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-483::DEBUG::2020-03-18 09:39:48,631::task::993::Storage.TaskManager.Task::(_decref) Task=`badbadac-bf40-4a17-9309-90bcafab3508`::ref 1 aborting False
Thread-483::INFO::2020-03-18 09:39:48,633::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'40f29b86-0eaa-4e64-a670-69ed7bc1011d']}
Thread-483::DEBUG::2020-03-18 09:39:48,633::task::1191::Storage.TaskManager.Task::(prepare) Task=`badbadac-bf40-4a17-9309-90bcafab3508`::finished: {'uuidlist': [u'40f29b86-0eaa-4e64-a670-69ed7bc1011d']}
Thread-483::DEBUG::2020-03-18 09:39:48,633::task::595::Storage.TaskManager.Task::(_updateState) Task=`badbadac-bf40-4a17-9309-90bcafab3508`::moving from state preparing -> state finished
Thread-483::DEBUG::2020-03-18 09:39:48,633::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-483::DEBUG::2020-03-18 09:39:48,633::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-483::DEBUG::2020-03-18 09:39:48,633::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-483::DEBUG::2020-03-18 09:39:48,633::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-483::DEBUG::2020-03-18 09:39:48,633::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-483::DEBUG::2020-03-18 09:39:48,634::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-483::DEBUG::2020-03-18 09:39:48,634::task::993::Storage.TaskManager.Task::(_decref) Task=`badbadac-bf40-4a17-9309-90bcafab3508`::ref 0 aborting False
Thread-483::INFO::2020-03-18 09:39:48,634::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42700 stopped
Reactor thread::INFO::2020-03-18 09:39:48,634::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42702
Reactor thread::DEBUG::2020-03-18 09:39:48,638::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,638::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42702
Reactor thread::DEBUG::2020-03-18 09:39:48,638::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42702)
BindingXMLRPC::INFO::2020-03-18 09:39:48,638::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42702
Thread-484::INFO::2020-03-18 09:39:48,638::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42702 started
Thread-484::DEBUG::2020-03-18 09:39:48,638::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-484::DEBUG::2020-03-18 09:39:48,639::task::595::Storage.TaskManager.Task::(_updateState) Task=`3212d32a-f088-415d-853c-d4a6c203b2fb`::moving from state init -> state preparing
Thread-484::INFO::2020-03-18 09:39:48,639::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='f470821b-d9a9-4835-8ed9-2ab358e06b41', volUUID='40f29b86-0eaa-4e64-a670-69ed7bc1011d', options=None)
Thread-484::DEBUG::2020-03-18 09:39:48,639::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`0b02bb3e-2a26-4d99-ad15-a329eeae426d`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo'
Thread-484::DEBUG::2020-03-18 09:39:48,639::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-484::DEBUG::2020-03-18 09:39:48,639::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-484::DEBUG::2020-03-18 09:39:48,639::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`0b02bb3e-2a26-4d99-ad15-a329eeae426d`::Granted request
Thread-484::DEBUG::2020-03-18 09:39:48,639::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`3212d32a-f088-415d-853c-d4a6c203b2fb`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-484::DEBUG::2020-03-18 09:39:48,639::task::993::Storage.TaskManager.Task::(_decref) Task=`3212d32a-f088-415d-853c-d4a6c203b2fb`::ref 1 aborting False
Thread-484::DEBUG::2020-03-18 09:39:48,640::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 40f29b86-0eaa-4e64-a670-69ed7bc1011d
Thread-484::INFO::2020-03-18 09:39:48,640::volume::915::Storage.Volume::(getInfo) Info request: sdUUID=331e6287-61df-48dd-9733-a8ad236750b1 imgUUID=f470821b-d9a9-4835-8ed9-2ab358e06b41 volUUID = 40f29b86-0eaa-4e64-a670-69ed7bc1011d
Thread-484::INFO::2020-03-18 09:39:48,642::volume::943::Storage.Volume::(getInfo) 331e6287-61df-48dd-9733-a8ad236750b1/f470821b-d9a9-4835-8ed9-2ab358e06b41/40f29b86-0eaa-4e64-a670-69ed7bc1011d info is {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'Hosted Engine Image', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'f470821b-d9a9-4835-8ed9-2ab358e06b41', 'ctime': '1581544001', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10737418240', 'children': [], 'pool': '', 'capacity': '10737418240', 'uuid': '40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'truesize': '4488503296', 'type': 'SPARSE'}
Thread-484::INFO::2020-03-18 09:39:48,642::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'Hosted Engine Image', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'f470821b-d9a9-4835-8ed9-2ab358e06b41', 'ctime': '1581544001', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10737418240', 'children': [], 'pool': '', 'capacity': '10737418240', 'uuid': '40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'truesize': '4488503296', 'type': 'SPARSE'}}
Thread-484::DEBUG::2020-03-18 09:39:48,643::task::1191::Storage.TaskManager.Task::(prepare) Task=`3212d32a-f088-415d-853c-d4a6c203b2fb`::finished: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': 'Hosted Engine Image', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': 'f470821b-d9a9-4835-8ed9-2ab358e06b41', 'ctime': '1581544001', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10737418240', 'children': [], 'pool': '', 'capacity': '10737418240', 'uuid': '40f29b86-0eaa-4e64-a670-69ed7bc1011d', 'truesize': '4488503296', 'type': 'SPARSE'}}
Thread-484::DEBUG::2020-03-18 09:39:48,643::task::595::Storage.TaskManager.Task::(_updateState) Task=`3212d32a-f088-415d-853c-d4a6c203b2fb`::moving from state preparing -> state finished
Thread-484::DEBUG::2020-03-18 09:39:48,643::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-484::DEBUG::2020-03-18 09:39:48,643::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-484::DEBUG::2020-03-18 09:39:48,643::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-484::DEBUG::2020-03-18 09:39:48,643::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-484::DEBUG::2020-03-18 09:39:48,643::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-484::DEBUG::2020-03-18 09:39:48,643::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-484::DEBUG::2020-03-18 09:39:48,643::task::993::Storage.TaskManager.Task::(_decref) Task=`3212d32a-f088-415d-853c-d4a6c203b2fb`::ref 0 aborting False
Thread-484::INFO::2020-03-18 09:39:48,644::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42702 stopped
Reactor thread::INFO::2020-03-18 09:39:48,644::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42704
Reactor thread::DEBUG::2020-03-18 09:39:48,647::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,648::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42704
Reactor thread::DEBUG::2020-03-18 09:39:48,648::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42704)
BindingXMLRPC::INFO::2020-03-18 09:39:48,648::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42704
Thread-485::INFO::2020-03-18 09:39:48,648::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42704 started
Thread-485::DEBUG::2020-03-18 09:39:48,648::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-485::DEBUG::2020-03-18 09:39:48,648::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf8ef3e1-bcee-430c-b9c0-a8a80768dbfc`::moving from state init -> state preparing
Thread-485::INFO::2020-03-18 09:39:48,648::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumesList(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='63491779-c7cf-434c-84c9-7878694a8946', options=None)
Thread-485::DEBUG::2020-03-18 09:39:48,649::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`ad813fca-5f8d-4197-874b-7feb262fe810`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3291' at 'getVolumesList'
Thread-485::DEBUG::2020-03-18 09:39:48,649::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-485::DEBUG::2020-03-18 09:39:48,649::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-485::DEBUG::2020-03-18 09:39:48,649::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`ad813fca-5f8d-4197-874b-7feb262fe810`::Granted request
Thread-485::DEBUG::2020-03-18 09:39:48,649::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`bf8ef3e1-bcee-430c-b9c0-a8a80768dbfc`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-485::DEBUG::2020-03-18 09:39:48,649::task::993::Storage.TaskManager.Task::(_decref) Task=`bf8ef3e1-bcee-430c-b9c0-a8a80768dbfc`::ref 1 aborting False
Thread-485::INFO::2020-03-18 09:39:48,651::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumesList, Return response: {'uuidlist': [u'2f086a70-e97d-4161-a232-1268bb3145de']}
Thread-485::DEBUG::2020-03-18 09:39:48,651::task::1191::Storage.TaskManager.Task::(prepare) Task=`bf8ef3e1-bcee-430c-b9c0-a8a80768dbfc`::finished: {'uuidlist': [u'2f086a70-e97d-4161-a232-1268bb3145de']}
Thread-485::DEBUG::2020-03-18 09:39:48,651::task::595::Storage.TaskManager.Task::(_updateState) Task=`bf8ef3e1-bcee-430c-b9c0-a8a80768dbfc`::moving from state preparing -> state finished
Thread-485::DEBUG::2020-03-18 09:39:48,651::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-485::DEBUG::2020-03-18 09:39:48,651::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-485::DEBUG::2020-03-18 09:39:48,651::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-485::DEBUG::2020-03-18 09:39:48,651::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-485::DEBUG::2020-03-18 09:39:48,651::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-485::DEBUG::2020-03-18 09:39:48,651::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-485::DEBUG::2020-03-18 09:39:48,651::task::993::Storage.TaskManager.Task::(_decref) Task=`bf8ef3e1-bcee-430c-b9c0-a8a80768dbfc`::ref 0 aborting False
Thread-485::INFO::2020-03-18 09:39:48,652::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42704 stopped
Reactor thread::INFO::2020-03-18 09:39:48,652::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42706
Reactor thread::DEBUG::2020-03-18 09:39:48,656::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,656::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42706
Reactor thread::DEBUG::2020-03-18 09:39:48,656::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42706)
BindingXMLRPC::INFO::2020-03-18 09:39:48,656::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42706
Thread-486::INFO::2020-03-18 09:39:48,656::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42706 started
Thread-486::DEBUG::2020-03-18 09:39:48,656::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-486::DEBUG::2020-03-18 09:39:48,656::task::595::Storage.TaskManager.Task::(_updateState) Task=`d72d37c8-3a4d-4afc-bc50-b64a8359362e`::moving from state init -> state preparing
Thread-486::INFO::2020-03-18 09:39:48,657::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='331e6287-61df-48dd-9733-a8ad236750b1', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='63491779-c7cf-434c-84c9-7878694a8946', volUUID='2f086a70-e97d-4161-a232-1268bb3145de', options=None)
Thread-486::DEBUG::2020-03-18 09:39:48,657::resourceManager::199::Storage.ResourceManager.Request::(__init__) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`bab61764-0f3d-491c-9009-d8d47024878a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3159' at 'getVolumeInfo'
Thread-486::DEBUG::2020-03-18 09:39:48,657::resourceManager::545::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' for lock type 'shared'
Thread-486::DEBUG::2020-03-18 09:39:48,657::resourceManager::604::Storage.ResourceManager::(registerResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free. Now locking as 'shared' (1 active user)
Thread-486::DEBUG::2020-03-18 09:39:48,657::resourceManager::239::Storage.ResourceManager.Request::(grant) ResName=`Storage.331e6287-61df-48dd-9733-a8ad236750b1`ReqID=`bab61764-0f3d-491c-9009-d8d47024878a`::Granted request
Thread-486::DEBUG::2020-03-18 09:39:48,657::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`d72d37c8-3a4d-4afc-bc50-b64a8359362e`::_resourcesAcquired: Storage.331e6287-61df-48dd-9733-a8ad236750b1 (shared)
Thread-486::DEBUG::2020-03-18 09:39:48,657::task::993::Storage.TaskManager.Task::(_decref) Task=`d72d37c8-3a4d-4afc-bc50-b64a8359362e`::ref 1 aborting False
Thread-486::DEBUG::2020-03-18 09:39:48,658::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 2f086a70-e97d-4161-a232-1268bb3145de
Thread-486::INFO::2020-03-18 09:39:48,658::volume::915::Storage.Volume::(getInfo) Info request: sdUUID=331e6287-61df-48dd-9733-a8ad236750b1 imgUUID=63491779-c7cf-434c-84c9-7878694a8946 volUUID = 2f086a70-e97d-4161-a232-1268bb3145de
Thread-486::INFO::2020-03-18 09:39:48,660::volume::943::Storage.Volume::(getInfo) 331e6287-61df-48dd-9733-a8ad236750b1/63491779-c7cf-434c-84c9-7878694a8946/2f086a70-e97d-4161-a232-1268bb3145de info is {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': '{"Updated":true,"Size":10240,"Last Updated":"Tue Mar 03 10:33:30 PST 2020","Storage Domains":[{"uuid":"331e6287-61df-48dd-9733-a8ad236750b1"}],"Disk Description":"OVF_STORE"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '63491779-c7cf-434c-84c9-7878694a8946', 'ctime': '1583260407', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10240', 'children': [], 'pool': '', 'capacity': '134217728', 'uuid': '2f086a70-e97d-4161-a232-1268bb3145de', 'truesize': '12288', 'type': 'PREALLOCATED'}
Thread-486::INFO::2020-03-18 09:39:48,660::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': '{"Updated":true,"Size":10240,"Last Updated":"Tue Mar 03 10:33:30 PST 2020","Storage Domains":[{"uuid":"331e6287-61df-48dd-9733-a8ad236750b1"}],"Disk Description":"OVF_STORE"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '63491779-c7cf-434c-84c9-7878694a8946', 'ctime': '1583260407', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10240', 'children': [], 'pool': '', 'capacity': '134217728', 'uuid': '2f086a70-e97d-4161-a232-1268bb3145de', 'truesize': '12288', 'type': 'PREALLOCATED'}}
Thread-486::DEBUG::2020-03-18 09:39:48,660::task::1191::Storage.TaskManager.Task::(prepare) Task=`d72d37c8-3a4d-4afc-bc50-b64a8359362e`::finished: {'info': {'status': 'OK', 'domain': '331e6287-61df-48dd-9733-a8ad236750b1', 'voltype': 'LEAF', 'description': '{"Updated":true,"Size":10240,"Last Updated":"Tue Mar 03 10:33:30 PST 2020","Storage Domains":[{"uuid":"331e6287-61df-48dd-9733-a8ad236750b1"}],"Disk Description":"OVF_STORE"}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '63491779-c7cf-434c-84c9-7878694a8946', 'ctime': '1583260407', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '10240', 'children': [], 'pool': '', 'capacity': '134217728', 'uuid': '2f086a70-e97d-4161-a232-1268bb3145de', 'truesize': '12288', 'type': 'PREALLOCATED'}}
Thread-486::DEBUG::2020-03-18 09:39:48,660::task::595::Storage.TaskManager.Task::(_updateState) Task=`d72d37c8-3a4d-4afc-bc50-b64a8359362e`::moving from state preparing -> state finished
Thread-486::DEBUG::2020-03-18 09:39:48,661::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.331e6287-61df-48dd-9733-a8ad236750b1': < ResourceRef 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', isValid: 'True' obj: 'None'>}
Thread-486::DEBUG::2020-03-18 09:39:48,661::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-486::DEBUG::2020-03-18 09:39:48,661::resourceManager::619::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1'
Thread-486::DEBUG::2020-03-18 09:39:48,661::resourceManager::638::Storage.ResourceManager::(releaseResource) Released resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' (0 active users)
Thread-486::DEBUG::2020-03-18 09:39:48,661::resourceManager::644::Storage.ResourceManager::(releaseResource) Resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1' is free, finding out if anyone is waiting for it.
Thread-486::DEBUG::2020-03-18 09:39:48,661::resourceManager::652::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.331e6287-61df-48dd-9733-a8ad236750b1', Clearing records.
Thread-486::DEBUG::2020-03-18 09:39:48,661::task::993::Storage.TaskManager.Task::(_decref) Task=`d72d37c8-3a4d-4afc-bc50-b64a8359362e`::ref 0 aborting False
Thread-486::INFO::2020-03-18 09:39:48,662::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42706 stopped
Reactor thread::INFO::2020-03-18 09:39:48,686::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:42708
Reactor thread::DEBUG::2020-03-18 09:39:48,690::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2020-03-18 09:39:48,690::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:42708
Reactor thread::DEBUG::2020-03-18 09:39:48,690::bindingxmlrpc::1302::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 42708)
BindingXMLRPC::INFO::2020-03-18 09:39:48,690::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:42708
Thread-487::INFO::2020-03-18 09:39:48,690::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42708 started
Thread-487::DEBUG::2020-03-18 09:39:48,690::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-487::DEBUG::2020-03-18 09:39:48,691::task::595::Storage.TaskManager.Task::(_updateState) Task=`b3a81320-5e4b-49c1-bd67-546012d57a9a`::moving from state init -> state preparing
Thread-487::INFO::2020-03-18 09:39:48,691::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-487::INFO::2020-03-18 09:39:48,691::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'331e6287-61df-48dd-9733-a8ad236750b1': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000279927', 'lastCheck': '4.6', 'valid': True}}
Thread-487::DEBUG::2020-03-18 09:39:48,691::task::1191::Storage.TaskManager.Task::(prepare) Task=`b3a81320-5e4b-49c1-bd67-546012d57a9a`::finished: {'331e6287-61df-48dd-9733-a8ad236750b1': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000279927', 'lastCheck': '4.6', 'valid': True}}
Thread-487::DEBUG::2020-03-18 09:39:48,691::task::595::Storage.TaskManager.Task::(_updateState) Task=`b3a81320-5e4b-49c1-bd67-546012d57a9a`::moving from state preparing -> state finished
Thread-487::DEBUG::2020-03-18 09:39:48,691::resourceManager::943::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-487::DEBUG::2020-03-18 09:39:48,691::resourceManager::980::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-487::DEBUG::2020-03-18 09:39:48,691::task::993::Storage.TaskManager.Task::(_decref) Task=`b3a81320-5e4b-49c1-bd67-546012d57a9a`::ref 0 aborting False
Thread-487::INFO::2020-03-18 09:39:48,692::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:42708 stopped
_______________________________________________
Users mailing list -- users@ovirt.org
To unsubscribe send an email to users-leave@ovirt.org
Privacy Statement: https://nam12.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.ovirt.org%2Fprivacy-policy.html&amp;data=02%7C01%7C%7Cf044032ed14f4e4d0bd108d7cc2ce5dd%7C32669cd6737f4b398bddd6951120d3fc%7C0%7C1%7C637202365566899917&amp;sdata=AfdsIAzmR6Mvt4DI8fyGC67Vf0Um2QY1MaptVGnXcvY%3D&amp;reserved=0
oVirt Code of Conduct: https://nam12.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.ovirt.org%2Fcommunity%2Fabout%2Fcommunity-guidelines%2F&amp;data=02%7C01%7C%7Cf044032ed14f4e4d0bd108d7cc2ce5dd%7C32669cd6737f4b398bddd6951120d3fc%7C0%7C1%7C637202365566909911&amp;sdata=BxFkMbAZSx6ntI1NeDL0RSmHnnrz07hNU2ZEy3AG%2Fmw%3D&amp;reserved=0
List Archives: https://nam12.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.ovirt.org%2Farchives%2Flist%2Fusers%40ovirt.org%2Fmessage%2FKKU4EDNZ2Y2ZDNEWKB5B2BZJPLUCKS6S%2F&amp;data=02%7C01%7C%7Cf044032ed14f4e4d0bd108d7cc2ce5dd%7C32669cd6737f4b398bddd6951120d3fc%7C0%7C1%7C637202365566909911&amp;sdata=hBSyMJq0ouLHQPgdwqtZVZPl4YZqEUFoj%2B8r9EjE8dU%3D&amp;reserved=0