Re: [Users] Constant lopping log of task activity

Monday, 3 February 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(a)hnw.com&gt;
To: users(a)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(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

Re: [Users] Constant lopping log of task activity