[Users] Constant lopping log of task activity
Gadi Ickowicz
gickowic at redhat.com
Mon Feb 3 01:27:57 EST 2014
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 at hnw.com>
To: users at 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 at ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
More information about the Users
mailing list