Users March 2020

users@ovirt.org

98 participants
152 discussions

ovirt-engine service in hosted engine appliance cannot start properly

by it＠rafalwojciechowski.pl

hello, I have a problem with oVirt in my home lab - probably after power outage(all hypervisors + hosted engine appliance went down) Current state: hosted engine appliance is starting from OS perspective, however some jboss related stuff seems to be malfunctioning. /var/log/ovirt-engine: grep ERROR engine.log | tail -n2 2020-03-17 17:35:52,769+01 ERROR [org.ovirt.engine.core.bll.network.macpool.MacPoolPerCluster] (ServerService Thread Pool -- 50) [] Error initializing: Duplicate key VM [***some_vm_name***] 2020-03-17 17:35:52,922+01 ERROR [org.ovirt.engine.core.bll.Backend] (ServerService Thread Pool -- 50) [] Error during initialization: javax.ejb.EJBException: java.lang.IllegalStateException: WFLYEE0042: Failed to construct component instance grep ERROR server.log | tail -n2 2020-03-17 17:36:00,755+01 ERROR [org.jboss.as.controller.management-operation] (Controller Boot Thread) WFLYCTL0013: Operation ("deploy") failed - address: ([("deployment" => "engine.ear")]) - failure description: {"WFLYCTL0080: Failed services" => {"jboss.deployment.subunit.\"engine.ear\".\"bll.jar\".component.Backend.START" => "java.lang.IllegalStateException: WFLYEE0042: Failed to construct component instance 2020-03-17 17:36:01,021+01 ERROR [org.jboss.as] (Controller Boot Thread) WFLYSRV0026: WildFly Full 14.0.1.Final (WildFly Core 6.0.2.Final) started (with errors) in 56493ms - Started 1492 of 1728 services (6 services failed or missing dependencies, 387 services are lazy, passive or on-demand) probably because of that I am receiving 503 while connecting to webgui grep 503 /var/log/httpd/access_log | tail -n1 ***some_intenal_ip*** - - [18/Mar/2020:13:01:26 +0100] "GET /ovirt-engine/services/health HTTP/1.1" 503 299 "-" "Python-urllib/2.7" Ovirt Engine version: ovirt-engine-4.2.8.2-1.el7.noarch if you could help me or at least give some hints/advice then it could be great. I tried to google it however without any luck. thanks in advance. btw - in this case ovirt-engine service status is "fine" when checking via systemctl - not sure if it should reflect state "active (running)" when it is working partially

4 years, 1 month

1
1
0 / 0

3.6-- hosted_storage volume not importing

by briany＠alleninstitute.org

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://access.redhat.com/solutions/2592761 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

4 years, 1 month

4
3
0 / 0

LDAP

by Nicholas Emmerling

Would you please provide any documentation you have regarding configuring oVirt to work with LDAP. Preferably the guest VMs as well as the Hosts/Nodes themselves. Thank you. nicholas.emmerling(a)me.com Sent from my iPhone

4 years, 1 month

2
1
0 / 0

Error when adding storage domain using VLAN tagging

by briandumont＠gmail.com

Hello, First post! I'm trying to add a nfs storage domain with VLAN tagging turned on the logical network. It errors out with "Error while executing action Add Storage Connection: Problem while trying to mount target". Couple of notes - I am able to attach to this nfs export from RHV without vlan tagging. I have also verified that I can attach to this nfs export with vlan tagging using a non-ovirt rhel host. Here's my config: - Logical network created at Data Center - Enable Vlan Tagging - ID 15 - Not a VM Network - Cluster status - Network - Up - Assign all - checked - Require - checked - no other boxes checked Host status - Host 1 and Host 2 each show - Status - up - BootP - None (same issue with static IP's) - LinK Layer info shows VLAN ID 15 on switch port Appreciate any help! Brian

4 years, 1 month

1
0
0 / 0

storage use after storage live migration

by Rik Theys

Hi, We are in the process of migrating our VM's from one storage domain to another. Both domains are FC storage. There are VM's with thin provisioned disks of 16G that currently only occupy 3G according to the interface. When we live migrate the disks (with the VM running), I can see that a snapshot is being taken and removed afterwards. After the storage migration, the occupied disk space on the new storage domain is 6G. Even for a VM that hardly has any writes. How can I reclaim this space? I've powered down the VM and did a sparsify on the disk but this doesn't seem to have any effect. When I do a storage migration of a VM with a thin provisioned disk that is down during the migration, the used disk space does not increase. VM's with fully allocated disks also don't seem to exhibit this behavior. My storage domain now also contains VM with more occupied storage space and the size of the disk?? There are no snapshots listed for those disks. Is there a way to clean up this situation? Regards, Rik -- Rik Theys System Engineer KU Leuven - Dept. Elektrotechniek (ESAT) Kasteelpark Arenberg 10 bus 2440 - B-3001 Leuven-Heverlee +32(0)16/32.11.07 ---------------------------------------------------------------- <<Any errors in spelling, tact or fact are transmission errors>>

4 years, 1 month

2
2
0 / 0

Ovirt API and CLI

by Eugène Ngontang

Hi, I'm trying to find out there a sort of API or ovirt CLI/SDK in order to be able to interact with my ovirt VMS and associated resources. In my architecture, I have an Ovirt virtualization host, with a self-hosted engine VM to manage VMs. From the host I have the virsh command to list VMs status, but this doesn't really let me get into VMs management actions like : create, delete, get, reboot, get VMs wide informations (IPs, name, disks.....) So each time I have to login to the hosted engine web admin page to explore VM, but I'd really like to play with my Ovirt resources from my command line or programatically. The ovirt API documentation I've found is really poor, I don't know if someone here has already got the same need and had a good solution. Thanks for your help. Regards, Eugène NG -- LesCDN <http://lescdn.com> engontang(a)lescdn.com ------------------------------------------------------------ *Aux hommes il faut un chef, et au* * chef il faut des hommes!L'habit ne fait pas le moine, mais lorsqu'on te voit on te juge!*

4 years, 1 month

8
16
0 / 0

Orphaned ISO Storage Domain

by Bob Franzke

Greetings all, Full disclosure, complete OVIRT novice here. I inherited an OVIRT system and had a complete ovirt-engine back in December-January. Because of time and my inexperience with OVIRT, I had to resort to hiring consultants to rebuild my OVIRT engine from backups. That's a situation I never want to repeat. Anyway, we were able to piece it together and at least get most functionality back. The previous setup had a ISO storage domain called 'ISO-COLO' that seems to have been hosted on the engine server itself. The engine hostname is 'mydesktop'. We restored the engine from backups I had taken of the SQL DB and various support files using the built in OVIRT backup tool. So now when looking into the OVIRT console, I see the storage domain listed. It has a status of 'inactive' showing in the list of various storage domains we have setup for this. We tried to 'activate' it and it fails activation. The path listed for the domain is mydesktop:/gluster/colo-iso. On the host however there is no mountpoint that equates to that path: [root@mydesktop ~]# df -h Filesystem Size Used Avail Use% Mounted on devtmpfs 47G 0 47G 0% /dev tmpfs 47G 12K 47G 1% /dev/shm tmpfs 47G 131M 47G 1% /run tmpfs 47G 0 47G 0% /sys/fs/cgroup /dev/mapper/centos-root 50G 5.4G 45G 11% / /dev/sda2 1014M 185M 830M 19% /boot /dev/sda1 200M 12M 189M 6% /boot/efi /dev/mapper/centos-home 224G 15G 210G 7% /home tmpfs 9.3G 0 9.3G 0% /run/user/0 The original layout looked like this on the broken engine: [root@mydesktop ~]# df -h Filesystem Size Used Avail Use% Mounted on /dev/mapper/centos_mydesktop-root 50G 27G 20G 58% / devtmpfs 24G 0 24G 0% /dev tmpfs 24G 28K 24G 1% /dev/shm tmpfs 24G 42M 24G 1% /run tmpfs 24G 0 24G 0% /sys/fs/cgroup /dev/mapper/centos_mydesktop-home 25G 45M 24G 1% /home /dev/sdc1 1014M 307M 708M 31% /boot /dev/mapper/centos_mydesktop-gluster 177G 127G 42G 76% /gluster tmpfs 4.7G 0 4.7G 0% /run/user/0 So it seems the orphaned storage domain is just point to a path that does not exist on the new Engine host. Also noticed some of the hosts are trying to aces this storage domain and getting errors: The error message for connection mydesktop:/gluster/colo-iso returned by VDSM was: Problem while trying to mount target 3/17/2010:47:05 AM Failed to connect Host vm-host-colo-2 to the Storage Domains ISO-Colo. 3/17/2010:47:05 AM So it seems hosts are trying to be connected to this storage domain but cannot because its not there. Any of the files from the original path are not available so I am not even sure what we are missing if anything. So what are my options here. Destroy the current ISO domain and recreate it, or somehow provide the correct path on the engine server? Currently the storage space I can use is mounted with /home, which is a different path than the original one. Not sure if anything can be done with the disk layout at this point to correct this on the engine server itself to get the gluster path back. Right now we cannot attach CDs to VMs for booting. No choices show up for use when doing a 'run once' on an existing VM so I would like to get this working so I can fix a broken VM that I need to boot off of ISO media. Thanks in advance for any help you can provide.

4 years, 1 month

2
1
0 / 0

Gluster Settings

by Christian Reiss

Hey folks, quick question. For running Gluster / oVirt I found several places, some outdated (ovirt docs), gluster Mailinglists, oVirt Mailinglists etc that recommend different things. Here is what I found out/configured: features.barrier: disable features.show-snapshot-directory: on features.uss: enable cluster.data-self-heal-algorithm: full cluster.entry-self-heal: on cluster.data-self-heal: on cluster.metadata-self-heal: on cluster.readdir-optimize: on transport.address-family: inet storage.fips-mode-rchecksum: on nfs.disable: on performance.client-io-threads: off network.remote-dio: off performance.strict-o-direct: on client.event-threads: 16 cluster.choose-local: true snap-activate-on-create: enable auto-delete: enable Would you agree or change anything (usual vm workload). Thanks! o/ And keep healthy. -- with kind regards, mit freundlichen Gruessen, Christian Reiss

4 years, 1 month

3
4
0 / 0

VNC Encryption

by Tommaso - Shellrent

Hi to all. We need to set VNC Encryption to disabled on cluster creation, but we do not find any reference on API or SDK to do this automatically. Someone have any kind of hint to do this? -- -- Shellrent - Il primo hosting italiano Security First *Tommaso De Marchi* /COO - Chief Operating Officer/ Shellrent Srl Via dell'Edilizia, 19 - 36100 Vicenza Tel. 0444321155 <tel:+390444321155> | Fax 04441492177

4 years, 1 month

1
0
0 / 0

How to delete events

by xilazz＠126.com

Hello everybody, there are some wrong log events in the controller. How can I delete the events information after I have checked it?

4 years, 1 month

5
5
0 / 0

← Newer
1
...
7
8
9
10
11
12
13
...
16
Older →

Jump to page:

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

Users March 2020