[ovirt-users] Creating a Instance

Mon Oct 19 06:58:22 UTC 2015

We need the full vdsm logs showing the 15 minutes timeframe when you
created a vm from the template.

The best way to make progress is to file an ovirt bug and attach the
relevant vdsm logs to the bug.

Nir

On Mon, Oct 19, 2015 at 6:20 AM, Budur Nagaraju <nbudoor at gmail.com> wrote:
> Below are the logs..
>
>
>
>  tail -f /var/log/vdsm
> vdsm/     vdsm-reg/
> [root at 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 at redhat.com> wrote:
>>
>>
>> בתאריך 16 באוק׳ 2015 2:10 אחה״צ,‏ "Budur Nagaraju" <nbudoor at gmail.com>
>> כתב:
>> >
>> > Below are the details,
>> >
>> > Template size :virtual size 20GB ,actual size :4GB
>> > Storage server :Dell mounted through NFS storage capacity 2TB
>> > Free space :1.5TB
>> >
>> > There is no warn message in the engine ,let me know what logs you are
>> > expecting ?
>>
>> vdsm.log showing the these 15 minutes may be useful.
>> >
>> > Thanks,
>> > Nagaraju
>> >
>> >
>> >
>> > On Fri, Oct 16, 2015 at 4:24 PM, Nir Soffer <nsoffer at redhat.com> wrote:
>> >>
>> >>
>> >> בתאריך 16 באוק׳ 2015 9:11 לפנה״צ,‏ "Budur Nagaraju" <nbudoor at gmail.com>
>> >> כתב:
>> >> >
>> >> > HI ,
>> >> >
>> >> > While a deploying a vm from the template ,its taking minimum 15
>> >> > minutes is there any ways to solve the issues ?
>> >>
>> >> What is the template size? storage server? network? free space on
>> >> storage? logs?
>> >>
>> >> Nir
>> >> >
>> >> > Thanks,
>> >> > Nagaraju
>> >> >
>> >> >
>> >> > _______________________________________________
>> >> > Users mailing list
>> >> > Users at ovirt.org
>> >> > http://lists.ovirt.org/mailman/listinfo/users
>> >> >
>> >
>> >
>
>