[Users] Constant lopping log of task activity
Trey Dockendorf
treydock at gmail.com
Fri Feb 7 01:12:29 UTC 2014
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 at 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 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
> _______________________________________________
> Users mailing list
> Users at ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
-------------- next part --------------
A non-text attachment was scrubbed...
Name: vm02_vdsm.log
Type: application/octet-stream
Size: 315130 bytes
Desc: not available
URL: <http://lists.ovirt.org/pipermail/users/attachments/20140206/c75a0f0e/attachment-0001.obj>
More information about the Users
mailing list