Re: [Users] Constant lopping log of task activity

2014-02-02 Thread Gadi Ickowicz
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" 
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': '', &#x

[Users] Constant lopping log of task activity

2014-02-02 Thread Matt Warren
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-4