Users
Threads by month
- ----- 2025 -----
- 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
March 2020
- 98 participants
- 153 discussions
Hi,
it seems the online documentation regarding the windows installation steps
is well out of date. Where is there any current documentation on where to
get the VirtIO drivers for a Windows installation?
From a bit of Googling, it seems that I need to 'yum install virtio-win' on
the engine VM and then copy the relevant .iso/.vfd to the ISO domain. Is
that correct?
Where is the documentation maintained and how do I open a bug on it?
Thanks, Shareef.
3
2
25 Mar '20
oVirt 4.4.0 Alpha release refresh is now available for testing
The oVirt Project is excited to announce the availability of the alpha
release refresh of oVirt 4.4.0 for testing, as of March 6th, 2020
This release unleashes an altogether more powerful and flexible open source
virtualization solution that encompasses hundreds of individual changes and
a wide range of enhancements across the engine, storage, network, user
interface, and analytics on top of oVirt 4.3.
Important notes before you try it
Please note this is an Alpha release.
The oVirt Project makes no guarantees as to its suitability or usefulness.
This pre-release must not to be used in production, and it is not feature
complete.
In particular, please note that upgrades from 4.3 and future upgrades from
this alpha to the final 4.4 release from this version are not supported.
Some of the features included in oVirt 4.4.0 Alpha require content that
will be available in CentOS Linux 8.2 which are currently included in Red
Hat Enterprise Linux 8.2 beta. If you want to have a better experience you
can test oVirt 4.4.0 Alpha on Red Hat Enterprise Linux 8.2 beta.
Known Issues
-
After installation open the Default cluster and hit “Save”, for any
other new Cluster using CPU autodetection the dialog needs to be explicitly
saved after the detection happens, after first host is added. (bug
https://bugzilla.redhat.com/1770697)
Installation instructions
For the engine: either use appliance or:
- Install CentOS Linux 8 minimal from
http://centos.mirror.garr.it/centos/8.1.1911/isos/x86_64/CentOS-8.1.1911-x8…
- dnf install
https://resources.ovirt.org/pub/yum-repo/ovirt-release44-pre.rpm
- dnf update (reboot if needed)
- dnf module enable -y javapackages-tools pki-deps 389-ds
- dnf install ovirt-engine
- engine-setup
For the nodes:
Either use oVirt Node ISO or:
- Install CentOS Linux 8 from
http://centos.mirror.garr.it/centos/8.1.1911/isos/x86_64/CentOS-8.1.1911-x8…
; select minimal installation
- dnf config-manager --set-enabled PowerTools
- dnf install
https://resources.ovirt.org/pub/yum-repo/ovirt-release44-pre.rpm
- dnf update (reboot if needed)
- Attach the host to engine and let it be deployed.
What’s new in oVirt 4.4.0 Alpha?
-
Hypervisors based on CentOS Linux 8 (rebuilt from award winning RHEL8),
for both oVirt Node and standalone CentOS Linux hosts
-
Easier network management and configuration flexibility with
NetworkManager
-
VMs based on a more modern Q35 chipset with legacy seabios and UEFI
firmware
-
Support for direct passthrough of local host disks to VMs
-
Live migration improvements for High Performance guests.
-
New Windows Guest tools installer based on WiX framework now moved to
VirtioWin project
-
Dropped support for cluster level prior to 4.2
-
Dropped SDK3 support
-
4K disks support
-
Exporting a VM to a data domain
-
Editing of floating disks
-
Integrating ansible-runner into engine, which allows a more detailed
monitoring of playbooks executed from engine
-
Adding/reinstalling hosts are now completely based on Ansible
-
The OpenStack Neutron Agent cannot be configured by oVirt anymore, it
should be configured by TripleO instead
This release is available now on x86_64 architecture for:
* Red Hat Enterprise Linux 8.1 or newer
* CentOS Linux (or similar) 8.1 or newer
This release supports Hypervisor Hosts on x86_64 and ppc64le architectures
for:
* Red Hat Enterprise Linux 8.1 or newer (8.2 beta recommended)
* CentOS Linux (or similar) 8.1 or newer
* oVirt Node 4.4 based on CentOS Linux 8.1 (available for x86_64 only)
See the release notes [1] for installation instructions and a list of new
features and bugs fixed.
If you manage more than one oVirt instance, OKD or RDO we also recommend to
try ManageIQ <http://manageiq.org/>.
In such a case, please be sure to take the qc2 image and not the ova image.
Notes:
- oVirt Appliance is already available for CentOS Linux 8
- oVirt Node NG is already available for CentOS Linux 8
Additional Resources:
* Read more about the oVirt 4.4.0 release highlights:
http://www.ovirt.org/release/4.4.0/
* Get more oVirt project updates on Twitter: https://twitter.com/ovirt
* Check out the latest project news on the oVirt blog:
http://www.ovirt.org/blog/
[1] http://www.ovirt.org/release/4.4.0/
[2] http://resources.ovirt.org/pub/ovirt-4.4-pre/iso/
--
Sandro Bonazzola
MANAGER, SOFTWARE ENGINEERING, EMEA R&D RHV
Red Hat EMEA <https://www.redhat.com/>
sbonazzo(a)redhat.com
<https://www.redhat.com/>*Red Hat respects your work life balance.
Therefore there is no need to answer this email out of your office hours.*
12
19
Hi Everybody,
Does anybody know when we will most likely be able to do a live storage migration of the Hosted Engine? I've been battling with the backup and restore way for a couple of days now already, and it is starting to feel like a fruitless exercise.
Thanks
Anton Louw
Cloud Engineer: Storage and Virtualization
______________________________________
D: 087 805 1572 | M: N/A
A: Rutherford Estate, 1 Scott Street, Waverley, Johannesburg
anton.louw(a)voxtelecom.co.za
www.vox.co.za
1
0
hi
can't upload disk image with that script:
https://github.com/oVirt/ovirt-engine-sdk/blob/master/sdk/examples/upload_d…
this error message is appeared when i trying to upload image:
# python upload_disk.py --engine-url https://alias-e.localdomain
--username admin@internal --disk-format raw --sd-name iscsi-test-7 -c
ca.pem /home/linux1.raw
Checking image...
Image format: raw
Disk format: raw
Disk content type: data
Disk provisioned size: 42949672960
Disk initial size: 42949672960
Disk name: linux1.raw
Connecting...
Password:
Creating disk...
Creating transfer session...
Uploading image...
Traceback (most recent call last):
File "upload_disk.py", line 288, in <module>
with ui.ProgressBar() as pb:
TypeError: __init__() takes at least 2 arguments (1 given)
software using:
ovirt-engine 4.3.8.2-1
python-ovirt-engine-sdk4-4.3.2-2
2
2
Hello,
I heard some say SPM disappeared since 3.6.
nevertheless, SPM still exists in oVirt admin portal or even in RHV's manual.
So, I am wondering whether SPM still exists now.
And could I know how to get more detailed information for oVirt internals??
is the code review the best way?
2
2
On Mon, Mar 23, 2020 at 11:56 PM Shirly Radco <sradco(a)redhat.com> wrote:
> Hi,
>
> I can't answer about perf, But would Collectd be useful for you?
> It is already installed on the hosts and engine.
>
> Best,
> Shirly
>
>
Thanks for your answer Shirly,
do you mean implementing Metrics Store?
Gianluca
1
0
Good morning,
I have an Ovirt infrastructure and its configured in private network.
How can I connect from public network to web portal and the virtual machines via spice client?
My infrastructure is configured by 1 engine and 2 hosts.
How can I do? Suggestions?
Thanks!
Best regards
Nikkognt
1
1
Data Center, Cluster and Storage Domains show as "Down" after backup and restore
by anton.louw＠voxtelecom.co.za 24 Mar '20
by anton.louw＠voxtelecom.co.za 24 Mar '20
24 Mar '20
Hi Everybody,
So I did a full backup of our HE, redeployed and restored. After the restore, I ran engine-setup on the newly deployed HE. I can access the the environment as per normal, the only issue is that everything still shows as "down", this includes hosts and VMs?
Is there something I need to do in order to get everything to display as "Up" again?
Thanks
1
0
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
Would you please provide any documentation you have regarding configuring oVirt to work with LDAP. Preferably the guest VMs as well as the Hosts/Nodes themselves. Thank you.
nicholas.emmerling(a)me.com
Sent from my iPhone
2
1
Hello,
First post!
I'm trying to add a nfs storage domain with VLAN tagging turned on the logical network. It errors out with "Error while executing action Add Storage Connection: Problem while trying to mount target".
Couple of notes - I am able to attach to this nfs export from RHV without vlan tagging. I have also verified that I can attach to this nfs export with vlan tagging using a non-ovirt rhel host.
Here's my config:
- Logical network created at Data Center
- Enable Vlan Tagging - ID 15
- Not a VM Network
- Cluster status
- Network - Up
- Assign all - checked
- Require - checked
- no other boxes checked
Host status
- Host 1 and Host 2 each show
- Status - up
- BootP - None (same issue with static IP's)
- LinK Layer info shows VLAN ID 15 on switch port
Appreciate any help!
Brian
1
0
Hi,
We are in the process of migrating our VM's from one storage domain to
another. Both domains are FC storage.
There are VM's with thin provisioned disks of 16G that currently only
occupy 3G according to the interface. When we live migrate the disks
(with the VM running), I can see that a snapshot is being taken and
removed afterwards.
After the storage migration, the occupied disk space on the new storage
domain is 6G. Even for a VM that hardly has any writes. How can I
reclaim this space? I've powered down the VM and did a sparsify on the
disk but this doesn't seem to have any effect.
When I do a storage migration of a VM with a thin provisioned disk that
is down during the migration, the used disk space does not increase.
VM's with fully allocated disks also don't seem to exhibit this behavior.
My storage domain now also contains VM with more occupied storage space
and the size of the disk?? There are no snapshots listed for those
disks. Is there a way to clean up this situation?
Regards,
Rik
--
Rik Theys
System Engineer
KU Leuven - Dept. Elektrotechniek (ESAT)
Kasteelpark Arenberg 10 bus 2440 - B-3001 Leuven-Heverlee
+32(0)16/32.11.07
----------------------------------------------------------------
<<Any errors in spelling, tact or fact are transmission errors>>
2
2
Hi,
I'm trying to find out there a sort of API or ovirt CLI/SDK in order to be
able to interact with my ovirt VMS and associated resources.
In my architecture, I have an Ovirt virtualization host, with a self-hosted
engine VM to manage VMs.
From the host I have the virsh command to list VMs status, but this doesn't
really let me get into VMs management actions like : create, delete, get,
reboot, get VMs wide informations (IPs, name, disks.....)
So each time I have to login to the hosted engine web admin page to explore
VM, but I'd really like to play with my Ovirt resources from my command
line or programatically.
The ovirt API documentation I've found is really poor, I don't know if
someone here has already got the same need and had a good solution.
Thanks for your help.
Regards,
Eugène NG
--
LesCDN <http://lescdn.com>
engontang(a)lescdn.com
------------------------------------------------------------
*Aux hommes il faut un chef, et au*
* chef il faut des hommes!L'habit ne fait pas le moine, mais lorsqu'on te
voit on te juge!*
8
16
Greetings all,
Full disclosure, complete OVIRT novice here. I inherited an OVIRT system and
had a complete ovirt-engine back in December-January. Because of time and my
inexperience with OVIRT, I had to resort to hiring consultants to rebuild my
OVIRT engine from backups. That's a situation I never want to repeat.
Anyway, we were able to piece it together and at least get most
functionality back. The previous setup had a ISO storage domain called
'ISO-COLO' that seems to have been hosted on the engine server itself. The
engine hostname is 'mydesktop'. We restored the engine from backups I had
taken of the SQL DB and various support files using the built in OVIRT
backup tool.
So now when looking into the OVIRT console, I see the storage domain listed.
It has a status of 'inactive' showing in the list of various storage domains
we have setup for this. We tried to 'activate' it and it fails activation.
The path listed for the domain is mydesktop:/gluster/colo-iso. On the host
however there is no mountpoint that equates to that path:
[root@mydesktop ~]# df -h
Filesystem Size Used Avail Use% Mounted on
devtmpfs 47G 0 47G 0% /dev
tmpfs 47G 12K 47G 1% /dev/shm
tmpfs 47G 131M 47G 1% /run
tmpfs 47G 0 47G 0% /sys/fs/cgroup
/dev/mapper/centos-root 50G 5.4G 45G 11% /
/dev/sda2 1014M 185M 830M 19% /boot
/dev/sda1 200M 12M 189M 6% /boot/efi
/dev/mapper/centos-home 224G 15G 210G 7% /home
tmpfs 9.3G 0 9.3G 0% /run/user/0
The original layout looked like this on the broken engine:
[root@mydesktop ~]# df -h
Filesystem Size Used Avail Use% Mounted on
/dev/mapper/centos_mydesktop-root 50G 27G 20G 58% /
devtmpfs 24G 0 24G 0% /dev
tmpfs 24G 28K 24G 1% /dev/shm
tmpfs 24G 42M 24G 1% /run
tmpfs 24G 0 24G 0% /sys/fs/cgroup
/dev/mapper/centos_mydesktop-home 25G 45M 24G 1% /home
/dev/sdc1 1014M 307M 708M 31% /boot
/dev/mapper/centos_mydesktop-gluster 177G 127G 42G 76% /gluster
tmpfs 4.7G 0 4.7G 0% /run/user/0
So it seems the orphaned storage domain is just point to a path that does
not exist on the new Engine host.
Also noticed some of the hosts are trying to aces this storage domain and
getting errors:
The error message for connection mydesktop:/gluster/colo-iso returned by
VDSM was: Problem while trying to mount target
3/17/2010:47:05 AM
Failed to connect Host vm-host-colo-2 to the Storage Domains ISO-Colo.
3/17/2010:47:05 AM
So it seems hosts are trying to be connected to this storage domain but
cannot because its not there. Any of the files from the original path are
not available so I am not even sure what we are missing if anything.
So what are my options here. Destroy the current ISO domain and recreate it,
or somehow provide the correct path on the engine server? Currently the
storage space I can use is mounted with /home, which is a different path
than the original one. Not sure if anything can be done with the disk layout
at this point to correct this on the engine server itself to get the gluster
path back. Right now we cannot attach CDs to VMs for booting. No choices
show up for use when doing a 'run once' on an existing VM so I would like to
get this working so I can fix a broken VM that I need to boot off of ISO
media.
Thanks in advance for any help you can provide.
2
1
Hey folks,
quick question. For running Gluster / oVirt I found several places, some
outdated (ovirt docs), gluster Mailinglists, oVirt Mailinglists etc that
recommend different things.
Here is what I found out/configured:
features.barrier: disable
features.show-snapshot-directory: on
features.uss: enable
cluster.data-self-heal-algorithm: full
cluster.entry-self-heal: on
cluster.data-self-heal: on
cluster.metadata-self-heal: on
cluster.readdir-optimize: on
transport.address-family: inet
storage.fips-mode-rchecksum: on
nfs.disable: on
performance.client-io-threads: off
network.remote-dio: off
performance.strict-o-direct: on
client.event-threads: 16
cluster.choose-local: true
snap-activate-on-create: enable
auto-delete: enable
Would you agree or change anything (usual vm workload).
Thanks! o/
And keep healthy.
--
with kind regards,
mit freundlichen Gruessen,
Christian Reiss
3
4
Hi to all.
We need to set VNC Encryption to disabled on cluster creation, but we
do not find any reference on API or SDK to do this automatically.
Someone have any kind of hint to do this?
--
--
Shellrent - Il primo hosting italiano Security First
*Tommaso De Marchi*
/COO - Chief Operating Officer/
Shellrent Srl
Via dell'Edilizia, 19 - 36100 Vicenza
Tel. 0444321155 <tel:+390444321155> | Fax 04441492177
1
0