[Users] Constant lopping log of task activity
I'm seeing a constant loop of task issues in the vdsm.log Host is a CentOS 6.5 server otherwise setup as a db lab server. Engine is a CentOS 6.5 vm running on vmware esx host. The host has local storage only. Not sure if related, but I've been trying to attach a Win2k8-hosted NFS share for ISO's and failing. I can manually mount it just fine from the host os, but the ovirt-engine complains of privileges errors. I also had trouble getting the host recognized in ovirt dues to a messed up sudoers file. With that sorted, it added and report fine. Any troubleshooting tips? -------------------------------------------- Thread-84::DEBUG::2014-02-02 16:08:55,459::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-84::DEBUG::2014-02-02 16:08:55,459::task::579::TaskManager.Task::(_updateState) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::moving from state init -> state preparing Thread-84::INFO::2014-02-02 16:08:55,460::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-84::INFO::2014-02-02 16:08:55,460::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-84::DEBUG::2014-02-02 16:08:55,460::task::1168::TaskManager.Task::(prepare) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-84::DEBUG::2014-02-02 16:08:55,460::task::579::TaskManager.Task::(_updateState) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::moving from state preparing -> state finished Thread-84::DEBUG::2014-02-02 16:08:55,460::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-84::DEBUG::2014-02-02 16:08:55,461::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-84::DEBUG::2014-02-02 16:08:55,461::task::974::TaskManager.Task::(_decref) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::ref 0 aborting False Thread-85::DEBUG::2014-02-02 16:08:55,470::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-85::DEBUG::2014-02-02 16:08:55,470::task::579::TaskManager.Task::(_updateState) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::moving from state init -> state preparing Thread-85::INFO::2014-02-02 16:08:55,470::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`7bbb6abd-006b- 4b7b-b540-322dfdda7644`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2553' at 'getStoragePoolInfo' Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' for lock type 'shared' Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free. Now locking as 'shared' (1 active user) Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`7bbb6abd-006b- 4b7b-b540-322dfdda7644`::Granted request Thread-85::DEBUG::2014-02-02 16:08:55,472::task::811::TaskManager.Task::(resourceAcquired) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::_resourcesAcquired: Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745 (shared) Thread-85::DEBUG::2014-02-02 16:08:55,472::task::974::TaskManager.Task::(_decref) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::ref 1 aborting False Thread-85::INFO::2014-02-02 16:08:55,472::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-85::DEBUG::2014-02-02 16:08:55,473::task::1168::TaskManager.Task::(prepare) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::finished: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-85::DEBUG::2014-02-02 16:08:55,473::task::579::TaskManager.Task::(_updateState) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::moving from state preparing -> state finished Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745': < ResourceRef 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', isValid: 'True' obj: 'None'>} Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' (0 active users) Thread-85::DEBUG::2014-02-02 16:08:55,474::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free, finding out if anyone is waiting for it. Thread-85::DEBUG::2014-02-02 16:08:55,474::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', Clearing records. Thread-85::DEBUG::2014-02-02 16:08:55,474::task::974::TaskManager.Task::(_decref) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::ref 0 aborting False [slight pause] Thread-21::DEBUG::2014-02-02 16:08:58,274::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_data_images/d9f70b92-3c38-4503-ac69-b48325ead406/ dom_md/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2014-02-02 16:08:58,281::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n461 bytes (461 B) copied, 0.000121435 s, 3.8 MB/s\n'; <rc> = 0 [slight pause and repeat] Thread-89::DEBUG::2014-02-02 16:09:05,405::task::579::TaskManager.Task::(_updateState) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::moving from state init -> state preparing Thread-89::INFO::2014-02-02 16:09:05,406::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-89::INFO::2014-02-02 16:09:05,406::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'d9f70b92-3c38-4503-ac69-b48325ead406': {'delay': '0.000121435', 'lastCheck': '7.1', 'code': 0, 'valid': True, 'version': 3}} Thread-89::DEBUG::2014-02-02 16:09:05,406::task::1168::TaskManager.Task::(prepare) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::finished: {'d9f70b92-3c38-4503-ac69-b48325ead406': {'delay': '0.000121435', 'lastCheck': '7.1', 'code': 0, 'valid': True, 'version': 3}} Thread-89::DEBUG::2014-02-02 16:09:05,406::task::579::TaskManager.Task::(_updateState) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::moving from state preparing -> state finished Thread-89::DEBUG::2014-02-02 16:09:05,406::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-89::DEBUG::2014-02-02 16:09:05,407::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-89::DEBUG::2014-02-02 16:09:05,407::task::974::TaskManager.Task::(_decref) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::ref 0 aborting False Thread-91::DEBUG::2014-02-02 16:09:05,488::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-91::DEBUG::2014-02-02 16:09:05,488::task::579::TaskManager.Task::(_updateState) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::moving from state init -> state preparing Thread-91::INFO::2014-02-02 16:09:05,489::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-91::INFO::2014-02-02 16:09:05,489::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-91::DEBUG::2014-02-02 16:09:05,489::task::1168::TaskManager.Task::(prepare) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-91::DEBUG::2014-02-02 16:09:05,489::task::579::TaskManager.Task::(_updateState) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::moving from state preparing -> state finished Thread-91::DEBUG::2014-02-02 16:09:05,489::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-91::DEBUG::2014-02-02 16:09:05,489::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-91::DEBUG::2014-02-02 16:09:05,490::task::974::TaskManager.Task::(_decref) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::ref 0 aborting False Thread-92::DEBUG::2014-02-02 16:09:05,496::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-92::DEBUG::2014-02-02 16:09:05,496::task::579::TaskManager.Task::(_updateState) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::moving from state init -> state preparing Thread-92::INFO::2014-02-02 16:09:05,497::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-92::DEBUG::2014-02-02 16:09:05,497::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`128ecb64-c414- 44be-8fb4-ce8688f3a66f`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2553' at 'getStoragePoolInfo' Thread-92::DEBUG::2014-02-02 16:09:05,497::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' for lock type 'shared' Thread-92::DEBUG::2014-02-02 16:09:05,498::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free. Now locking as 'shared' (1 active user) Thread-92::DEBUG::2014-02-02 16:09:05,498::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`128ecb64-c414- 44be-8fb4-ce8688f3a66f`::Granted request Thread-92::DEBUG::2014-02-02 16:09:05,498::task::811::TaskManager.Task::(resourceAcquired) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::_resourcesAcquired: Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745 (shared) Thread-92::DEBUG::2014-02-02 16:09:05,498::task::974::TaskManager.Task::(_decref) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::ref 1 aborting False Thread-92::INFO::2014-02-02 16:09:05,499::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-92::DEBUG::2014-02-02 16:09:05,499::task::1168::TaskManager.Task::(prepare) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::finished: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-92::DEBUG::2014-02-02 16:09:05,499::task::579::TaskManager.Task::(_updateState) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::moving from state preparing -> state finished Thread-92::DEBUG::2014-02-02 16:09:05,499::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745': < ResourceRef 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', isValid: 'True' obj: 'None'>} Thread-92::DEBUG::2014-02-02 16:09:05,499::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' (0 active users) Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free, finding out if anyone is waiting for it. Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', Clearing records. Thread-92::DEBUG::2014-02-02 16:09:05,500::task::974::TaskManager.Task::(_decref) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::ref 0 aborting False [slight pause] Thread-21::DEBUG::2014-02-02 16:09:08,290::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_data_images/d9f70b92-3c38-4503-ac69-b48325ead406/ dom_md/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2014-02-02 16:09:08,296::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n461 bytes (461 B) copied, 0.000263153 s, 1.8 MB/s\n'; <rc> = 0
Hi Matt, Are the permissions on the NFS share set vdsm:kvm (36:36)? They have to be in order to be used by ovirt. Also, can you please attach the full vdsm log for the problematic host? I am probably missing something from the logs you pasted, but I cannot see any errors, and it is easier to work with the full logs. Thanks, Gadi Ickowicz ----- Original Message ----- From: "Matt Warren" <mwarren@hnw.com> To: users@ovirt.org Sent: Monday, February 3, 2014 4:41:51 AM Subject: [Users] Constant lopping log of task activity I'm seeing a constant loop of task issues in the vdsm.log Host is a CentOS 6.5 server otherwise setup as a db lab server. Engine is a CentOS 6.5 vm running on vmware esx host. The host has local storage only. Not sure if related, but I've been trying to attach a Win2k8-hosted NFS share for ISO's and failing. I can manually mount it just fine from the host os, but the ovirt-engine complains of privileges errors. I also had trouble getting the host recognized in ovirt dues to a messed up sudoers file. With that sorted, it added and report fine. Any troubleshooting tips? -------------------------------------------- Thread-84::DEBUG::2014-02-02 16:08:55,459::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-84::DEBUG::2014-02-02 16:08:55,459::task::579::TaskManager.Task::(_updateState) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::moving from state init -> state preparing Thread-84::INFO::2014-02-02 16:08:55,460::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-84::INFO::2014-02-02 16:08:55,460::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-84::DEBUG::2014-02-02 16:08:55,460::task::1168::TaskManager.Task::(prepare) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-84::DEBUG::2014-02-02 16:08:55,460::task::579::TaskManager.Task::(_updateState) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::moving from state preparing -> state finished Thread-84::DEBUG::2014-02-02 16:08:55,460::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-84::DEBUG::2014-02-02 16:08:55,461::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-84::DEBUG::2014-02-02 16:08:55,461::task::974::TaskManager.Task::(_decref) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::ref 0 aborting False Thread-85::DEBUG::2014-02-02 16:08:55,470::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-85::DEBUG::2014-02-02 16:08:55,470::task::579::TaskManager.Task::(_updateState) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::moving from state init -> state preparing Thread-85::INFO::2014-02-02 16:08:55,470::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`7bbb6abd-006b- 4b7b-b540-322dfdda7644`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2553' at 'getStoragePoolInfo' Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' for lock type 'shared' Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free. Now locking as 'shared' (1 active user) Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`7bbb6abd-006b- 4b7b-b540-322dfdda7644`::Granted request Thread-85::DEBUG::2014-02-02 16:08:55,472::task::811::TaskManager.Task::(resourceAcquired) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::_resourcesAcquired: Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745 (shared) Thread-85::DEBUG::2014-02-02 16:08:55,472::task::974::TaskManager.Task::(_decref) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::ref 1 aborting False Thread-85::INFO::2014-02-02 16:08:55,472::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-85::DEBUG::2014-02-02 16:08:55,473::task::1168::TaskManager.Task::(prepare) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::finished: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-85::DEBUG::2014-02-02 16:08:55,473::task::579::TaskManager.Task::(_updateState) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::moving from state preparing -> state finished Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745': < ResourceRef 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', isValid: 'True' obj: 'None'>} Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' (0 active users) Thread-85::DEBUG::2014-02-02 16:08:55,474::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free, finding out if anyone is waiting for it. Thread-85::DEBUG::2014-02-02 16:08:55,474::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', Clearing records. Thread-85::DEBUG::2014-02-02 16:08:55,474::task::974::TaskManager.Task::(_decref) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::ref 0 aborting False [slight pause] Thread-21::DEBUG::2014-02-02 16:08:58,274::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_data_images/d9f70b92-3c38-4503-ac69-b48325ead406/ dom_md/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2014-02-02 16:08:58,281::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n461 bytes (461 B) copied, 0.000121435 s, 3.8 MB/s\n'; <rc> = 0 [slight pause and repeat] Thread-89::DEBUG::2014-02-02 16:09:05,405::task::579::TaskManager.Task::(_updateState) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::moving from state init -> state preparing Thread-89::INFO::2014-02-02 16:09:05,406::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-89::INFO::2014-02-02 16:09:05,406::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'d9f70b92-3c38-4503-ac69-b48325ead406': {'delay': '0.000121435', 'lastCheck': '7.1', 'code': 0, 'valid': True, 'version': 3}} Thread-89::DEBUG::2014-02-02 16:09:05,406::task::1168::TaskManager.Task::(prepare) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::finished: {'d9f70b92-3c38-4503-ac69-b48325ead406': {'delay': '0.000121435', 'lastCheck': '7.1', 'code': 0, 'valid': True, 'version': 3}} Thread-89::DEBUG::2014-02-02 16:09:05,406::task::579::TaskManager.Task::(_updateState) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::moving from state preparing -> state finished Thread-89::DEBUG::2014-02-02 16:09:05,406::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-89::DEBUG::2014-02-02 16:09:05,407::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-89::DEBUG::2014-02-02 16:09:05,407::task::974::TaskManager.Task::(_decref) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::ref 0 aborting False Thread-91::DEBUG::2014-02-02 16:09:05,488::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-91::DEBUG::2014-02-02 16:09:05,488::task::579::TaskManager.Task::(_updateState) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::moving from state init -> state preparing Thread-91::INFO::2014-02-02 16:09:05,489::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-91::INFO::2014-02-02 16:09:05,489::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-91::DEBUG::2014-02-02 16:09:05,489::task::1168::TaskManager.Task::(prepare) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-91::DEBUG::2014-02-02 16:09:05,489::task::579::TaskManager.Task::(_updateState) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::moving from state preparing -> state finished Thread-91::DEBUG::2014-02-02 16:09:05,489::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-91::DEBUG::2014-02-02 16:09:05,489::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-91::DEBUG::2014-02-02 16:09:05,490::task::974::TaskManager.Task::(_decref) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::ref 0 aborting False Thread-92::DEBUG::2014-02-02 16:09:05,496::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-92::DEBUG::2014-02-02 16:09:05,496::task::579::TaskManager.Task::(_updateState) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::moving from state init -> state preparing Thread-92::INFO::2014-02-02 16:09:05,497::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-92::DEBUG::2014-02-02 16:09:05,497::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`128ecb64-c414- 44be-8fb4-ce8688f3a66f`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2553' at 'getStoragePoolInfo' Thread-92::DEBUG::2014-02-02 16:09:05,497::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' for lock type 'shared' Thread-92::DEBUG::2014-02-02 16:09:05,498::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free. Now locking as 'shared' (1 active user) Thread-92::DEBUG::2014-02-02 16:09:05,498::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`128ecb64-c414- 44be-8fb4-ce8688f3a66f`::Granted request Thread-92::DEBUG::2014-02-02 16:09:05,498::task::811::TaskManager.Task::(resourceAcquired) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::_resourcesAcquired: Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745 (shared) Thread-92::DEBUG::2014-02-02 16:09:05,498::task::974::TaskManager.Task::(_decref) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::ref 1 aborting False Thread-92::INFO::2014-02-02 16:09:05,499::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-92::DEBUG::2014-02-02 16:09:05,499::task::1168::TaskManager.Task::(prepare) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::finished: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-92::DEBUG::2014-02-02 16:09:05,499::task::579::TaskManager.Task::(_updateState) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::moving from state preparing -> state finished Thread-92::DEBUG::2014-02-02 16:09:05,499::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745': < ResourceRef 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', isValid: 'True' obj: 'None'>} Thread-92::DEBUG::2014-02-02 16:09:05,499::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' (0 active users) Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free, finding out if anyone is waiting for it. Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', Clearing records. Thread-92::DEBUG::2014-02-02 16:09:05,500::task::974::TaskManager.Task::(_decref) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::ref 0 aborting False [slight pause] Thread-21::DEBUG::2014-02-02 16:09:08,290::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_data_images/d9f70b92-3c38-4503-ac69-b48325ead406/ dom_md/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2014-02-02 16:09:08,296::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n461 bytes (461 B) copied, 0.000263153 s, 1.8 MB/s\n'; <rc> = 0 _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
I'm seeing same odd repeating "dd" operations on my domain, export and ISO domains, all mounted via NFS. Attached is the full vdsm.log. Ignore the initial failures to mount the domains, I had a typo resulting in the wrong RDMA port in vdsm.conf during those failures. On Mon, Feb 3, 2014 at 12:27 AM, Gadi Ickowicz <gickowic@redhat.com> wrote:
Hi Matt,
Are the permissions on the NFS share set vdsm:kvm (36:36)? They have to be in order to be used by ovirt.
Also, can you please attach the full vdsm log for the problematic host? I am probably missing something from the logs you pasted, but I cannot see any errors, and it is easier to work with the full logs.
Thanks, Gadi Ickowicz
----- Original Message ----- From: "Matt Warren" <mwarren@hnw.com> To: users@ovirt.org Sent: Monday, February 3, 2014 4:41:51 AM Subject: [Users] Constant lopping log of task activity
I'm seeing a constant loop of task issues in the vdsm.log
Host is a CentOS 6.5 server otherwise setup as a db lab server. Engine is a CentOS 6.5 vm running on vmware esx host.
The host has local storage only. Not sure if related, but I've been trying to attach a Win2k8-hosted NFS share for ISO's and failing. I can manually mount it just fine from the host os, but the ovirt-engine complains of privileges errors.
I also had trouble getting the host recognized in ovirt dues to a messed up sudoers file. With that sorted, it added and report fine.
Any troubleshooting tips?
--------------------------------------------
Thread-84::DEBUG::2014-02-02 16:08:55,459::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-84::DEBUG::2014-02-02 16:08:55,459::task::579::TaskManager.Task::(_updateState) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::moving from state init -> state preparing Thread-84::INFO::2014-02-02 16:08:55,460::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-84::INFO::2014-02-02 16:08:55,460::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-84::DEBUG::2014-02-02 16:08:55,460::task::1168::TaskManager.Task::(prepare) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-84::DEBUG::2014-02-02 16:08:55,460::task::579::TaskManager.Task::(_updateState) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::moving from state preparing -> state finished Thread-84::DEBUG::2014-02-02 16:08:55,460::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-84::DEBUG::2014-02-02 16:08:55,461::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-84::DEBUG::2014-02-02 16:08:55,461::task::974::TaskManager.Task::(_decref) Task=`cc9c6dac-ed6e-4cc9-a3e4-b741c5137caf`::ref 0 aborting False Thread-85::DEBUG::2014-02-02 16:08:55,470::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-85::DEBUG::2014-02-02 16:08:55,470::task::579::TaskManager.Task::(_updateState) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::moving from state init -> state preparing Thread-85::INFO::2014-02-02 16:08:55,470::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`7bbb6abd-006b- 4b7b-b540-322dfdda7644`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2553' at 'getStoragePoolInfo' Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' for lock type 'shared' Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free. Now locking as 'shared' (1 active user) Thread-85::DEBUG::2014-02-02 16:08:55,471::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`7bbb6abd-006b- 4b7b-b540-322dfdda7644`::Granted request Thread-85::DEBUG::2014-02-02 16:08:55,472::task::811::TaskManager.Task::(resourceAcquired) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::_resourcesAcquired: Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745 (shared) Thread-85::DEBUG::2014-02-02 16:08:55,472::task::974::TaskManager.Task::(_decref) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::ref 1 aborting False Thread-85::INFO::2014-02-02 16:08:55,472::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-85::DEBUG::2014-02-02 16:08:55,473::task::1168::TaskManager.Task::(prepare) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::finished: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-85::DEBUG::2014-02-02 16:08:55,473::task::579::TaskManager.Task::(_updateState) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::moving from state preparing -> state finished Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745': < ResourceRef 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', isValid: 'True' obj: 'None'>} Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' Thread-85::DEBUG::2014-02-02 16:08:55,473::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' (0 active users) Thread-85::DEBUG::2014-02-02 16:08:55,474::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free, finding out if anyone is waiting for it. Thread-85::DEBUG::2014-02-02 16:08:55,474::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', Clearing records. Thread-85::DEBUG::2014-02-02 16:08:55,474::task::974::TaskManager.Task::(_decref) Task=`59aa1ec2-64b9-4c6d-bdb8-66154f73915d`::ref 0 aborting False
[slight pause]
Thread-21::DEBUG::2014-02-02 16:08:58,274::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_data_images/d9f70b92-3c38-4503-ac69-b48325ead406/ dom_md/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2014-02-02 16:08:58,281::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n461 bytes (461 B) copied, 0.000121435 s, 3.8 MB/s\n'; <rc> = 0
[slight pause and repeat]
Thread-89::DEBUG::2014-02-02 16:09:05,405::task::579::TaskManager.Task::(_updateState) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::moving from state init -> state preparing Thread-89::INFO::2014-02-02 16:09:05,406::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-89::INFO::2014-02-02 16:09:05,406::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'d9f70b92-3c38-4503-ac69-b48325ead406': {'delay': '0.000121435', 'lastCheck': '7.1', 'code': 0, 'valid': True, 'version': 3}} Thread-89::DEBUG::2014-02-02 16:09:05,406::task::1168::TaskManager.Task::(prepare) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::finished: {'d9f70b92-3c38-4503-ac69-b48325ead406': {'delay': '0.000121435', 'lastCheck': '7.1', 'code': 0, 'valid': True, 'version': 3}} Thread-89::DEBUG::2014-02-02 16:09:05,406::task::579::TaskManager.Task::(_updateState) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::moving from state preparing -> state finished Thread-89::DEBUG::2014-02-02 16:09:05,406::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-89::DEBUG::2014-02-02 16:09:05,407::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-89::DEBUG::2014-02-02 16:09:05,407::task::974::TaskManager.Task::(_decref) Task=`86ddb0cb-43c9-4e2f-b779-9ba2ccfaae99`::ref 0 aborting False Thread-91::DEBUG::2014-02-02 16:09:05,488::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-91::DEBUG::2014-02-02 16:09:05,488::task::579::TaskManager.Task::(_updateState) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::moving from state init -> state preparing Thread-91::INFO::2014-02-02 16:09:05,489::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-91::INFO::2014-02-02 16:09:05,489::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-91::DEBUG::2014-02-02 16:09:05,489::task::1168::TaskManager.Task::(prepare) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}} Thread-91::DEBUG::2014-02-02 16:09:05,489::task::579::TaskManager.Task::(_updateState) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::moving from state preparing -> state finished Thread-91::DEBUG::2014-02-02 16:09:05,489::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-91::DEBUG::2014-02-02 16:09:05,489::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-91::DEBUG::2014-02-02 16:09:05,490::task::974::TaskManager.Task::(_decref) Task=`91b6affb-d61c-491e-ba08-6db785402efe`::ref 0 aborting False Thread-92::DEBUG::2014-02-02 16:09:05,496::BindingXMLRPC::167::vds::(wrapper) client [10.1.9.11] Thread-92::DEBUG::2014-02-02 16:09:05,496::task::579::TaskManager.Task::(_updateState) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::moving from state init -> state preparing Thread-92::INFO::2014-02-02 16:09:05,497::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='b780d909-b6a0-4a38-82e2-3d7fd3a2b745', options=None) Thread-92::DEBUG::2014-02-02 16:09:05,497::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`128ecb64-c414- 44be-8fb4-ce8688f3a66f`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2553' at 'getStoragePoolInfo' Thread-92::DEBUG::2014-02-02 16:09:05,497::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' for lock type 'shared' Thread-92::DEBUG::2014-02-02 16:09:05,498::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free. Now locking as 'shared' (1 active user) Thread-92::DEBUG::2014-02-02 16:09:05,498::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745`ReqID=`128ecb64-c414- 44be-8fb4-ce8688f3a66f`::Granted request Thread-92::DEBUG::2014-02-02 16:09:05,498::task::811::TaskManager.Task::(resourceAcquired) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::_resourcesAcquired: Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745 (shared) Thread-92::DEBUG::2014-02-02 16:09:05,498::task::974::TaskManager.Task::(_decref) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::ref 1 aborting False Thread-92::INFO::2014-02-02 16:09:05,499::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-92::DEBUG::2014-02-02 16:09:05,499::task::1168::TaskManager.Task::(prepare) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::finished: {'info': {'spm_id': 1, 'master_uuid': 'd9f70b92-3c38-4503-ac69-b48325ead406', 'name': 'hnwdb05-Local', 'version': '3', 'domains': 'd9f70b92-3c38-4503-ac69-b48325ead406:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 1}, 'dominfo': {'d9f70b92-3c38-4503-ac69-b48325ead406': {'status': 'Active', 'diskfree': '409127440384', 'alerts': [], 'version': 3, 'disktotal': '945068838912'}}} Thread-92::DEBUG::2014-02-02 16:09:05,499::task::579::TaskManager.Task::(_updateState) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::moving from state preparing -> state finished Thread-92::DEBUG::2014-02-02 16:09:05,499::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745': < ResourceRef 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', isValid: 'True' obj: 'None'>} Thread-92::DEBUG::2014-02-02 16:09:05,499::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' (0 active users) Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745' is free, finding out if anyone is waiting for it. Thread-92::DEBUG::2014-02-02 16:09:05,500::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b780d909-b6a0-4a38-82e2-3d7fd3a2b745', Clearing records. Thread-92::DEBUG::2014-02-02 16:09:05,500::task::974::TaskManager.Task::(_decref) Task=`538b5b93-8e03-4a1c-a1c7-43769926d532`::ref 0 aborting False
[slight pause]
Thread-21::DEBUG::2014-02-02 16:09:08,290::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_data_images/d9f70b92-3c38-4503-ac69-b48325ead406/ dom_md/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2014-02-02 16:09:08,296::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n461 bytes (461 B) copied, 0.000263153 s, 1.8 MB/s\n'; <rc> = 0
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
participants (3)
-
Gadi Ickowicz -
Matt Warren -
Trey Dockendorf