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: [email protected] [mailto:[email protected]] Im Auftrag von
Rene Rosenberger
Gesendet: Donnerstag, 29. März 2012 09:32
An: Moran Goldboim
Cc: [email protected]
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:[email protected]]
Gesendet: Donnerstag, 29. März 2012 09:06
An: Rene Rosenberger
Cc: Itamar Heim; [email protected]
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:[email protected]]
Gesendet: Mittwoch, 28. März 2012 22:07
An: Rene Rosenberger
Cc: [email protected]
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@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@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@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
[email protected]
http://lists.ovirt.org/mailman/listinfo/users
_______________________________________________
Users mailing list
[email protected]
http://lists.ovirt.org/mailman/listinfo/users
