[Users] export domain issues with latest nightly/GIT Master

Thu Nov 8 03:47:26 UTC 2012

On issue 1 attached are log files narrowed down what was logged during the
attempted import when the disks are not shown.

On issue 2 I found this bug (
https://bugzilla.redhat.com/show_bug.cgi?id=801112) which seems to have a
similar footprint. This was working a few weeks back so I would classify
this as a regression.

On Wed, Nov 7, 2012 at 2:59 AM, Eli Mesika <emesika at redhat.com> wrote:

>
>
> ----- Original Message -----
> > From: "Dead Horse" <deadhorseconsulting at gmail.com>
> > To: "<users at ovirt.org>" <users at ovirt.org>
> > Sent: Wednesday, November 7, 2012 3:12:07 AM
> > Subject: [Users] export domain issues with latest nightly/GIT Master
> >
> >
> > I have noted some export domain issues with builds from the latest
> > GIT Master.
> >
> > 1) When importing a VM, the disks subtab of the VM to import will not
> > show the disks. Instead it shows the blinking progress squares. This
> > is persistent and will it will not show information on the disks to
> > be imported. This stopped working about 2 weeks back. Expected is to
> > show the disks to import as well as set provisioning type and
> > destination storage domain.
>
> Hi, can you plesae attach engin/vdsm logs as this is occuring generally
> when an exception is thrown in the middle of the import operation.
>
> >
> > 2) The import process does does not respect thin provisioning.
> > Importing a VM without checking the collapse snapshots box (there
> > are actually no snapshots to collapse...) results in the imported
> > disks being imported thickly provisioned. If the collapse snapshots
> > box is checked thin provisioning is respected and the disks import
> > thin provisioned. This may be intertwined with the prior issue.
>
> Is that as regression or a new bug ?
>
> >
> > - DHC
> >
> > _______________________________________________
> > Users mailing list
> > Users at ovirt.org
> > http://lists.ovirt.org/mailman/listinfo/users
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20121107/9baa7ba9/attachment-0001.html>
-------------- next part --------------
2012-11-07 21:22:45,978 INFO  [org.ovirt.engine.core.bll.LoginAdminUserCommand] (ajp--127.0.0.1-8702-11) Checking if user admin at internal is an admin, result true
2012-11-07 21:22:45,980 INFO  [org.ovirt.engine.core.bll.LoginAdminUserCommand] (ajp--127.0.0.1-8702-11) Running command: LoginAdminUserCommand internal: false.
2012-11-07 21:22:46,139 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (ajp--127.0.0.1-8702-1) Failed to decrypt Data must start with zero
2012-11-07 21:22:46,140 ERROR [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp--127.0.0.1-8702-1) Failed to decrypt value for property LocalAdminPassword will be used encrypted value
2012-11-07 21:22:46,162 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (ajp--127.0.0.1-8702-1) Failed to decrypt Data must start with zero
2012-11-07 21:22:46,162 ERROR [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp--127.0.0.1-8702-1) Failed to decrypt value for property LocalAdminPassword will be used encrypted value
2012-11-07 21:22:46,183 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (ajp--127.0.0.1-8702-1) Failed to decrypt Data must start with zero
2012-11-07 21:22:46,183 ERROR [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp--127.0.0.1-8702-1) Failed to decrypt value for property LocalAdminPassword will be used encrypted value
2012-11-07 21:22:46,204 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (ajp--127.0.0.1-8702-1) Failed to decrypt Data must start with zero
2012-11-07 21:22:46,205 ERROR [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp--127.0.0.1-8702-1) Failed to decrypt value for property LocalAdminPassword will be used encrypted value
2012-11-07 21:22:51,085 ERROR [org.ovirt.engine.core.ServletUtils] (ajp--127.0.0.1-8702-9) Can't read file "/usr/share/ovirt-engine/docs/DocumentationPath.csv" for request "/docs/DocumentationPath.csv", will send a 404 error response.
2012-11-07 21:23:06,285 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetVmsInfoVDSCommand] (ajp--127.0.0.1-8702-11) START, GetVmsInfoVDSCommand( storagePoolId = f90a0d1c-06ca-11e2-a05b-00151712f280, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 1130b87a-3b34-45d6-8016-d435825c68ef, vmIdList = null), log id: 4863ae13
2012-11-07 21:23:06,336 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetVmsInfoVDSCommand] (ajp--127.0.0.1-8702-11) FINISH, GetVmsInfoVDSCommand, log id: 4863ae13
2012-11-07 21:23:12,622 INFO  [org.ovirt.engine.core.bll.VdsLoadBalancer] (QuartzScheduler_Worker-84) VdsLoadBalancer: Starting load balance for cluster: Horde, algorithm: EvenlyDistribute.
2012-11-07 21:23:12,625 INFO  [org.ovirt.engine.core.bll.VdsLoadBalancer] (QuartzScheduler_Worker-84) VdsLoadBalancer: high util: 75, low util: 0, duration: 2, threashold: 80
2012-11-07 21:23:12,695 INFO  [org.ovirt.engine.core.bll.VdsLoadBalancingAlgorithm] (QuartzScheduler_Worker-84) VdsLoadBalancer: number of relevant vdss (no migration, no pending): 1.
2012-11-07 21:23:12,698 INFO  [org.ovirt.engine.core.bll.VdsCpuVdsLoadBalancingAlgorithm] (QuartzScheduler_Worker-84) VdsLoadBalancer: number of over utilized vdss found: 0.
2012-11-07 21:23:12,699 INFO  [org.ovirt.engine.core.bll.VdsCpuVdsLoadBalancingAlgorithm] (QuartzScheduler_Worker-84) VdsLoadBalancer: max cpu limit: 60, number of ready to migration vdss: 1
2012-11-07 21:23:14,936 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetVmsInfoVDSCommand] (ajp--127.0.0.1-8702-6) START, GetVmsInfoVDSCommand( storagePoolId = f90a0d1c-06ca-11e2-a05b-00151712f280, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 1130b87a-3b34-45d6-8016-d435825c68ef, vmIdList = null), log id: 42359b90
2012-11-07 21:23:14,953 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetVmsInfoVDSCommand] (ajp--127.0.0.1-8702-6) FINISH, GetVmsInfoVDSCommand, log id: 42359b90
2012-11-07 21:23:19,938 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetVmsInfoVDSCommand] (ajp--127.0.0.1-8702-10) START, GetVmsInfoVDSCommand( storagePoolId = f90a0d1c-06ca-11e2-a05b-00151712f280, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 1130b87a-3b34-45d6-8016-d435825c68ef, vmIdList = null), log id: 3ea994d9
2012-11-07 21:23:19,953 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetVmsInfoVDSCommand] (ajp--127.0.0.1-8702-10) FINISH, GetVmsInfoVDSCommand, log id: 3ea994d9
-------------- next part --------------
Thread-268::DEBUG::2012-11-07 21:23:56,869::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.f90a0d1c-06ca-11e2-a05b-00151712f280`ReqID=`deb48132-9c75-4d88-9779-1728c537b599`::Granted request
Thread-268::DEBUG::2012-11-07 21:23:56,870::task::794::TaskManager.Task::(resourceAcquired) Task=`bb36e4e5-a305-4596-92f4-e292515921df`::_resourcesAcquired: Storage.f90a0d1c-06ca-11e2-a05b-00151712f280 (shared)
Thread-268::DEBUG::2012-11-07 21:23:56,870::task::957::TaskManager.Task::(_decref) Task=`bb36e4e5-a305-4596-92f4-e292515921df`::ref 1 aborting False
Thread-268::INFO::2012-11-07 21:23:56,873::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'c331a800-839d-4d23-9059-870a7471240a', 'name': 'Azeroth', 'version': '3', 'domains': '0549ee91-4498-4130-8c23-4c173b5c0959:Active,d8b55105-c90a-465d-9803-8130da9a671e:Active,67534cca-1327-462a-b455-a04464084b31:Active,c331a800-839d-4d23-9059-870a7471240a:Active,f8984825-ff8d-43d9-91db-0d0959f8bae9:Active,c434056e-96be-4702-8beb-82a408a5c8cb:Active,f7da73c7-b5fe-48b6-93a0-0c773018c94f:Active,82e3b34a-6f89-4299-8cd8-2cc8f973a3b4:Active,e615c975-6b00-469f-8fb6-ff58ae3fdb2c:Active,5bc86532-55f7-4a91-a52c-fad261f322d5:Active,1130b87a-3b34-45d6-8016-d435825c68ef:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/f90a0d1c-06ca-11e2-a05b-00151712f280/d8b55105-c90a-465d-9803-8130da9a671e/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 160, 'lver': 2}, 'dominfo': {'0549ee91-4498-4130-8c23-4c173b5c0959': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'd8b55105-c90a-465d-9803-8130da9a671e': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'e615c975-6b00-469f-8fb6-ff58ae3fdb2c': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'c331a800-839d-4d23-9059-870a7471240a': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'f8984825-ff8d-43d9-91db-0d0959f8bae9': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'c434056e-96be-4702-8beb-82a408a5c8cb': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'f7da73c7-b5fe-48b6-93a0-0c773018c94f': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '82e3b34a-6f89-4299-8cd8-2cc8f973a3b4': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '67534cca-1327-462a-b455-a04464084b31': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '5bc86532-55f7-4a91-a52c-fad261f322d5': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '1130b87a-3b34-45d6-8016-d435825c68ef': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}}}
Thread-268::DEBUG::2012-11-07 21:23:56,873::task::1151::TaskManager.Task::(prepare) Task=`bb36e4e5-a305-4596-92f4-e292515921df`::finished: {'info': {'spm_id': 1, 'master_uuid': 'c331a800-839d-4d23-9059-870a7471240a', 'name': 'Azeroth', 'version': '3', 'domains': '0549ee91-4498-4130-8c23-4c173b5c0959:Active,d8b55105-c90a-465d-9803-8130da9a671e:Active,67534cca-1327-462a-b455-a04464084b31:Active,c331a800-839d-4d23-9059-870a7471240a:Active,f8984825-ff8d-43d9-91db-0d0959f8bae9:Active,c434056e-96be-4702-8beb-82a408a5c8cb:Active,f7da73c7-b5fe-48b6-93a0-0c773018c94f:Active,82e3b34a-6f89-4299-8cd8-2cc8f973a3b4:Active,e615c975-6b00-469f-8fb6-ff58ae3fdb2c:Active,5bc86532-55f7-4a91-a52c-fad261f322d5:Active,1130b87a-3b34-45d6-8016-d435825c68ef:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/f90a0d1c-06ca-11e2-a05b-00151712f280/d8b55105-c90a-465d-9803-8130da9a671e/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 160, 'lver': 2}, 'dominfo': {'0549ee91-4498-4130-8c23-4c173b5c0959': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'd8b55105-c90a-465d-9803-8130da9a671e': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'e615c975-6b00-469f-8fb6-ff58ae3fdb2c': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'c331a800-839d-4d23-9059-870a7471240a': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'f8984825-ff8d-43d9-91db-0d0959f8bae9': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'c434056e-96be-4702-8beb-82a408a5c8cb': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'f7da73c7-b5fe-48b6-93a0-0c773018c94f': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '82e3b34a-6f89-4299-8cd8-2cc8f973a3b4': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '67534cca-1327-462a-b455-a04464084b31': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '5bc86532-55f7-4a91-a52c-fad261f322d5': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '1130b87a-3b34-45d6-8016-d435825c68ef': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}}}
Thread-268::DEBUG::2012-11-07 21:23:56,874::task::568::TaskManager.Task::(_updateState) Task=`bb36e4e5-a305-4596-92f4-e292515921df`::moving from state preparing -> state finished
Thread-268::DEBUG::2012-11-07 21:23:56,874::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280': < ResourceRef 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280', isValid: 'True' obj: 'None'>}
Thread-268::DEBUG::2012-11-07 21:23:56,874::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-268::DEBUG::2012-11-07 21:23:56,874::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280'
Thread-268::DEBUG::2012-11-07 21:23:56,874::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280' (0 active users)
Thread-268::DEBUG::2012-11-07 21:23:56,874::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280' is free, finding out if anyone is waiting for it.
Thread-268::DEBUG::2012-11-07 21:23:56,875::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280', Clearing records.
Thread-268::DEBUG::2012-11-07 21:23:56,875::task::957::TaskManager.Task::(_decref) Task=`bb36e4e5-a305-4596-92f4-e292515921df`::ref 0 aborting False
Thread-270::DEBUG::2012-11-07 21:23:59,233::task::568::TaskManager.Task::(_updateState) Task=`635a225a-ed01-45bf-a73e-0c06050d6b24`::moving from state init -> state preparing
Thread-270::INFO::2012-11-07 21:23:59,233::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-270::INFO::2012-11-07 21:23:59,234::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'0549ee91-4498-4130-8c23-4c173b5c0959': {'delay': '0.00227499008179', 'lastCheck': '5.6', 'code': 0, 'valid': True}, 'd8b55105-c90a-465d-9803-8130da9a671e': {'delay': '0.00180912017822', 'lastCheck': '5.6', 'code': 0, 'valid': True}, 'e615c975-6b00-469f-8fb6-ff58ae3fdb2c': {'delay': '0.00380206108093', 'lastCheck': '5.5', 'code': 0, 'valid': True}, 'c331a800-839d-4d23-9059-870a7471240a': {'delay': '0.00253009796143', 'lastCheck': '5.8', 'code': 0, 'valid': True}, 'f8984825-ff8d-43d9-91db-0d0959f8bae9': {'delay': '0.0022668838501', 'lastCheck': '5.5', 'code': 0, 'valid': True}, 'c434056e-96be-4702-8beb-82a408a5c8cb': {'delay': '0.00436902046204', 'lastCheck': '5.5', 'code': 0, 'valid': True}, 'f7da73c7-b5fe-48b6-93a0-0c773018c94f': {'delay': '0.00419092178345', 'lastCheck': '5.5', 'code': 0, 'valid': True}, '82e3b34a-6f89-4299-8cd8-2cc8f973a3b4': {'delay': '0.00350999832153', 'lastCheck': '5.5', 'code': 0, 'valid': True}, '67534cca-1327-462a-b455-a04464084b31': {'delay': '0.00193190574646', 'lastCheck': '5.5', 'code': 0, 'valid': True}, '5bc86532-55f7-4a91-a52c-fad261f322d5': {'delay': '0.00200700759888', 'lastCheck': '5.4', 'code': 0, 'valid': True}, '1130b87a-3b34-45d6-8016-d435825c68ef': {'delay': '0.00202393531799', 'lastCheck': '5.5', 'code': 0, 'valid': True}}
Thread-270::DEBUG::2012-11-07 21:23:59,234::task::1151::TaskManager.Task::(prepare) Task=`635a225a-ed01-45bf-a73e-0c06050d6b24`::finished: {'0549ee91-4498-4130-8c23-4c173b5c0959': {'delay': '0.00227499008179', 'lastCheck': '5.6', 'code': 0, 'valid': True}, 'd8b55105-c90a-465d-9803-8130da9a671e': {'delay': '0.00180912017822', 'lastCheck': '5.6', 'code': 0, 'valid': True}, 'e615c975-6b00-469f-8fb6-ff58ae3fdb2c': {'delay': '0.00380206108093', 'lastCheck': '5.5', 'code': 0, 'valid': True}, 'c331a800-839d-4d23-9059-870a7471240a': {'delay': '0.00253009796143', 'lastCheck': '5.8', 'code': 0, 'valid': True}, 'f8984825-ff8d-43d9-91db-0d0959f8bae9': {'delay': '0.0022668838501', 'lastCheck': '5.5', 'code': 0, 'valid': True}, 'c434056e-96be-4702-8beb-82a408a5c8cb': {'delay': '0.00436902046204', 'lastCheck': '5.5', 'code': 0, 'valid': True}, 'f7da73c7-b5fe-48b6-93a0-0c773018c94f': {'delay': '0.00419092178345', 'lastCheck': '5.5', 'code': 0, 'valid': True}, '82e3b34a-6f89-4299-8cd8-2cc8f973a3b4': {'delay': '0.00350999832153', 'lastCheck': '5.5', 'code': 0, 'valid': True}, '67534cca-1327-462a-b455-a04464084b31': {'delay': '0.00193190574646', 'lastCheck': '5.5', 'code': 0, 'valid': True}, '5bc86532-55f7-4a91-a52c-fad261f322d5': {'delay': '0.00200700759888', 'lastCheck': '5.4', 'code': 0, 'valid': True}, '1130b87a-3b34-45d6-8016-d435825c68ef': {'delay': '0.00202393531799', 'lastCheck': '5.5', 'code': 0, 'valid': True}}
Thread-270::DEBUG::2012-11-07 21:23:59,234::task::568::TaskManager.Task::(_updateState) Task=`635a225a-ed01-45bf-a73e-0c06050d6b24`::moving from state preparing -> state finished
Thread-270::DEBUG::2012-11-07 21:23:59,234::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-270::DEBUG::2012-11-07 21:23:59,235::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-270::DEBUG::2012-11-07 21:23:59,235::task::957::TaskManager.Task::(_decref) Task=`635a225a-ed01-45bf-a73e-0c06050d6b24`::ref 0 aborting False
Thread-275::DEBUG::2012-11-07 21:24:07,059::BindingXMLRPC::161::vds::(wrapper) [3.57.111.30]
Thread-275::DEBUG::2012-11-07 21:24:07,059::task::568::TaskManager.Task::(_updateState) Task=`3c8af79a-be86-4e20-9b27-4b854c65273e`::moving from state init -> state preparing
Thread-275::INFO::2012-11-07 21:24:07,060::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='f90a0d1c-06ca-11e2-a05b-00151712f280', options=None)
Thread-275::INFO::2012-11-07 21:24:07,060::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2}}
Thread-275::DEBUG::2012-11-07 21:24:07,060::task::1151::TaskManager.Task::(prepare) Task=`3c8af79a-be86-4e20-9b27-4b854c65273e`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2}}
Thread-275::DEBUG::2012-11-07 21:24:07,060::task::568::TaskManager.Task::(_updateState) Task=`3c8af79a-be86-4e20-9b27-4b854c65273e`::moving from state preparing -> state finished
Thread-275::DEBUG::2012-11-07 21:24:07,060::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-275::DEBUG::2012-11-07 21:24:07,060::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-275::DEBUG::2012-11-07 21:24:07,061::task::957::TaskManager.Task::(_decref) Task=`3c8af79a-be86-4e20-9b27-4b854c65273e`::ref 0 aborting False
Thread-276::DEBUG::2012-11-07 21:24:07,068::BindingXMLRPC::161::vds::(wrapper) [3.57.111.30]
Thread-276::DEBUG::2012-11-07 21:24:07,068::task::568::TaskManager.Task::(_updateState) Task=`3539595a-6805-4131-9f61-7270cc5bff92`::moving from state init -> state preparing
Thread-276::INFO::2012-11-07 21:24:07,068::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='f90a0d1c-06ca-11e2-a05b-00151712f280', options=None)
Thread-276::DEBUG::2012-11-07 21:24:07,069::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.f90a0d1c-06ca-11e2-a05b-00151712f280`ReqID=`321c6776-a0c4-4131-a48d-f42e9fb4da15`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-276::DEBUG::2012-11-07 21:24:07,069::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280' for lock type 'shared'
Thread-276::DEBUG::2012-11-07 21:24:07,069::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280' is free. Now locking as 'shared' (1 active user)
Thread-276::DEBUG::2012-11-07 21:24:07,069::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.f90a0d1c-06ca-11e2-a05b-00151712f280`ReqID=`321c6776-a0c4-4131-a48d-f42e9fb4da15`::Granted request
Thread-276::DEBUG::2012-11-07 21:24:07,070::task::794::TaskManager.Task::(resourceAcquired) Task=`3539595a-6805-4131-9f61-7270cc5bff92`::_resourcesAcquired: Storage.f90a0d1c-06ca-11e2-a05b-00151712f280 (shared)
Thread-276::DEBUG::2012-11-07 21:24:07,070::task::957::TaskManager.Task::(_decref) Task=`3539595a-6805-4131-9f61-7270cc5bff92`::ref 1 aborting False
Thread-276::INFO::2012-11-07 21:24:07,073::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'c331a800-839d-4d23-9059-870a7471240a', 'name': 'Azeroth', 'version': '3', 'domains': '0549ee91-4498-4130-8c23-4c173b5c0959:Active,d8b55105-c90a-465d-9803-8130da9a671e:Active,67534cca-1327-462a-b455-a04464084b31:Active,c331a800-839d-4d23-9059-870a7471240a:Active,f8984825-ff8d-43d9-91db-0d0959f8bae9:Active,c434056e-96be-4702-8beb-82a408a5c8cb:Active,f7da73c7-b5fe-48b6-93a0-0c773018c94f:Active,82e3b34a-6f89-4299-8cd8-2cc8f973a3b4:Active,e615c975-6b00-469f-8fb6-ff58ae3fdb2c:Active,5bc86532-55f7-4a91-a52c-fad261f322d5:Active,1130b87a-3b34-45d6-8016-d435825c68ef:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/f90a0d1c-06ca-11e2-a05b-00151712f280/d8b55105-c90a-465d-9803-8130da9a671e/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 160, 'lver': 2}, 'dominfo': {'0549ee91-4498-4130-8c23-4c173b5c0959': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'd8b55105-c90a-465d-9803-8130da9a671e': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'e615c975-6b00-469f-8fb6-ff58ae3fdb2c': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'c331a800-839d-4d23-9059-870a7471240a': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'f8984825-ff8d-43d9-91db-0d0959f8bae9': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'c434056e-96be-4702-8beb-82a408a5c8cb': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'f7da73c7-b5fe-48b6-93a0-0c773018c94f': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '82e3b34a-6f89-4299-8cd8-2cc8f973a3b4': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '67534cca-1327-462a-b455-a04464084b31': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '5bc86532-55f7-4a91-a52c-fad261f322d5': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '1130b87a-3b34-45d6-8016-d435825c68ef': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}}}
Thread-276::DEBUG::2012-11-07 21:24:07,073::task::1151::TaskManager.Task::(prepare) Task=`3539595a-6805-4131-9f61-7270cc5bff92`::finished: {'info': {'spm_id': 1, 'master_uuid': 'c331a800-839d-4d23-9059-870a7471240a', 'name': 'Azeroth', 'version': '3', 'domains': '0549ee91-4498-4130-8c23-4c173b5c0959:Active,d8b55105-c90a-465d-9803-8130da9a671e:Active,67534cca-1327-462a-b455-a04464084b31:Active,c331a800-839d-4d23-9059-870a7471240a:Active,f8984825-ff8d-43d9-91db-0d0959f8bae9:Active,c434056e-96be-4702-8beb-82a408a5c8cb:Active,f7da73c7-b5fe-48b6-93a0-0c773018c94f:Active,82e3b34a-6f89-4299-8cd8-2cc8f973a3b4:Active,e615c975-6b00-469f-8fb6-ff58ae3fdb2c:Active,5bc86532-55f7-4a91-a52c-fad261f322d5:Active,1130b87a-3b34-45d6-8016-d435825c68ef:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/f90a0d1c-06ca-11e2-a05b-00151712f280/d8b55105-c90a-465d-9803-8130da9a671e/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 160, 'lver': 2}, 'dominfo': {'0549ee91-4498-4130-8c23-4c173b5c0959': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'd8b55105-c90a-465d-9803-8130da9a671e': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'e615c975-6b00-469f-8fb6-ff58ae3fdb2c': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'c331a800-839d-4d23-9059-870a7471240a': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'f8984825-ff8d-43d9-91db-0d0959f8bae9': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'c434056e-96be-4702-8beb-82a408a5c8cb': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, 'f7da73c7-b5fe-48b6-93a0-0c773018c94f': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '82e3b34a-6f89-4299-8cd8-2cc8f973a3b4': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '67534cca-1327-462a-b455-a04464084b31': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '5bc86532-55f7-4a91-a52c-fad261f322d5': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}, '1130b87a-3b34-45d6-8016-d435825c68ef': {'status': 'Active', 'diskfree': '5391642525696', 'alerts': [], 'disktotal': '5894624509952'}}}
Thread-276::DEBUG::2012-11-07 21:24:07,073::task::568::TaskManager.Task::(_updateState) Task=`3539595a-6805-4131-9f61-7270cc5bff92`::moving from state preparing -> state finished
Thread-276::DEBUG::2012-11-07 21:24:07,073::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280': < ResourceRef 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280', isValid: 'True' obj: 'None'>}
Thread-276::DEBUG::2012-11-07 21:24:07,074::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-276::DEBUG::2012-11-07 21:24:07,074::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280'
Thread-276::DEBUG::2012-11-07 21:24:07,074::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280' (0 active users)
Thread-276::DEBUG::2012-11-07 21:24:07,074::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280' is free, finding out if anyone is waiting for it.
Thread-276::DEBUG::2012-11-07 21:24:07,074::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f90a0d1c-06ca-11e2-a05b-00151712f280', Clearing records.
Thread-276::DEBUG::2012-11-07 21:24:07,074::task::957::TaskManager.Task::(_decref) Task=`3539595a-6805-4131-9f61-7270cc5bff92`::ref 0 aborting False