[Users] creating and running a vm fails
Moran Goldboim
mgoldboi at redhat.com
Thu Mar 29 08:10:37 UTC 2012
Rene, this log doesn't contain the run vm command either it's not
getting there or log snip doesn't contain it. the verb is: call vmCreate
Trail it when you are trying to run the vm on that host.
are you still getting same logs on the engine?
Moran.
On 03/29/2012 09:53 AM, Rene Rosenberger wrote:
> Hi,
>
> this is what vdms.log says on the host i want to run the vm:
>
> Thread-55012::DEBUG::2012-03-29 09:51:02,514::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' for lock type 'shared'
> Thread-55012::DEBUG::2012-03-29 09:51:02,516::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' is free. Now locking as 'shared' (1 active user)
> Thread-55012::DEBUG::2012-03-29 09:51:02,518::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.13080edc-77ea-11e1-b6a4-525400c49d2a`ReqID=`2c8c0dd9-feef-431f-a246-d8a6ae2a6fe1`::Granted request
> Thread-55012::DEBUG::2012-03-29 09:51:02,521::task::817::TaskManager.Task::(resourceAcquired) Task=`2f85e9fd-3ae4-4ecc-9b42-53543228fcd4`::_resourcesAcquired: Storage.13080edc-77ea-11e1-b6a4-525400c49d2a (shared)
> Thread-55012::DEBUG::2012-03-29 09:51:02,523::task::978::TaskManager.Task::(_decref) Task=`2f85e9fd-3ae4-4ecc-9b42-53543228fcd4`::ref 1 aborting False
> Thread-55012::INFO::2012-03-29 09:51:02,529::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '8ed25a57-f53a-4cf0-bb92-781f3ce36a48', 'name': 'Default', 'version': '2', 'domains': u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0:Active,bb13e29f-0e5a-4f79-8bf2-f235a0dbd515:Active,8ed25a57-f53a-4cf0-bb92-781f3ce36a48:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/93e2079e-ef3b-452f-af71-5b3e7eb32ba0/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 1}, 'dominfo': {u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'status': u'Active', 'diskfree': '235838373888', 'alerts': [], 'disktotal': '257822818304'}, u'8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'status': u'Active', 'diskfree': '2141846503424', 'alerts': [], 'disktotal': '2147080994816'}, u'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'status': u'Active', 'diskfree': '5267626524672', 'alerts': [], 'disktotal': '5902284816384'}}}
> Thread-55012::DEBUG::2012-03-29 09:51:02,531::task::1172::TaskManager.Task::(prepare) Task=`2f85e9fd-3ae4-4ecc-9b42-53543228fcd4`::finished: {'info': {'spm_id': 1, 'master_uuid': '8ed25a57-f53a-4cf0-bb92-781f3ce36a48', 'name': 'Default', 'version': '2', 'domains': u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0:Active,bb13e29f-0e5a-4f79-8bf2-f235a0dbd515:Active,8ed25a57-f53a-4cf0-bb92-781f3ce36a48:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/93e2079e-ef3b-452f-af71-5b3e7eb32ba0/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 1}, 'dominfo': {u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'status': u'Active', 'diskfree': '235838373888', 'alerts': [], 'disktotal': '257822818304'}, u'8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'status': u'Active', 'diskfree': '2141846503424', 'alerts': [], 'disktotal': '2147080994816'}, u'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'status': u'Active', 'diskfree': '5267626524672', 'alerts': [], 'disktotal': '5902284816384'}}}
> Thread-55012::DEBUG::2012-03-29 09:51:02,533::task::588::TaskManager.Task::(_updateState) Task=`2f85e9fd-3ae4-4ecc-9b42-53543228fcd4`::moving from state preparing -> state finished
> Thread-55012::DEBUG::2012-03-29 09:51:02,535::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a':< ResourceRef 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a', isValid: 'True' obj: 'None'>}
> Thread-55012::DEBUG::2012-03-29 09:51:02,536::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-55012::DEBUG::2012-03-29 09:51:02,539::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a'
> Thread-55012::DEBUG::2012-03-29 09:51:02,541::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' (0 active users)
> Thread-55012::DEBUG::2012-03-29 09:51:02,542::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' is free, finding out if anyone is waiting for it.
> Thread-55012::DEBUG::2012-03-29 09:51:02,544::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a', Clearing records.
> Thread-55012::DEBUG::2012-03-29 09:51:02,546::task::978::TaskManager.Task::(_decref) Task=`2f85e9fd-3ae4-4ecc-9b42-53543228fcd4`::ref 0 aborting False
> Dummy-93::DEBUG::2012-03-29 09:51:03,920::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:04,372::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.187424 s, 5.5 MB/s\n';<rc> = 0
> Dummy-93::DEBUG::2012-03-29 09:51:06,420::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:06,895::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.209075 s, 4.9 MB/s\n';<rc> = 0
> Dummy-93::DEBUG::2012-03-29 09:51:08,953::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:09,403::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.187018 s, 5.5 MB/s\n';<rc> = 0
> Thread-55016::DEBUG::2012-03-29 09:51:10,110::task::588::TaskManager.Task::(_updateState) Task=`83108b7c-5bbd-4aad-bfb2-da6ebf87882f`::moving from state init -> state preparing
> Thread-55016::INFO::2012-03-29 09:51:10,113::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-55016::INFO::2012-03-29 09:51:10,116::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'delay': '0.00430202484131', 'lastCheck': 1333007465.9121721, 'code': 0, 'valid': True}, '8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'delay': '0.00339603424072', 'lastCheck': 1333007467.4905169, 'code': 0, 'valid': True}, 'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'delay': '0.00301098823547', 'lastCheck': 1333007468.0463679, 'code': 0, 'valid': True}}
> Thread-55016::DEBUG::2012-03-29 09:51:10,117::task::1172::TaskManager.Task::(prepare) Task=`83108b7c-5bbd-4aad-bfb2-da6ebf87882f`::finished: {'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'delay': '0.00430202484131', 'lastCheck': 1333007465.9121721, 'code': 0, 'valid': True}, '8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'delay': '0.00339603424072', 'lastCheck': 1333007467.4905169, 'code': 0, 'valid': True}, 'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'delay': '0.00301098823547', 'lastCheck': 1333007468.0463679, 'code': 0, 'valid': True}}
> Thread-55016::DEBUG::2012-03-29 09:51:10,120::task::588::TaskManager.Task::(_updateState) Task=`83108b7c-5bbd-4aad-bfb2-da6ebf87882f`::moving from state preparing -> state finished
> Thread-55016::DEBUG::2012-03-29 09:51:10,121::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-55016::DEBUG::2012-03-29 09:51:10,123::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-55016::DEBUG::2012-03-29 09:51:10,125::task::978::TaskManager.Task::(_decref) Task=`83108b7c-5bbd-4aad-bfb2-da6ebf87882f`::ref 0 aborting False
> Dummy-93::DEBUG::2012-03-29 09:51:11,451::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:11,921::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.181907 s, 5.6 MB/s\n';<rc> = 0
> Thread-55019::DEBUG::2012-03-29 09:51:12,583::BindingXMLRPC::167::vds::(wrapper) [192.168.100.10]
> Thread-55019::DEBUG::2012-03-29 09:51:12,587::task::588::TaskManager.Task::(_updateState) Task=`ec333fa9-0878-479f-a781-b91c236c2e50`::moving from state init -> state preparing
> Thread-55019::INFO::2012-03-29 09:51:12,589::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='13080edc-77ea-11e1-b6a4-525400c49d2a', options=None)
> Thread-55019::INFO::2012-03-29 09:51:12,592::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
> Thread-55019::DEBUG::2012-03-29 09:51:12,593::task::1172::TaskManager.Task::(prepare) Task=`ec333fa9-0878-479f-a781-b91c236c2e50`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
> Thread-55019::DEBUG::2012-03-29 09:51:12,595::task::588::TaskManager.Task::(_updateState) Task=`ec333fa9-0878-479f-a781-b91c236c2e50`::moving from state preparing -> state finished
> Thread-55019::DEBUG::2012-03-29 09:51:12,597::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-55019::DEBUG::2012-03-29 09:51:12,598::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-55019::DEBUG::2012-03-29 09:51:12,600::task::978::TaskManager.Task::(_decref) Task=`ec333fa9-0878-479f-a781-b91c236c2e50`::ref 0 aborting False
> Thread-55020::DEBUG::2012-03-29 09:51:12,610::BindingXMLRPC::167::vds::(wrapper) [192.168.100.10]
> Thread-55020::DEBUG::2012-03-29 09:51:12,613::task::588::TaskManager.Task::(_updateState) Task=`67cf8ade-753b-4a9f-9f06-9991412582b8`::moving from state init -> state preparing
> Thread-55020::INFO::2012-03-29 09:51:12,615::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='13080edc-77ea-11e1-b6a4-525400c49d2a', options=None)
> Thread-55020::DEBUG::2012-03-29 09:51:12,619::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.13080edc-77ea-11e1-b6a4-525400c49d2a`ReqID=`4a7a5857-9d8c-4f4c-8177-2386473f98d7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2037' at 'getStoragePoolInfo'
> Thread-55020::DEBUG::2012-03-29 09:51:12,620::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' for lock type 'shared'
> Thread-55020::DEBUG::2012-03-29 09:51:12,622::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' is free. Now locking as 'shared' (1 active user)
> Thread-55020::DEBUG::2012-03-29 09:51:12,624::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.13080edc-77ea-11e1-b6a4-525400c49d2a`ReqID=`4a7a5857-9d8c-4f4c-8177-2386473f98d7`::Granted request
> Thread-55020::DEBUG::2012-03-29 09:51:12,632::task::817::TaskManager.Task::(resourceAcquired) Task=`67cf8ade-753b-4a9f-9f06-9991412582b8`::_resourcesAcquired: Storage.13080edc-77ea-11e1-b6a4-525400c49d2a (shared)
> Thread-55020::DEBUG::2012-03-29 09:51:12,634::task::978::TaskManager.Task::(_decref) Task=`67cf8ade-753b-4a9f-9f06-9991412582b8`::ref 1 aborting False
> Thread-55020::INFO::2012-03-29 09:51:12,640::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '8ed25a57-f53a-4cf0-bb92-781f3ce36a48', 'name': 'Default', 'version': '2', 'domains': u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0:Active,bb13e29f-0e5a-4f79-8bf2-f235a0dbd515:Active,8ed25a57-f53a-4cf0-bb92-781f3ce36a48:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/93e2079e-ef3b-452f-af71-5b3e7eb32ba0/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 1}, 'dominfo': {u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'status': u'Active', 'diskfree': '235838373888', 'alerts': [], 'disktotal': '257822818304'}, u'8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'status': u'Active', 'diskfree': '2141846503424', 'alerts': [], 'disktotal': '2147080994816'}, u'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'status': u'Active', 'diskfree': '5267626524672', 'alerts': [], 'disktotal': '5902284816384'}}}
> Thread-55020::DEBUG::2012-03-29 09:51:12,642::task::1172::TaskManager.Task::(prepare) Task=`67cf8ade-753b-4a9f-9f06-9991412582b8`::finished: {'info': {'spm_id': 1, 'master_uuid': '8ed25a57-f53a-4cf0-bb92-781f3ce36a48', 'name': 'Default', 'version': '2', 'domains': u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0:Active,bb13e29f-0e5a-4f79-8bf2-f235a0dbd515:Active,8ed25a57-f53a-4cf0-bb92-781f3ce36a48:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/93e2079e-ef3b-452f-af71-5b3e7eb32ba0/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 1}, 'dominfo': {u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'status': u'Active', 'diskfree': '235838373888', 'alerts': [], 'disktotal': '257822818304'}, u'8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'status': u'Active', 'diskfree': '2141846503424', 'alerts': [], 'disktotal': '2147080994816'}, u'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'status': u'Active', 'diskfree': '5267626524672', 'alerts': [], 'disktotal': '5902284816384'}}}
> Thread-55020::DEBUG::2012-03-29 09:51:12,644::task::588::TaskManager.Task::(_updateState) Task=`67cf8ade-753b-4a9f-9f06-9991412582b8`::moving from state preparing -> state finished
> Thread-55020::DEBUG::2012-03-29 09:51:12,646::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a':< ResourceRef 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a', isValid: 'True' obj: 'None'>}
> Thread-55020::DEBUG::2012-03-29 09:51:12,648::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-55020::DEBUG::2012-03-29 09:51:12,650::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a'
> Thread-55020::DEBUG::2012-03-29 09:51:12,652::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' (0 active users)
> Thread-55020::DEBUG::2012-03-29 09:51:12,653::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' is free, finding out if anyone is waiting for it.
> Thread-55020::DEBUG::2012-03-29 09:51:12,655::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a', Clearing records.
> Thread-55020::DEBUG::2012-03-29 09:51:12,657::task::978::TaskManager.Task::(_decref) Task=`67cf8ade-753b-4a9f-9f06-9991412582b8`::ref 0 aborting False
> Dummy-93::DEBUG::2012-03-29 09:51:13,970::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:14,422::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.194021 s, 5.3 MB/s\n';<rc> = 0
> Dummy-93::DEBUG::2012-03-29 09:51:16,469::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:16,962::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.187019 s, 5.5 MB/s\n';<rc> = 0
> Dummy-93::DEBUG::2012-03-29 09:51:19,009::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:19,451::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.18092 s, 5.7 MB/s\n';<rc> = 0
> Thread-55024::DEBUG::2012-03-29 09:51:20,246::task::588::TaskManager.Task::(_updateState) Task=`73e39a42-ee05-459f-9d83-b1329d987665`::moving from state init -> state preparing
> Thread-55024::INFO::2012-03-29 09:51:20,249::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-55024::INFO::2012-03-29 09:51:20,252::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'delay': '0.00443387031555', 'lastCheck': 1333007475.9278209, 'code': 0, 'valid': True}, '8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'delay': '0.00118398666382', 'lastCheck': 1333007477.502805, 'code': 0, 'valid': True}, 'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'delay': '0.00273203849792', 'lastCheck': 1333007478.0588491, 'code': 0, 'valid': True}}
> Thread-55024::DEBUG::2012-03-29 09:51:20,253::task::1172::TaskManager.Task::(prepare) Task=`73e39a42-ee05-459f-9d83-b1329d987665`::finished: {'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'delay': '0.00443387031555', 'lastCheck': 1333007475.9278209, 'code': 0, 'valid': True}, '8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'delay': '0.00118398666382', 'lastCheck': 1333007477.502805, 'code': 0, 'valid': True}, 'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'delay': '0.00273203849792', 'lastCheck': 1333007478.0588491, 'code': 0, 'valid': True}}
> Thread-55024::DEBUG::2012-03-29 09:51:20,256::task::588::TaskManager.Task::(_updateState) Task=`73e39a42-ee05-459f-9d83-b1329d987665`::moving from state preparing -> state finished
> Thread-55024::DEBUG::2012-03-29 09:51:20,257::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-55024::DEBUG::2012-03-29 09:51:20,259::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-55024::DEBUG::2012-03-29 09:51:20,261::task::978::TaskManager.Task::(_decref) Task=`73e39a42-ee05-459f-9d83-b1329d987665`::ref 0 aborting False
> Dummy-93::DEBUG::2012-03-29 09:51:21,502::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:21,950::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.179002 s, 5.7 MB/s\n';<rc> = 0
> Thread-55027::DEBUG::2012-03-29 09:51:22,700::BindingXMLRPC::167::vds::(wrapper) [192.168.100.10]
> Thread-55027::DEBUG::2012-03-29 09:51:22,704::task::588::TaskManager.Task::(_updateState) Task=`f6e28785-c757-4b89-87ce-c92286bc1bc2`::moving from state init -> state preparing
> Thread-55027::INFO::2012-03-29 09:51:22,706::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='13080edc-77ea-11e1-b6a4-525400c49d2a', options=None)
> Thread-55027::INFO::2012-03-29 09:51:22,709::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
> Thread-55027::DEBUG::2012-03-29 09:51:22,711::task::1172::TaskManager.Task::(prepare) Task=`f6e28785-c757-4b89-87ce-c92286bc1bc2`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
> Thread-55027::DEBUG::2012-03-29 09:51:22,712::task::588::TaskManager.Task::(_updateState) Task=`f6e28785-c757-4b89-87ce-c92286bc1bc2`::moving from state preparing -> state finished
> Thread-55027::DEBUG::2012-03-29 09:51:22,714::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-55027::DEBUG::2012-03-29 09:51:22,716::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-55027::DEBUG::2012-03-29 09:51:22,717::task::978::TaskManager.Task::(_decref) Task=`f6e28785-c757-4b89-87ce-c92286bc1bc2`::ref 0 aborting False
> Thread-55028::DEBUG::2012-03-29 09:51:22,727::BindingXMLRPC::167::vds::(wrapper) [192.168.100.10]
> Thread-55028::DEBUG::2012-03-29 09:51:22,730::task::588::TaskManager.Task::(_updateState) Task=`22afe74b-e4a8-421b-84b3-6c9295dce788`::moving from state init -> state preparing
> Thread-55028::INFO::2012-03-29 09:51:22,732::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='13080edc-77ea-11e1-b6a4-525400c49d2a', options=None)
> Thread-55028::DEBUG::2012-03-29 09:51:22,735::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.13080edc-77ea-11e1-b6a4-525400c49d2a`ReqID=`8e695a8f-e8b2-4ab6-a464-4447e37f0fe5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2037' at 'getStoragePoolInfo'
> Thread-55028::DEBUG::2012-03-29 09:51:22,737::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' for lock type 'shared'
> Thread-55028::DEBUG::2012-03-29 09:51:22,739::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' is free. Now locking as 'shared' (1 active user)
> Thread-55028::DEBUG::2012-03-29 09:51:22,741::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.13080edc-77ea-11e1-b6a4-525400c49d2a`ReqID=`8e695a8f-e8b2-4ab6-a464-4447e37f0fe5`::Granted request
> Thread-55028::DEBUG::2012-03-29 09:51:22,743::task::817::TaskManager.Task::(resourceAcquired) Task=`22afe74b-e4a8-421b-84b3-6c9295dce788`::_resourcesAcquired: Storage.13080edc-77ea-11e1-b6a4-525400c49d2a (shared)
> Thread-55028::DEBUG::2012-03-29 09:51:22,745::task::978::TaskManager.Task::(_decref) Task=`22afe74b-e4a8-421b-84b3-6c9295dce788`::ref 1 aborting False
> Thread-55028::INFO::2012-03-29 09:51:22,752::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '8ed25a57-f53a-4cf0-bb92-781f3ce36a48', 'name': 'Default', 'version': '2', 'domains': u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0:Active,bb13e29f-0e5a-4f79-8bf2-f235a0dbd515:Active,8ed25a57-f53a-4cf0-bb92-781f3ce36a48:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/93e2079e-ef3b-452f-af71-5b3e7eb32ba0/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 1}, 'dominfo': {u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'status': u'Active', 'diskfree': '235838373888', 'alerts': [], 'disktotal': '257822818304'}, u'8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'status': u'Active', 'diskfree': '2141846503424', 'alerts': [], 'disktotal': '2147080994816'}, u'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'status': u'Active', 'diskfree': '5267626524672', 'alerts': [], 'disktotal': '5902284816384'}}}
> Thread-55028::DEBUG::2012-03-29 09:51:22,753::task::1172::TaskManager.Task::(prepare) Task=`22afe74b-e4a8-421b-84b3-6c9295dce788`::finished: {'info': {'spm_id': 1, 'master_uuid': '8ed25a57-f53a-4cf0-bb92-781f3ce36a48', 'name': 'Default', 'version': '2', 'domains': u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0:Active,bb13e29f-0e5a-4f79-8bf2-f235a0dbd515:Active,8ed25a57-f53a-4cf0-bb92-781f3ce36a48:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/93e2079e-ef3b-452f-af71-5b3e7eb32ba0/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 1}, 'dominfo': {u'93e2079e-ef3b-452f-af71-5b3e7eb32ba0': {'status': u'Active', 'diskfree': '235838373888', 'alerts': [], 'disktotal': '257822818304'}, u'8ed25a57-f53a-4cf0-bb92-781f3ce36a48': {'status': u'Active', 'diskfree': '2141846503424', 'alerts': [], 'disktotal': '2147080994816'}, u'bb13e29f-0e5a-4f79-8bf2-f235a0dbd515': {'status': u'Active', 'diskfree': '5267626524672', 'alerts': [], 'disktotal': '5902284816384'}}}
> Thread-55028::DEBUG::2012-03-29 09:51:22,756::task::588::TaskManager.Task::(_updateState) Task=`22afe74b-e4a8-421b-84b3-6c9295dce788`::moving from state preparing -> state finished
> Thread-55028::DEBUG::2012-03-29 09:51:22,757::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a':< ResourceRef 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a', isValid: 'True' obj: 'None'>}
> Thread-55028::DEBUG::2012-03-29 09:51:22,759::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-55028::DEBUG::2012-03-29 09:51:22,761::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a'
> Thread-55028::DEBUG::2012-03-29 09:51:22,763::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' (0 active users)
> Thread-55028::DEBUG::2012-03-29 09:51:22,764::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a' is free, finding out if anyone is waiting for it.
> Thread-55028::DEBUG::2012-03-29 09:51:22,766::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.13080edc-77ea-11e1-b6a4-525400c49d2a', Clearing records.
> Thread-55028::DEBUG::2012-03-29 09:51:22,768::task::978::TaskManager.Task::(_decref) Task=`22afe74b-e4a8-421b-84b3-6c9295dce788`::ref 0 aborting False
> Dummy-93::DEBUG::2012-03-29 09:51:23,999::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
> Dummy-93::DEBUG::2012-03-29 09:51:24,459::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS:<err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.178758 s, 5.7 MB/s\n';<rc> = 0
> Dummy-93::DEBUG::2012-03-29 09:51:26,507::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/13080edc-77ea-11e1-b6a4-525400c49d2a/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>
> Regards, rene
>
>
> -----Ursprüngliche Nachricht-----
> Von: users-bounces at ovirt.org [mailto:users-bounces at ovirt.org] Im Auftrag von Rene Rosenberger
> Gesendet: Donnerstag, 29. März 2012 09:32
> An: Moran Goldboim
> Cc: users at oVirt.org
> Betreff: Re: [Users] creating and running a vm fails
>
> Hi,
>
> i have just retried to start the vm what fails again. Looking in /var/log/vsdm/vdsm.log shows last entry on 27.03.2012.
>
> MainThread::INFO::2012-03-27 10:58:13,525::vdsm::70::vds::(run) I am the actual vdsm 4.9-0
> MainThread::DEBUG::2012-03-27 10:58:15,120::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
> MainThread::DEBUG::2012-03-27 10:58:15,122::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
> MainThread::DEBUG::2012-03-27 10:58:15,393::multipath::109::Storage.Multipath::(isEnabled) multipath Defaulting to False
> MainThread::DEBUG::2012-03-27 10:58:15,398::multipath::123::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /bin/cp /tmp/tmpkart5V /etc/multipath.conf' (cwd None)
> MainThread::DEBUG::2012-03-27 10:58:15,505::multipath::123::Storage.Misc.excCmd::(setupMultipath) SUCCESS:<err> = '';<rc> = 0
> MainThread::DEBUG::2012-03-27 10:58:15,508::multipath::131::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /sbin/multipath -F' (cwd None)
> MainThread::DEBUG::2012-03-27 10:58:15,591::multipath::131::Storage.Misc.excCmd::(setupMultipath) FAILED:<err> = '';<rc> = 1
> MainThread::DEBUG::2012-03-27 10:58:15,600::multipath::134::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /sbin/service multipathd restart' (cwd None)
> MainThread::DEBUG::2012-03-27 10:58:16,123::multipath::134::Storage.Misc.excCmd::(setupMultipath) SUCCESS:<err> = '';<rc> = 0
> MainThread::DEBUG::2012-03-27 10:58:16,130::hsm::334::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
> MainThread::DEBUG::2012-03-27 10:58:16,424::hsm::334::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS:<err> = '';<rc> = 0
> MainThread::DEBUG::2012-03-27 10:58:16,428::lvm::316::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
> MainThread::DEBUG::2012-03-27 10:58:16,434::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)
> MainThread::DEBUG::2012-03-27 10:58:16,708::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS:<err> = '';<rc> = 0
> MainThread::DEBUG::2012-03-27 10:58:16,711::lvm::339::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
> MainThread::DEBUG::2012-03-27 10:58:16,712::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
> MainThread::DEBUG::2012-03-27 10:58:16,713::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free' (cwd None)
> MainThread::DEBUG::2012-03-27 10:58:16,906::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS:<err> = ' No volume groups found\n';<rc> = 0
> MainThread::DEBUG::2012-03-27 10:58:16,909::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
> MainThread::DEBUG::2012-03-27 10:58:16,910::lvm::284::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None)
> MainThread::DEBUG::2012-03-27 10:58:17,119::lvm::284::Storage.Misc.excCmd::(cmd) SUCCESS:<err> = ' No volume groups found\n';<rc> = 0
> Thread-12::DEBUG::2012-03-27 10:58:17,123::misc::1022::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
> MainThread::INFO::2012-03-27 10:58:17,130::dispatcher::118::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
> Thread-12::DEBUG::2012-03-27 10:58:17,132::misc::1024::SamplingMethod::(__call__) Got in to sampling method
> Thread-12::DEBUG::2012-03-27 10:58:17,141::misc::1022::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
> Thread-12::DEBUG::2012-03-27 10:58:17,142::misc::1024::SamplingMethod::(__call__) Got in to sampling method
> Thread-12::DEBUG::2012-03-27 10:58:17,147::iscsiadm::48::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
> MainThread::ERROR::2012-03-27 10:58:17,164::netinfo::126::root::(speed) cannot read eth0 speed Traceback (most recent call last):
> File "/usr/lib/python2.6/site-packages/vdsm/netinfo.py", line 113, in speed
> s = int(file('/sys/class/net/%s/speed' % dev).read())
> IOError: [Errno 22] Invalid argument
> MainThread::DEBUG::2012-03-27 10:58:17,198::utils::602::Storage.Misc.excCmd::(execCmd) '/usr/bin/pgrep -xf ksmd' (cwd None)
> Thread-12::DEBUG::2012-03-27 10:58:17,297::iscsiadm::48::Storage.Misc.excCmd::(_runCmd) FAILED:<err> = 'iscsiadm: No session found.\n';<rc> = 21
> Thread-12::DEBUG::2012-03-27 10:58:17,304::misc::1032::SamplingMethod::(__call__) Returning last result
> Thread-12::DEBUG::2012-03-27 10:58:17,306::supervdsm::83::SuperVdsmProxy::(_killSupervdsm) Could not kill old Super Vdsm [Errno 2] No such file or directory: '/var/run/vdsm/svdsm.pid'
> Thread-12::DEBUG::2012-03-27 10:58:17,308::supervdsm::71::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
> Thread-12::DEBUG::2012-03-27 10:58:17,309::supervdsm::74::Storage.Misc.excCmd::(_launchSupervdsm) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.pyc f90ef831-7bff-4eb4-a9b5-890538959b22 2858' (cwd None)
> MainThread::DEBUG::2012-03-27 10:58:17,390::utils::602::Storage.Misc.excCmd::(execCmd) SUCCESS:<err> = '';<rc> = 0
> MainThread::INFO::2012-03-27 10:58:17,438::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
> VM Channels Listener::INFO::2012-03-27 10:58:17,524::vmChannels::127::vds::(run) Starting VM channels listener thread.
> MainThread::DEBUG::2012-03-27 10:58:17,864::supervdsmServer::201::SuperVdsm.Server::(main) Making sure I'm root
> MainThread::DEBUG::2012-03-27 10:58:17,866::supervdsmServer::205::SuperVdsm.Server::(main) Parsing cmd args
> MainThread::DEBUG::2012-03-27 10:58:17,867::supervdsmServer::208::SuperVdsm.Server::(main) Creating PID file
> MainThread::DEBUG::2012-03-27 10:58:17,867::supervdsmServer::212::SuperVdsm.Server::(main) Cleaning old socket
> MainThread::DEBUG::2012-03-27 10:58:17,868::supervdsmServer::216::SuperVdsm.Server::(main) Setting up keep alive thread
> MainThread::DEBUG::2012-03-27 10:58:17,887::supervdsmServer::221::SuperVdsm.Server::(main) Creating remote object manager
> MainThread::DEBUG::2012-03-27 10:58:17,894::supervdsmServer::232::SuperVdsm.Server::(main) Started serving super vdsm object
> Thread-12::DEBUG::2012-03-27 10:58:19,378::supervdsm::92::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
> Thread-12::DEBUG::2012-03-27 10:58:19,431::supervdsm::64::SuperVdsmProxy::(__init__) Connected to Super Vdsm
> Thread-12::DEBUG::2012-03-27 10:58:19,737::multipath::71::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
> Thread-12::DEBUG::2012-03-27 10:58:19,838::multipath::71::Storage.Misc.excCmd::(rescan) FAILED:<err> = '';<rc> = 1
> Thread-12::DEBUG::2012-03-27 10:58:19,841::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
> Thread-12::DEBUG::2012-03-27 10:58:19,842::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
> Thread-12::DEBUG::2012-03-27 10:58:19,843::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
> Thread-12::DEBUG::2012-03-27 10:58:19,844::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
> Thread-12::DEBUG::2012-03-27 10:58:19,844::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
> Thread-12::DEBUG::2012-03-27 10:58:19,845::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
> Thread-12::DEBUG::2012-03-27 10:58:19,846::misc::1032::SamplingMethod::(__call__) Returning last result
> Thread-12::DEBUG::2012-03-27 10:58:19,847::hsm::358::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
> Thread-12::DEBUG::2012-03-27 10:58:19,853::hsm::390::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
> Thread-12::DEBUG::2012-03-27 10:58:19,857::hsm::391::Storage.HSM::(__cleanStorageRepository) Mount list: []
> Thread-12::DEBUG::2012-03-27 10:58:19,857::hsm::393::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
> Thread-12::DEBUG::2012-03-27 10:58:19,858::hsm::436::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>
> Regards, rene
>
>
> -----Ursprüngliche Nachricht-----
> Von: Moran Goldboim [mailto:mgoldboi at redhat.com]
> Gesendet: Donnerstag, 29. März 2012 09:06
> An: Rene Rosenberger
> Cc: Itamar Heim; users at oVirt.org
> Betreff: Re: [Users] creating and running a vm fails
>
> I suspect something happened to vdsm - can you attach vdsm logs
> (/var/log/vdsm/vdsm.log) from that time and maybe sneak a pick at /var/log/core if we have something there.
> Moran.
>
> On 03/29/2012 08:07 AM, Rene Rosenberger wrote:
>> Hi,
>>
>> the host on which the vm should run is up. It has a green arrow.
>>
>> Regards, rene
>>
>>
>> -----Ursprüngliche Nachricht-----
>> Von: Itamar Heim [mailto:iheim at redhat.com]
>> Gesendet: Mittwoch, 28. März 2012 22:07
>> An: Rene Rosenberger
>> Cc: users at oVirt.org
>> Betreff: Re: [Users] creating and running a vm fails
>>
>> On 03/28/2012 02:33 PM, Rene Rosenberger wrote:
>>> Hi,
>>>
>>> when i create a VM with it virtual disk and i want to run it once to
>>> install from imported iso file I get the following error message:
>>>
>>> 2012-03-28 14:31:35,488
>>> INFO[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
>>> (http--0.0.0.0-8443-5) [cf5d84e] START, CreateVmVDSCommand(vdsId =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a,
>>> vmId=93220e0a-610a-4b20-986e-3c8b0d39e35f,
>>> vm=org.ovirt.engine.core.common.businessentities.VM at 6e69e491), log id:
>>> 3fc82aad
>>>
>>> 2012-03-28 14:31:35,498
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
>>> (http--0.0.0.0-8443-5) [cf5d84e] START, CreateVDSCommand(vdsId =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a,
>>> vmId=93220e0a-610a-4b20-986e-3c8b0d39e35f,
>>> vm=org.ovirt.engine.core.common.businessentities.VM at 6e69e491), log id:
>>> 7e63d56b
>>>
>>> 2012-03-28 14:31:35,620
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
>>> (http--0.0.0.0-8443-5) [cf5d84e]
>>> org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand
>>> spiceSslCipherSuite=DEFAULT,memSize=512,kvmEnable=true,boot=dc,smp=1,
>>> e
>>> mulatedMachine=pc-0.14,vmType=kvm,keyboardLayout=en-us,pitReinjection
>>> =
>>> false,nice=0,display=vnc,tabletEnable=true,smpCoresPerSocket=1,spiceS
>>> e
>>> cureChannels=,spiceMonitors=1,cdrom=/rhev/data-center/13080edc-77ea-1
>>> 1
>>> e1-b6a4-525400c49d2a/93e2079e-ef3b-452f-af71-5b3e7eb32ba0/images/1111
>>> 1
>>> 111-1111-1111-1111-111111111111/CentOS-6.2-x86_64-bin-DVD1.iso,timeOf
>>> f
>>> set=0,transparentHugePages=true,drives=[Ljava.util.Map;@7f0ba1c1,vmId
>>> =
>>> 93220e0a-610a-4b20-986e-3c8b0d39e35f,acpiEnable=true,vmName=test,cpuT
>>> y
>>> pe=Opteron_G3,custom={}
>>>
>>> 2012-03-28 14:31:35,620
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
>>> (http--0.0.0.0-8443-5) [cf5d84e] FINISH, CreateVDSCommand, log id:
>>> 7e63d56b
>>>
>>> 2012-03-28 14:31:35,625
>>> INFO[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
>>> (http--0.0.0.0-8443-5) [cf5d84e]
>>> IncreasePendingVms::CreateVmIncreasing
>>> vds KVM-DMZ-04 pending vcpu count, now 1. Vm: test
>>>
>>> 2012-03-28 14:31:35,631
>>> INFO[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
>>> (http--0.0.0.0-8443-5) [cf5d84e] FINISH, CreateVmVDSCommand, return:
>>> WaitForLaunch, log id: 3fc82aad
>>>
>>> 2012-03-28 14:31:39,316
>>> WARN[org.ovirt.engine.core.vdsbroker.VdsManager]
>>> (QuartzScheduler_Worker-35)
>>> ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a : KVM-DMZ-04, VDS Network Error,
>>> continuing.
>>>
>>> VDSNetworkException:
>>>
>>> 2012-03-28 14:31:41,328
>>> WARN[org.ovirt.engine.core.vdsbroker.VdsManager]
>>> (QuartzScheduler_Worker-29)
>>> ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a : KVM-DMZ-04, VDS Network Error,
>>> continuing.
>>>
>>> VDSNetworkException:
>>>
>>> 2012-03-28 14:31:43,340
>>> WARN[org.ovirt.engine.core.vdsbroker.VdsManager]
>>> (QuartzScheduler_Worker-45)
>>> ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a : KVM-DMZ-04, VDS Network Error,
>>> continuing.
>>>
>>> VDSNetworkException:
>>>
>>> 2012-03-28 14:31:43,519
>>> INFO[org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand]
>>> (QuartzScheduler_Worker-38) [7ed2f412] Running command:
>>> SetStoragePoolStatusCommand internal: true. Entities affected :ID:
>>> 13080edc-77ea-11e1-b6a4-525400c49d2a Type: StoragePool
>>>
>>> 2012-03-28 14:31:43,543 ERROR
>>> [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>> (QuartzScheduler_Worker-38) [7ed2f412]
>>> IrsBroker::Failed::GetStoragePoolInfoVDS due to: ConnectException:
>>> Connection refused
>>>
>>> 2012-03-28 14:31:45,351
>>> WARN[org.ovirt.engine.core.vdsbroker.VdsManager]
>>> (QuartzScheduler_Worker-47)
>>> ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a : KVM-DMZ-04, VDS Network Error,
>>> continuing.
>>>
>>> VDSNetworkException:
>>>
>>> 2012-03-28 14:31:47,363
>>> WARN[org.ovirt.engine.core.vdsbroker.VdsManager]
>>> (QuartzScheduler_Worker-71)
>>> ResourceManager::refreshVdsRunTimeInfo::Failed to refresh VDS , vds =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a : KVM-DMZ-04, VDS Network Error,
>>> continuing.
>>>
>>> VDSNetworkException:
>>>
>>> 2012-03-28 14:31:51,091
>>> INFO[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
>>> (QuartzScheduler_Worker-55) vm test running in db and not running in
>>> vds
>>> - add to rerun treatment. vds KVM-DMZ-04
>>>
>>> 2012-03-28 14:31:51,104
>>> INFO[org.ovirt.engine.core.bll.InitVdsOnUpCommand]
>>> (QuartzScheduler_Worker-55) [6df61eca] Running command:
>>> InitVdsOnUpCommand internal: true.
>>>
>>> 2012-03-28 14:31:51,182
>>> INFO[org.ovirt.engine.core.bll.storage.ConnectHostToStoragePoolServer
>>> s
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] Running command:
>>> ConnectHostToStoragePoolServersCommand internal: true. Entities
>>> affected
>>> :ID: 13080edc-77ea-11e1-b6a4-525400c49d2a Type: StoragePool
>>>
>>> 2012-03-28 14:31:51,185
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVD
>>> S
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] START,
>>> ConnectStorageServerVDSCommand(vdsId =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a, storagePoolId =
>>> 13080edc-77ea-11e1-b6a4-525400c49d2a, storageType = ISCSI,
>>> connectionList = [{ id: e25e5093-9240-42ac-a21a-f0c216294944,
>>> connection: 192.168.200.32 };]), log id: 11a3b069
>>>
>>> 2012-03-28 14:31:51,488
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVD
>>> S
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] FINISH,
>>> ConnectStorageServerVDSCommand, return:
>>> {e25e5093-9240-42ac-a21a-f0c216294944=0}, log id: 11a3b069
>>>
>>> 2012-03-28 14:31:51,489
>>> INFO[org.ovirt.engine.core.bll.storage.ConnectHostToStoragePoolServer
>>> s
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] Host KVM-DMZ-04 storage
>>> connection was succeeded
>>>
>>> 2012-03-28 14:31:51,492
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVD
>>> S
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] START,
>>> ConnectStorageServerVDSCommand(vdsId =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a, storagePoolId =
>>> 13080edc-77ea-11e1-b6a4-525400c49d2a, storageType = NFS,
>>> connectionList = [{ id: 3dd798da-77ea-11e1-969c-525400c49d2a, connection:
>>> oVirt.dynetic.de:/mnt/iso };]), log id: 1d73fc4e
>>>
>>> 2012-03-28 14:31:51,535
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVD
>>> S
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] FINISH,
>>> ConnectStorageServerVDSCommand, return:
>>> {3dd798da-77ea-11e1-969c-525400c49d2a=0}, log id: 1d73fc4e
>>>
>>> 2012-03-28 14:31:51,535
>>> INFO[org.ovirt.engine.core.bll.storage.ConnectHostToStoragePoolServer
>>> s
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] Host KVM-DMZ-04 storage
>>> connection was succeeded
>>>
>>> 2012-03-28 14:31:51,538
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVD
>>> S
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] START,
>>> ConnectStorageServerVDSCommand(vdsId =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a, storagePoolId =
>>> 13080edc-77ea-11e1-b6a4-525400c49d2a, storageType = NFS,
>>> connectionList = [{ id: 57d6595f-1109-49f9-a7f3-f8fe255c34bd, connection:
>>> 192.168.200.32:/nfsexport };]), log id: 618343ee
>>>
>>> 2012-03-28 14:31:51,579
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVD
>>> S
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] FINISH,
>>> ConnectStorageServerVDSCommand, return:
>>> {57d6595f-1109-49f9-a7f3-f8fe255c34bd=0}, log id: 618343ee
>>>
>>> 2012-03-28 14:31:51,579
>>> INFO[org.ovirt.engine.core.bll.storage.ConnectHostToStoragePoolServer
>>> s
>>> Command]
>>> (QuartzScheduler_Worker-55) [48a331d9] Host KVM-DMZ-04 storage
>>> connection was succeeded
>>>
>>> 2012-03-28 14:31:51,594
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSC
>>> o
>>> mmand]
>>> (QuartzScheduler_Worker-55) [48a331d9] START,
>>> ConnectStoragePoolVDSCommand(vdsId =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a, storagePoolId =
>>> 13080edc-77ea-11e1-b6a4-525400c49d2a, vds_spm_id = 1, masterDomainId
>>> = 8ed25a57-f53a-4cf0-bb92-781f3ce36a48, masterVersion = 1), log id:
>>> 190d7dea
>>>
>>> 2012-03-28 14:32:02,207
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSC
>>> o
>>> mmand]
>>> (QuartzScheduler_Worker-55) [48a331d9] FINISH,
>>> ConnectStoragePoolVDSCommand, log id: 190d7dea
>>>
>>> 2012-03-28 14:32:02,231
>>> INFO[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDire
>>> c
>>> tor]
>>> (QuartzScheduler_Worker-55) [48a331d9] No string for UNASSIGNED type.
>>> Use default Log
>>>
>>> 2012-03-28 14:32:02,234
>>> INFO[org.ovirt.engine.core.bll.MultipleActionsRunner]
>>> (pool-5-thread-47) [48a331d9] MultipleActionsRunner of type
>>> MigrateVmToServer invoked with no actions
>>>
>>> 2012-03-28 14:32:02,264
>>> INFO[org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedComma
>>> n
>>> d]
>>> (QuartzScheduler_Worker-55) [75839ca5] Running command:
>>> HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities
>>> affected :ID: 0e0403a4-78ae-11e1-9c19-525400c49d2a Type: VDS
>>>
>>> 2012-03-28 14:32:02,272
>>> INFO[org.ovirt.engine.core.bll.HandleVdsVersionCommand]
>>> (QuartzScheduler_Worker-55) [2dd7e7a] Running command:
>>> HandleVdsVersionCommand internal: true. Entities affected :ID:
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a Type: VDS
>>>
>>> 2012-03-28 14:32:02,276 ERROR
>>> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
>>> (QuartzScheduler_Worker-55) [2dd7e7a] Rerun vm
>>> 93220e0a-610a-4b20-986e-3c8b0d39e35f. Called from vds KVM-DMZ-04
>>>
>>> 2012-03-28 14:32:02,280
>>> INFO[org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand]
>>> (pool-5-thread-47) [2dd7e7a] START,
>>> UpdateVdsDynamicDataVDSCommand(vdsId
>>> = 0e0403a4-78ae-11e1-9c19-525400c49d2a,
>>> vdsDynamic=org.ovirt.engine.core.common.businessentities.VdsDynamic at 2
>>> f
>>> 1f5a9f),
>>> log id: 2901421c
>>>
>>> 2012-03-28 14:32:02,282
>>> INFO[org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand]
>>> (pool-5-thread-47) [2dd7e7a] FINISH, UpdateVdsDynamicDataVDSCommand,
>>> log
>>> id: 2901421c
>>>
>>> 2012-03-28 14:32:02,299
>>> INFO[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
>>> (pool-5-thread-47) [2dd7e7a] START, IsValidVDSCommand(storagePoolId =
>>> 13080edc-77ea-11e1-b6a4-525400c49d2a, ignoreFailoverLimit = false,
>>> compatabilityVersion = null), log id: 2d73522e
>>>
>>> 2012-03-28 14:32:02,300
>>> INFO[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
>>> (pool-5-thread-47) [2dd7e7a] FINISH, IsValidVDSCommand, return:
>>> false, log id: 2d73522e
>>>
>>> 2012-03-28 14:32:02,301
>>> WARN[org.ovirt.engine.core.bll.RunVmOnceCommand]
>>> (pool-5-thread-47) [2dd7e7a] CanDoAction of action RunVmOnce failed.
>>> Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM
>>> , ACTION_TYPE_FAILED_IMAGE_REPOSITORY_NOT_FOUND
>>>
>>> 2012-03-28 14:32:04,591
>>> INFO[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>> (QuartzScheduler_Worker-62) hostFromVds::selectedVds - KVM-DMZ-04,
>>> spmStatus Free, storage pool Default
>>>
>>> 2012-03-28 14:32:05,430
>>> INFO[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>> (QuartzScheduler_Worker-62) SpmStatus on vds
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a: Free
>>>
>>> 2012-03-28 14:32:05,436
>>> INFO[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
>>> (QuartzScheduler_Worker-62) starting spm on vds KVM-DMZ-04, storage
>>> pool Default, prevId 1, LVER 0
>>>
>>> 2012-03-28 14:32:05,439
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
>>> (QuartzScheduler_Worker-62) START, SpmStartVDSCommand(vdsId =
>>> 0e0403a4-78ae-11e1-9c19-525400c49d2a, storagePoolId =
>>> 13080edc-77ea-11e1-b6a4-525400c49d2a, prevId=1, prevLVER=0,
>>> storagePoolFormatType=V2, recoveryMode=Manual, SCSIFencing=false),
>>> log
>>> id: 25d38cf4
>>>
>>> 2012-03-28 14:32:05,490
>>> INFO[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
>>> (QuartzScheduler_Worker-62) spmStart polling started: taskId =
>>> c2a0d9a2-e356-4aa9-bb29-f66a0899d8cc
>>>
>>> Any idea what to do?
>>>
>> looks like the host is no up?
>> _______________________________________________
>> 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
More information about the Users
mailing list