Re: [ovirt-users] Creating a Instance

Below are the logs.. tail -f /var/log/vdsm vdsm/ vdsm-reg/ [root@pbuovirt3 ~]# tail -f /var/log/vdsm/vdsm.log File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 173, in _configure_broker_conn File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/env/config.py", line 129, in get Exception: Configuration value not found: file=/etc/ovirt-hosted-engine/hosted-engine.conf, key=sdUUID Thread-178420::DEBUG::2015-10-19 03:17:31,101::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-25::DEBUG::2015-10-19 03:17:31,112::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-25::DEBUG::2015-10-19 03:17:31,123::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n342 bytes (342 B) copied, 0.000262612 s, 1.3 MB/s\n'; <rc> = 0 Thread-178421::DEBUG::2015-10-19 03:17:31,131::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-74698::DEBUG::2015-10-19 03:17:31,221::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-178422::DEBUG::2015-10-19 03:17:34,156::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-178423::DEBUG::2015-10-19 03:17:37,164::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-32442::DEBUG::2015-10-19 03:17:37,824::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_home_export__domain/1484ea07-4269-44c4-a503-fa6bf43d8bd9/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-32442::DEBUG::2015-10-19 03:17:37,834::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n347 bytes (347 B) copied, 0.000355762 s, 975 kB/s\n'; <rc> = 0 Thread-26::DEBUG::2015-10-19 03:17:39,764::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-26::DEBUG::2015-10-19 03:17:39,773::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n329 bytes (329 B) copied, 0.00037456 s, 878 kB/s\n'; <rc> = 0 Thread-178424::DEBUG::2015-10-19 03:17:40,172::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-25::DEBUG::2015-10-19 03:17:41,131::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-25::DEBUG::2015-10-19 03:17:41,141::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n342 bytes (342 B) copied, 0.000363463 s, 941 kB/s\n'; <rc> = 0 Thread-178425::DEBUG::2015-10-19 03:17:43,179::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-74187::DEBUG::2015-10-19 03:17:44,816::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-74194::DEBUG::2015-10-19 03:17:44,816::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-178426::DEBUG::2015-10-19 03:17:46,187::task::595::Storage.TaskManager.Task::(_updateState) Task=`5e671cc5-9f6d-457b-8ad1-2f41e898aa56`::moving from state init -> state preparing Thread-178426::INFO::2015-10-19 03:17:46,187::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-178426::INFO::2015-10-19 03:17:46,188::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000363463', 'lastCheck': '5.0', 'valid': True}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000355762', 'lastCheck': '8.3', 'valid': True}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.00037456', 'lastCheck': '6.4', 'valid': True}} Thread-178426::DEBUG::2015-10-19 03:17:46,188::task::1191::Storage.TaskManager.Task::(prepare) Task=`5e671cc5-9f6d-457b-8ad1-2f41e898aa56`::finished: {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000363463', 'lastCheck': '5.0', 'valid': True}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000355762', 'lastCheck': '8.3', 'valid': True}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.00037456', 'lastCheck': '6.4', 'valid': True}} Thread-178426::DEBUG::2015-10-19 03:17:46,188::task::595::Storage.TaskManager.Task::(_updateState) Task=`5e671cc5-9f6d-457b-8ad1-2f41e898aa56`::moving from state preparing -> state finished Thread-178426::DEBUG::2015-10-19 03:17:46,189::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-178426::DEBUG::2015-10-19 03:17:46,189::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-178426::DEBUG::2015-10-19 03:17:46,189::task::993::Storage.TaskManager.Task::(_decref) Task=`5e671cc5-9f6d-457b-8ad1-2f41e898aa56`::ref 0 aborting False Thread-178426::ERROR::2015-10-19 03:17:46,191::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/hosted-engine.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'] Thread-178426::ERROR::2015-10-19 03:17:46,191::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/vm.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/vm.conf'] Thread-178426::ERROR::2015-10-19 03:17:46,191::API::1723::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info Traceback (most recent call last): File "/usr/share/vdsm/API.py", line 1703, in _getHaInfo File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 100, in get_all_stats File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 173, in _configure_broker_conn File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/env/config.py", line 129, in get Exception: Configuration value not found: file=/etc/ovirt-hosted-engine/hosted-engine.conf, key=sdUUID Thread-178426::DEBUG::2015-10-19 03:17:46,192::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-178427::DEBUG::2015-10-19 03:17:46,204::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-74698::DEBUG::2015-10-19 03:17:46,228::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-32442::DEBUG::2015-10-19 03:17:47,841::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_home_export__domain/1484ea07-4269-44c4-a503-fa6bf43d8bd9/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-32442::DEBUG::2015-10-19 03:17:47,852::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n347 bytes (347 B) copied, 0.000259381 s, 1.3 MB/s\n'; <rc> = 0 Thread-178428::DEBUG::2015-10-19 03:17:49,229::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-26::DEBUG::2015-10-19 03:17:49,780::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-26::DEBUG::2015-10-19 03:17:49,790::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n329 bytes (329 B) copied, 0.000346972 s, 948 kB/s\n'; <rc> = 0 Thread-25::DEBUG::2015-10-19 03:17:51,146::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-25::DEBUG::2015-10-19 03:17:51,155::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n342 bytes (342 B) copied, 0.000290823 s, 1.2 MB/s\n'; <rc> = 0 Thread-178429::DEBUG::2015-10-19 03:17:52,238::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-178430::DEBUG::2015-10-19 03:17:55,246::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-32442::DEBUG::2015-10-19 03:17:57,859::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_home_export__domain/1484ea07-4269-44c4-a503-fa6bf43d8bd9/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-32442::DEBUG::2015-10-19 03:17:57,868::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n347 bytes (347 B) copied, 0.000393319 s, 882 kB/s\n'; <rc> = 0 Thread-178431::DEBUG::2015-10-19 03:17:58,255::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-26::DEBUG::2015-10-19 03:17:59,796::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-26::DEBUG::2015-10-19 03:17:59,805::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n329 bytes (329 B) copied, 0.000300772 s, 1.1 MB/s\n'; <rc> = 0 Thread-74187::DEBUG::2015-10-19 03:17:59,827::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-74194::DEBUG::2015-10-19 03:17:59,827::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-25::DEBUG::2015-10-19 03:18:01,159::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-25::DEBUG::2015-10-19 03:18:01,168::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n342 bytes (342 B) copied, 0.000290265 s, 1.2 MB/s\n'; <rc> = 0 Thread-74698::DEBUG::2015-10-19 03:18:01,236::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-178432::DEBUG::2015-10-19 03:18:01,262::task::595::Storage.TaskManager.Task::(_updateState) Task=`fef96575-8a4c-486d-afc3-a346deec8ae0`::moving from state init -> state preparing Thread-178432::INFO::2015-10-19 03:18:01,262::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-178432::INFO::2015-10-19 03:18:01,262::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000290265', 'lastCheck': '0.1', 'valid': True}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000393319', 'lastCheck': '3.4', 'valid': True}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000300772', 'lastCheck': '1.5', 'valid': True}} Thread-178432::DEBUG::2015-10-19 03:18:01,263::task::1191::Storage.TaskManager.Task::(prepare) Task=`fef96575-8a4c-486d-afc3-a346deec8ae0`::finished: {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000290265', 'lastCheck': '0.1', 'valid': True}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000393319', 'lastCheck': '3.4', 'valid': True}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000300772', 'lastCheck': '1.5', 'valid': True}} Thread-178432::DEBUG::2015-10-19 03:18:01,263::task::595::Storage.TaskManager.Task::(_updateState) Task=`fef96575-8a4c-486d-afc3-a346deec8ae0`::moving from state preparing -> state finished Thread-178432::DEBUG::2015-10-19 03:18:01,263::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-178432::DEBUG::2015-10-19 03:18:01,263::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-178432::DEBUG::2015-10-19 03:18:01,263::task::993::Storage.TaskManager.Task::(_decref) Task=`fef96575-8a4c-486d-afc3-a346deec8ae0`::ref 0 aborting False Thread-178432::ERROR::2015-10-19 03:18:01,265::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/hosted-engine.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'] Thread-178432::ERROR::2015-10-19 03:18:01,265::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/vm.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/vm.conf'] Thread-178432::ERROR::2015-10-19 03:18:01,266::API::1723::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info Traceback (most recent call last): File "/usr/share/vdsm/API.py", line 1703, in _getHaInfo File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 100, in get_all_stats File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 173, in _configure_broker_conn File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/env/config.py", line 129, in get Exception: Configuration value not found: file=/etc/ovirt-hosted-engine/hosted-engine.conf, key=sdUUID Thread-178432::DEBUG::2015-10-19 03:18:01,267::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-178433::DEBUG::2015-10-19 03:18:01,278::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-178434::DEBUG::2015-10-19 03:18:04,302::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-178435::DEBUG::2015-10-19 03:18:07,313::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-32442::DEBUG::2015-10-19 03:18:07,873::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_home_export__domain/1484ea07-4269-44c4-a503-fa6bf43d8bd9/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-32442::DEBUG::2015-10-19 03:18:07,882::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n347 bytes (347 B) copied, 0.000382904 s, 906 kB/s\n'; <rc> = 0 Thread-26::DEBUG::2015-10-19 03:18:09,810::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-26::DEBUG::2015-10-19 03:18:09,819::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n329 bytes (329 B) copied, 0.000372718 s, 883 kB/s\n'; <rc> = 0 Thread-178436::DEBUG::2015-10-19 03:18:10,320::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-25::DEBUG::2015-10-19 03:18:11,171::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-25::DEBUG::2015-10-19 03:18:11,180::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n342 bytes (342 B) copied, 0.000348527 s, 981 kB/s\n'; <rc> = 0 Thread-178437::DEBUG::2015-10-19 03:18:13,325::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-74187::DEBUG::2015-10-19 03:18:14,835::task::595::Storage.TaskManager.Task::(_updateState) Task=`d140d5d5-3cab-407a-8b3b-ddf2ddf16b14`::moving from state init -> state preparing Thread-74194::DEBUG::2015-10-19 03:18:14,835::task::595::Storage.TaskManager.Task::(_updateState) Task=`06eb876d-eb40-49b4-870b-f75deb9a60cb`::moving from state init -> state preparing Thread-74187::INFO::2015-10-19 03:18:14,837::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'49d4a9cd-946d-41e0-a7ae-f2620f010302', spUUID=u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', imgUUID=u'ae633317-e647-41df-81f5-d4c81c2c5def', volUUID=u'31d5b7b7-f0f2-4287-ad8f-666e57c0ff61', options=None) Thread-74194::INFO::2015-10-19 03:18:14,837::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'49d4a9cd-946d-41e0-a7ae-f2620f010302', spUUID=u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', imgUUID=u'73367293-d532-48b5-9755-b323190df47f', volUUID=u'64ebcf8d-ecd7-479f-ba9e-fff0d11a1c20', options=None) Thread-74194::INFO::2015-10-19 03:18:14,843::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6664757248', 'apparentsize': '6664814592'} Thread-74187::INFO::2015-10-19 03:18:14,844::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '3695058944', 'apparentsize': '3695181824'} Thread-74194::DEBUG::2015-10-19 03:18:14,844::task::1191::Storage.TaskManager.Task::(prepare) Task=`06eb876d-eb40-49b4-870b-f75deb9a60cb`::finished: {'truesize': '6664757248', 'apparentsize': '6664814592'} Thread-74187::DEBUG::2015-10-19 03:18:14,845::task::1191::Storage.TaskManager.Task::(prepare) Task=`d140d5d5-3cab-407a-8b3b-ddf2ddf16b14`::finished: {'truesize': '3695058944', 'apparentsize': '3695181824'} Thread-74194::DEBUG::2015-10-19 03:18:14,845::task::595::Storage.TaskManager.Task::(_updateState) Task=`06eb876d-eb40-49b4-870b-f75deb9a60cb`::moving from state preparing -> state finished Thread-74187::DEBUG::2015-10-19 03:18:14,846::task::595::Storage.TaskManager.Task::(_updateState) Task=`d140d5d5-3cab-407a-8b3b-ddf2ddf16b14`::moving from state preparing -> state finished Thread-74194::DEBUG::2015-10-19 03:18:14,846::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-74187::DEBUG::2015-10-19 03:18:14,847::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-74194::DEBUG::2015-10-19 03:18:14,847::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-74187::DEBUG::2015-10-19 03:18:14,847::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-74194::DEBUG::2015-10-19 03:18:14,848::task::993::Storage.TaskManager.Task::(_decref) Task=`06eb876d-eb40-49b4-870b-f75deb9a60cb`::ref 0 aborting False Thread-74187::DEBUG::2015-10-19 03:18:14,848::task::993::Storage.TaskManager.Task::(_decref) Task=`d140d5d5-3cab-407a-8b3b-ddf2ddf16b14`::ref 0 aborting False Thread-74187::DEBUG::2015-10-19 03:18:14,874::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-74194::DEBUG::2015-10-19 03:18:14,874::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-74698::DEBUG::2015-10-19 03:18:16,239::task::595::Storage.TaskManager.Task::(_updateState) Task=`515b9bf4-d51b-48b8-847f-53816a01a7b7`::moving from state init -> state preparing Thread-74698::INFO::2015-10-19 03:18:16,240::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'49d4a9cd-946d-41e0-a7ae-f2620f010302', spUUID=u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', imgUUID=u'86f7a0dc-6ad8-4690-bae7-e3e4248bff28', volUUID=u'890ea1b5-9201-441e-8d4f-3fff58c00849', options=None) Thread-74698::INFO::2015-10-19 03:18:16,246::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '7419543552', 'apparentsize': '21474836480'} Thread-74698::DEBUG::2015-10-19 03:18:16,247::task::1191::Storage.TaskManager.Task::(prepare) Task=`515b9bf4-d51b-48b8-847f-53816a01a7b7`::finished: {'truesize': '7419543552', 'apparentsize': '21474836480'} Thread-74698::DEBUG::2015-10-19 03:18:16,248::task::595::Storage.TaskManager.Task::(_updateState) Task=`515b9bf4-d51b-48b8-847f-53816a01a7b7`::moving from state preparing -> state finished Thread-74698::DEBUG::2015-10-19 03:18:16,248::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-74698::DEBUG::2015-10-19 03:18:16,248::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-74698::DEBUG::2015-10-19 03:18:16,249::task::993::Storage.TaskManager.Task::(_decref) Task=`515b9bf4-d51b-48b8-847f-53816a01a7b7`::ref 0 aborting False Thread-74698::DEBUG::2015-10-19 03:18:16,273::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present Thread-178438::DEBUG::2015-10-19 03:18:16,332::task::595::Storage.TaskManager.Task::(_updateState) Task=`e3fb7540-0a63-49ef-a44e-05197d37b333`::moving from state init -> state preparing Thread-178438::INFO::2015-10-19 03:18:16,332::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-178438::INFO::2015-10-19 03:18:16,332::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000348527', 'lastCheck': '5.2', 'valid': True}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000382904', 'lastCheck': '8.4', 'valid': True}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000372718', 'lastCheck': '6.5', 'valid': True}} Thread-178438::DEBUG::2015-10-19 03:18:16,333::task::1191::Storage.TaskManager.Task::(prepare) Task=`e3fb7540-0a63-49ef-a44e-05197d37b333`::finished: {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000348527', 'lastCheck': '5.2', 'valid': True}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000382904', 'lastCheck': '8.4', 'valid': True}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000372718', 'lastCheck': '6.5', 'valid': True}} Thread-178438::DEBUG::2015-10-19 03:18:16,333::task::595::Storage.TaskManager.Task::(_updateState) Task=`e3fb7540-0a63-49ef-a44e-05197d37b333`::moving from state preparing -> state finished Thread-178438::DEBUG::2015-10-19 03:18:16,333::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-178438::DEBUG::2015-10-19 03:18:16,333::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-178438::DEBUG::2015-10-19 03:18:16,333::task::993::Storage.TaskManager.Task::(_decref) Task=`e3fb7540-0a63-49ef-a44e-05197d37b333`::ref 0 aborting False Thread-178438::ERROR::2015-10-19 03:18:16,335::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/hosted-engine.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'] Thread-178438::ERROR::2015-10-19 03:18:16,335::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/vm.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/vm.conf'] Thread-178438::ERROR::2015-10-19 03:18:16,335::API::1723::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info Traceback (most recent call last): File "/usr/share/vdsm/API.py", line 1703, in _getHaInfo File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 100, in get_all_stats File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 173, in _configure_broker_conn File "/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/env/config.py", line 129, in get Exception: Configuration value not found: file=/etc/ovirt-hosted-engine/hosted-engine.conf, key=sdUUID Thread-178438::DEBUG::2015-10-19 03:18:16,336::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-178439::DEBUG::2015-10-19 03:18:16,349::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-32442::DEBUG::2015-10-19 03:18:17,886::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_home_export__domain/1484ea07-4269-44c4-a503-fa6bf43d8bd9/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-32442::DEBUG::2015-10-19 03:18:17,895::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n347 bytes (347 B) copied, 0.000457796 s, 758 kB/s\n'; <rc> = 0 Thread-178440::DEBUG::2015-10-19 03:18:19,374::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-26::DEBUG::2015-10-19 03:18:19,825::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-26::DEBUG::2015-10-19 03:18:19,834::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n329 bytes (329 B) copied, 0.00035298 s, 932 kB/s\n'; <rc> = 0 Thread-25::DEBUG::2015-10-19 03:18:21,182::domainMonitor::209::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 342d943d-bccb-49eb-abf5-be9f5a2afbb5 Thread-178441::DEBUG::2015-10-19 03:18:21,185::__init__::298::IOProcessClient::(_run) Starting IOProcess... Thread-178442::DEBUG::2015-10-19 03:18:21,196::__init__::298::IOProcessClient::(_run) Starting IOProcess... Thread-178443::DEBUG::2015-10-19 03:18:21,208::__init__::298::IOProcessClient::(_run) Starting IOProcess... Thread-25::DEBUG::2015-10-19 03:18:21,239::fileSD::153::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.204.207.171: _var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5 Thread-25::DEBUG::2015-10-19 03:18:21,242::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-25::DEBUG::2015-10-19 03:18:21,245::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=ISO_DOMAIN', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=a24369bc-3e57-451b-a21c-422c5aa7b1e5', 'REMOTE_PATH=10.204.207.171:/var/lib/exports/iso', 'ROLE=Regular', 'SDUUID=342d943d-bccb-49eb-abf5-be9f5a2afbb5', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=93a3e46086203d6e02fc76fd6c8db89d8903846f'] Thread-25::DEBUG::2015-10-19 03:18:21,247::fileSD::632::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images [] Thread-25::INFO::2015-10-19 03:18:21,248::sd::385::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 342d943d-bccb-49eb-abf5-be9f5a2afbb5_imageNS already registered Thread-25::INFO::2015-10-19 03:18:21,248::sd::393::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 342d943d-bccb-49eb-abf5-be9f5a2afbb5_volumeNS already registered Thread-25::DEBUG::2015-10-19 03:18:21,249::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-25::DEBUG::2015-10-19 03:18:21,258::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n342 bytes (342 B) copied, 0.000359113 s, 952 kB/s\n'; <rc> = 0 Thread-178444::DEBUG::2015-10-19 03:18:22,381::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-178445::DEBUG::2015-10-19 03:18:25,390::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-32442::DEBUG::2015-10-19 03:18:27,899::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.204.207.171:_home_export__domain/1484ea07-4269-44c4-a503-fa6bf43d8bd9/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-32442::DEBUG::2015-10-19 03:18:27,908::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n347 bytes (347 B) copied, 0.000332208 s, 1.0 MB/s\n'; <rc> = 0 Thread-178446::DEBUG::2015-10-19 03:18:28,396::stompReactor::162::yajsonrpc.StompServer::(send) Sending response ^C On Fri, Oct 16, 2015 at 4:59 PM, Nir Soffer <nsoffer(a)redhat.com&gt; wrote: