Users
Threads by month
- ----- 2026 -----
- February
- January
- ----- 2025 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2024 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2023 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2022 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2021 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2020 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2019 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2018 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2017 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2016 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2015 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2014 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2013 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2012 -----
- December
- November
- October
- September
- August
- July
- June
- May
- April
- March
- February
- January
- ----- 2011 -----
- December
- November
- October
- 6 participants
- 19176 discussions
Hello,
I want to know whether a base disk image is physically copied whenever the VM is created from a template.
I've just created a VM based on template with 1 disk and checked VM's virtual disk images.
there were (1)base image copied? from the template, (2)new delta image.
Here, (1) image was identical to that of the template and I know that image is used as read-only mode.
So, I am wondering why base (disk) image is inefficiently copied instead of directly referencing template's image as backing file.
1
1
Hello,
I would need to have on ovirt node these three packages:
- ipmitool
- perf
- dstat
Comparing latest RHVH (4.3.8) and latest ovirt-node-ng (4.3.9) I see that:
- ipmitool is present on both
- perf is present as an installable package in RHVH and not in ovirt-node-ng
- dstat is not available in any of them
Why the difference about perf?
Is it safe to install perf and dstat on ovirt-node-ng taking them from
CentOS updates?
This is for a lab and the packages would be used to compute some metrics
about performance of the node.
Thanks,
Gianluca
1
0
Hi Anton,
I believe so - but I believe you can do a hosted-engine deploy with
the backup file specified so it auto-restores with it.
I need to try it on a test system I haven't done much DR testing yet.
My builds have been rushed into production due to time constraints, and
although I backup and ship off-site so I have it all I actually haven't
done a full breakdown and re-restore yet :/
I'll be interested to know how you go, if you dont mind.
Thanks,
Joe
On 2020-03-23 3:32 PM, Anton Louw wrote:
>
>
> Hi Joseph,
>
> Thanks for the reply. So in short, the process will then be to 1) Take
> a backup of the Hosted Engine, 2) Do a clean-up of the Hosted Engine,
> and then lastly redeploy on one of the nodes using hosted-engine
> deploy? After that then I will do a restore?
>
> Thanks
>
>
> *Anton Louw*
> *Cloud Engineer: Storage and Virtualization* at *Vox*
> ------------------------------------------------------------------------
> *T:* 087 805 0000 | *D:* 087 805 1572
> *M:* N/A
> *E:* anton.louw(a)voxtelecom.co.za <mailto:anton.louw@voxtelecom.co.za>
> *A:* Rutherford Estate, 1 Scott Street, Waverley, Johannesburg
> www.vox.co.za <http://www.vox.co.za>
>
> F <https://www.facebook.com/voxtelecomZA>
>
>
> T <https://www.twitter.com/voxtelecom>
>
>
> I <https://www.instagram.com/voxtelecomza/>
>
>
> L <https://www.linkedin.com/company/voxtelecom>
>
>
> Y <https://www.youtube.com/user/VoxTelecom>
>
> #VoxBrand <https://www.vox.co.za/fibre/fibre-to-the-home/?prod=HOME>
>
>
> *Disclaimer*
>
> The contents of this email are confidential to the sender and the
> intended recipient. Unless the contents are clearly and entirely of a
> personal nature, they are subject to copyright in favour of the
> holding company of the Vox group of companies. Any recipient who
> receives this email in error should immediately report the error to
> the sender and permanently delete this email from all storage devices.
>
> This email has been scanned for viruses and malware, and may have been
> automatically archived by *Mimecast Ltd*, an innovator in Software as
> a Service (SaaS) for business. Providing a *safer* and *more useful*
> place for your human generated data. Specializing in; Security,
> archiving and compliance. To find out more Click Here
> <https://www.voxtelecom.co.za/security/mimecast/?prod=Enterprise>.
>
>
>
> *From:*Joseph Goldman <joseph(a)goldman.id.au>
> *Sent:* 20 March 2020 14:23
> *To:* users(a)ovirt.org
> *Subject:* [ovirt-users] Re: Moving Hosted Engine
>
> It is my understanding that yes taking a full backup and then redploying
> into a new storage domain using the backup is the correct way - I dont
> think you'd need a new physical server for it though unless you mean you
> are running on bare-metal.
>
> On 2020-03-20 11:04 PM, anton.louw(a)voxtelecom.co.za
> <mailto:anton.louw@voxtelecom.co.za> wrote:
> > Hi All,
> >
> > I am in serious need of some help. We currently have our Hosted
> Engine running on a Storage Domain, but that storage Domain is
> connected to a San that needs to be decommissioned. What would I need
> to do in order to get my Hosted Engine running on a different Storage
> Domain?
> >
> > Will I need to build a new CentOS server, download and Install the
> oVirt Setup, and then restore the backup that I took of my original
> Hosted Engine, using “engine-backup --mode=backup”?
> >
> > I tried looking around at backup solutions that would restore the
> whole VM to a different Storage Domain, but I can’t seem to find anything.
> >
> > Any advise would be greatly appreciated.
> > _______________________________________________
> > Users mailing list -- users(a)ovirt.org <mailto:users@ovirt.org>
> > To unsubscribe send an email to users-leave(a)ovirt.org
> <mailto:users-leave@ovirt.org>
> > Privacy Statement: https://www.ovirt.org/privacy-policy.html
> <https://www.ovirt.org/privacy-policy.html>
> > oVirt Code of Conduct:
> https://www.ovirt.org/community/about/community-guidelines/
> <https://www.ovirt.org/community/about/community-guidelines>
> > List Archives:
> https://lists.ovirt.org/archives/list/users@ovirt.org/message/TGI2T46W62JE4…
> <https://lists.ovirt.org/archives/list/users@ovirt.org/message/TGI2T46W62JE4…>
> _______________________________________________
> Users mailing list -- users(a)ovirt.org <mailto:users@ovirt.org>
> To unsubscribe send an email to users-leave(a)ovirt.org
> <mailto:users-leave@ovirt.org>
> Privacy Statement: https://www.ovirt.org/privacy-policy.html
> <https://www.ovirt.org/privacy-policy.html>
> oVirt Code of Conduct:
> https://www.ovirt.org/community/about/community-guidelines/
> <https://www.ovirt.org/community/about/community-guidelines/>
> List Archives:
> https://lists.ovirt.org/archives/list/users@ovirt.org/message/NYLHUQPK72QUN…
> <https://lists.ovirt.org/archives/list/users@ovirt.org/message/NYLHUQPK72QUN…>
>
1
0
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". I am able to
attach to this nfs export 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
3
2
Hello,
I successfully attached VF to a VM on a single PF nic following
https://access.redhat.com/articles/3215851.
I want the vm with VF to be migratable, but the nic hotplug/replug is
too long. So I tested the mode 1 bonding (active-backup) with a virtio
nic following this
https://www.ovirt.org/develop/release-management/features/network/liveMigra…
On a single PF, the resilience tests with migration are correct with 1
or 2 second downtime.
But now I want to do the same on a typical host with LACP PF:
Considering vlan13, I must bond a virtio nic on a brv13/brv13 profile
with SR-IOV/brv13 profile as the primary interface.
Everything work when the primary interface is brv13/brv13 profile (work
as a traditionnal bridge config), but not when changing on the
SR-IOV/brv13 profile.
I know in this case that the SR-IOV profile is connected to a LACP
interface, but does it mean that I have to configure the VF vnic in the
VM to be part of the LACP(bond1) as a single member and in that case to
do active-backup bond0 with two members bond1 and brv13 nic?
Hope to be clear enough.
Thanks for your help.
--
Nathanaël Blanchet
Supervision réseau
SIRE
227 avenue Professeur-Jean-Louis-Viala
34193 MONTPELLIER CEDEX 5
Tél. 33 (0)4 67 54 84 55
Fax 33 (0)4 67 54 84 14
blanchet(a)abes.fr
1
0
Hi All,
I am in serious need of some help. We currently have our Hosted Engine running on a Storage Domain, but that storage Domain is connected to a San that needs to be decommissioned. What would I need to do in order to get my Hosted Engine running on a different Storage Domain?
Will I need to build a new CentOS server, download and Install the oVirt Setup, and then restore the backup that I took of my original Hosted Engine, using “engine-backup --mode=backup”?
I tried looking around at backup solutions that would restore the whole VM to a different Storage Domain, but I can’t seem to find anything.
Any advise would be greatly appreciated.
3
2
Hello,
I created some hosts at time of 4.3.3 or similar and connecting to iSCSI I
set this in multipath.conf to specify customization
"
# VDSM REVISION 1.5
# VDSM PRIVATE
# This file is managed by vdsm.
...
"
Then I updated the environment gradually to 4.3.8 but of course the file
remained the same because of its configuration and the "PRIVATE" label.
Now I install new hosts in 4.3.8 and I see that by default they have these
lines
"
# VDSM REVISION 1.8
# This file is managed by vdsm.
"
So the question is:
suppose I customize the multipath.conf file using the "# VDSM PRIVATE"
line, how do I have to manage the REVISION number as time goes on and I
execute minor updates to hosts?
What will it change between 1.5 above and 1.8? Any impact if I leave 1.5
for example across all my 4.3.8 hosts?
Thanks in advance for clarification,
Gianluca
2
1
21 Mar '20
Hello Community,
Wanted to contribute with the little I know after working a few times with oVirt in an HCI environment.
One of the questions for which I was not able to find a straight forward answer is how to deploy an HCI oVirt environment, so after a few struggles I was able to achieve that goal.
Below is an example of what I used to fully deploy a 3 node cluster with oVirt 4.3.7.
Please note I am no expert and just providing what I have acomplished in my lab, so use the below at your own risk.
1.-Hardware used in my lab :
3 x Dell R610s, 48Gb Ram per server, Intel Xeon L5640 @ 2.27GHz Hex core x 2
2 x 146GB HDDs for OS
1 x 600GB HDD for Gluster Bricks
Dual 10Gb Nic.
2.-Deployed the servers using oVirt 4.3.7 image.
3.-Added ssh keys to be able to ssh from host 1 over to host 2 and host 3 without a password
4.-Modified the following files for ansible deployment on Host 1
4.1.-Under etc/ansible/roles/gluster.ansible/playbooks/hc-ansible-deployment
-- Modify file he_gluster_vars.json with the Hosted Engine VM required information:
--Modify file gluster_inventory.yml with hosts and gluster information
You can find the modified files that I used here https://github.com/viejillo/ovirt-hci-ansible
I hope this helps and if any questions feel free to reach out.
Regards,
AQ
1
0
ovirt-engine service in hosted engine appliance cannot start properly
by it＠rafalwojciechowski.pl 21 Mar '20
by it＠rafalwojciechowski.pl 21 Mar '20
21 Mar '20
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
1
1
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
3