Attachment 837388 Details for Bug 1038822 – vdsm.log

vdsm.log

vdsm.log (text/x-log), 211.55 KB, created by Vimal Patel on 2013-12-16 19:46:32 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Vimal Patel

Created: 2013-12-16 19:46:32 UTC

Size: 211.55 KB

patch

obsolete

>Thread-244::DEBUG::2013-12-16 13:40:10,039::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:40:10,053::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00100149 s, 4.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:40:16,239::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:40:16,252::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.00052305 s, 3.6 MB/s\n'; <rc> = 0
>Thread-206647::DEBUG::2013-12-16 13:40:18,479::task::579::TaskManager.Task::(_updateState) Task=`24ff89d8-a00b-4168-8e37-270af362d83b`::moving from state init -> state preparing
>Thread-206647::INFO::2013-12-16 13:40:18,479::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206647::INFO::2013-12-16 13:40:18,480::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00052305', 'lastCheck': '2.2', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00100149', 'lastCheck': '8.4', 'valid': True}}
>Thread-206647::DEBUG::2013-12-16 13:40:18,480::task::1168::TaskManager.Task::(prepare) Task=`24ff89d8-a00b-4168-8e37-270af362d83b`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00052305', 'lastCheck': '2.2', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00100149', 'lastCheck': '8.4', 'valid': True}}
>Thread-206647::DEBUG::2013-12-16 13:40:18,480::task::579::TaskManager.Task::(_updateState) Task=`24ff89d8-a00b-4168-8e37-270af362d83b`::moving from state preparing -> state finished
>Thread-206647::DEBUG::2013-12-16 13:40:18,480::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206647::DEBUG::2013-12-16 13:40:18,480::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206647::DEBUG::2013-12-16 13:40:18,480::task::974::TaskManager.Task::(_decref) Task=`24ff89d8-a00b-4168-8e37-270af362d83b`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:40:20,060::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:40:20,074::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00103217 s, 4.0 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:40:25,479::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:40:26,262::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:40:26,274::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000711196 s, 2.6 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:40:30,080::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:40:30,094::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00103206 s, 4.0 MB/s\n'; <rc> = 0
>Thread-206653::DEBUG::2013-12-16 13:40:34,041::task::579::TaskManager.Task::(_updateState) Task=`4ae06b4d-55aa-4d27-ad36-15802120dd2d`::moving from state init -> state preparing
>Thread-206653::INFO::2013-12-16 13:40:34,042::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206653::INFO::2013-12-16 13:40:34,042::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000711196', 'lastCheck': '7.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00103206', 'lastCheck': '3.9', 'valid': True}}
>Thread-206653::DEBUG::2013-12-16 13:40:34,042::task::1168::TaskManager.Task::(prepare) Task=`4ae06b4d-55aa-4d27-ad36-15802120dd2d`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000711196', 'lastCheck': '7.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00103206', 'lastCheck': '3.9', 'valid': True}}
>Thread-206653::DEBUG::2013-12-16 13:40:34,042::task::579::TaskManager.Task::(_updateState) Task=`4ae06b4d-55aa-4d27-ad36-15802120dd2d`::moving from state preparing -> state finished
>Thread-206653::DEBUG::2013-12-16 13:40:34,042::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206653::DEBUG::2013-12-16 13:40:34,042::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206653::DEBUG::2013-12-16 13:40:34,043::task::974::TaskManager.Task::(_decref) Task=`4ae06b4d-55aa-4d27-ad36-15802120dd2d`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:40:36,283::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:40:36,295::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000554527 s, 3.4 MB/s\n'; <rc> = 0
>Thread-73240::DEBUG::2013-12-16 13:40:39,125::task::579::TaskManager.Task::(_updateState) Task=`ef41d9b6-3dba-4560-a6e4-ec4f8023070b`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:40:39,125::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:40:39,126::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:40:39,126::task::1168::TaskManager.Task::(prepare) Task=`ef41d9b6-3dba-4560-a6e4-ec4f8023070b`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:40:39,127::task::579::TaskManager.Task::(_updateState) Task=`ef41d9b6-3dba-4560-a6e4-ec4f8023070b`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:40:39,127::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:40:39,127::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:40:39,127::task::974::TaskManager.Task::(_decref) Task=`ef41d9b6-3dba-4560-a6e4-ec4f8023070b`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:40:40,100::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:40:40,114::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00075538 s, 5.4 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:40:46,306::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:40:46,319::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000541582 s, 3.5 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:40:48,593::task::579::TaskManager.Task::(_updateState) Task=`e8972c1a-5c2d-489c-a6b3-bf72b1f4cec6`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:40:48,593::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:40:48,594::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:40:48,594::task::1168::TaskManager.Task::(prepare) Task=`e8972c1a-5c2d-489c-a6b3-bf72b1f4cec6`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:40:48,595::task::579::TaskManager.Task::(_updateState) Task=`e8972c1a-5c2d-489c-a6b3-bf72b1f4cec6`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:40:48,595::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:40:48,595::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:40:48,595::task::974::TaskManager.Task::(_decref) Task=`e8972c1a-5c2d-489c-a6b3-bf72b1f4cec6`::ref 0 aborting False
>Thread-206659::DEBUG::2013-12-16 13:40:49,598::task::579::TaskManager.Task::(_updateState) Task=`161de3a4-3acf-4a91-9849-d06fbaa1f22d`::moving from state init -> state preparing
>Thread-206659::INFO::2013-12-16 13:40:49,598::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206659::INFO::2013-12-16 13:40:49,599::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000541582', 'lastCheck': '3.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00075538', 'lastCheck': '9.5', 'valid': True}}
>Thread-206659::DEBUG::2013-12-16 13:40:49,599::task::1168::TaskManager.Task::(prepare) Task=`161de3a4-3acf-4a91-9849-d06fbaa1f22d`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000541582', 'lastCheck': '3.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00075538', 'lastCheck': '9.5', 'valid': True}}
>Thread-206659::DEBUG::2013-12-16 13:40:49,599::task::579::TaskManager.Task::(_updateState) Task=`161de3a4-3acf-4a91-9849-d06fbaa1f22d`::moving from state preparing -> state finished
>Thread-206659::DEBUG::2013-12-16 13:40:49,599::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206659::DEBUG::2013-12-16 13:40:49,599::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206659::DEBUG::2013-12-16 13:40:49,599::task::974::TaskManager.Task::(_decref) Task=`161de3a4-3acf-4a91-9849-d06fbaa1f22d`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:40:50,120::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:40:50,134::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000966243 s, 4.2 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:40:56,261::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:40:56,329::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:40:56,341::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000809927 s, 2.3 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:41:00,140::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:41:00,153::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00100952 s, 4.1 MB/s\n'; <rc> = 0
>Thread-206665::DEBUG::2013-12-16 13:41:05,161::task::579::TaskManager.Task::(_updateState) Task=`3e8bab46-cab2-4911-b332-de828677d2cd`::moving from state init -> state preparing
>Thread-206665::INFO::2013-12-16 13:41:05,161::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206665::INFO::2013-12-16 13:41:05,161::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000809927', 'lastCheck': '8.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00100952', 'lastCheck': '5.0', 'valid': True}}
>Thread-206665::DEBUG::2013-12-16 13:41:05,161::task::1168::TaskManager.Task::(prepare) Task=`3e8bab46-cab2-4911-b332-de828677d2cd`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000809927', 'lastCheck': '8.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00100952', 'lastCheck': '5.0', 'valid': True}}
>Thread-206665::DEBUG::2013-12-16 13:41:05,162::task::579::TaskManager.Task::(_updateState) Task=`3e8bab46-cab2-4911-b332-de828677d2cd`::moving from state preparing -> state finished
>Thread-206665::DEBUG::2013-12-16 13:41:05,162::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206665::DEBUG::2013-12-16 13:41:05,162::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206665::DEBUG::2013-12-16 13:41:05,162::task::974::TaskManager.Task::(_decref) Task=`3e8bab46-cab2-4911-b332-de828677d2cd`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:41:06,351::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:41:06,364::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000583243 s, 3.2 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:41:10,160::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:41:10,174::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000994149 s, 4.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:41:16,372::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:41:16,385::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000601669 s, 3.1 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:41:20,180::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:41:20,194::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000982137 s, 4.2 MB/s\n'; <rc> = 0
>Thread-206671::DEBUG::2013-12-16 13:41:20,831::task::579::TaskManager.Task::(_updateState) Task=`363079f8-0f90-46a7-987a-7ea25949f343`::moving from state init -> state preparing
>Thread-206671::INFO::2013-12-16 13:41:20,831::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206671::INFO::2013-12-16 13:41:20,832::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000601669', 'lastCheck': '4.4', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000982137', 'lastCheck': '0.6', 'valid': True}}
>Thread-206671::DEBUG::2013-12-16 13:41:20,832::task::1168::TaskManager.Task::(prepare) Task=`363079f8-0f90-46a7-987a-7ea25949f343`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000601669', 'lastCheck': '4.4', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000982137', 'lastCheck': '0.6', 'valid': True}}
>Thread-206671::DEBUG::2013-12-16 13:41:20,832::task::579::TaskManager.Task::(_updateState) Task=`363079f8-0f90-46a7-987a-7ea25949f343`::moving from state preparing -> state finished
>Thread-206671::DEBUG::2013-12-16 13:41:20,832::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206671::DEBUG::2013-12-16 13:41:20,832::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206671::DEBUG::2013-12-16 13:41:20,832::task::974::TaskManager.Task::(_decref) Task=`363079f8-0f90-46a7-987a-7ea25949f343`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:41:26,395::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:41:26,407::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000573022 s, 3.3 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:41:27,040::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:41:30,200::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:41:30,213::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000735731 s, 5.6 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:41:36,417::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-206677::DEBUG::2013-12-16 13:41:36,432::task::579::TaskManager.Task::(_updateState) Task=`945f7ce4-9a8b-40ee-a21e-79cbeab6bc4e`::moving from state init -> state preparing
>Thread-206677::INFO::2013-12-16 13:41:36,434::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206677::INFO::2013-12-16 13:41:36,435::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000573022', 'lastCheck': '10.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000735731', 'lastCheck': '6.2', 'valid': True}}
>Thread-206677::DEBUG::2013-12-16 13:41:36,436::task::1168::TaskManager.Task::(prepare) Task=`945f7ce4-9a8b-40ee-a21e-79cbeab6bc4e`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000573022', 'lastCheck': '10.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000735731', 'lastCheck': '6.2', 'valid': True}}
>Thread-206677::DEBUG::2013-12-16 13:41:36,438::task::579::TaskManager.Task::(_updateState) Task=`945f7ce4-9a8b-40ee-a21e-79cbeab6bc4e`::moving from state preparing -> state finished
>Thread-206677::DEBUG::2013-12-16 13:41:36,439::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-504::DEBUG::2013-12-16 13:41:36,439::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000456544 s, 4.1 MB/s\n'; <rc> = 0
>Thread-206677::DEBUG::2013-12-16 13:41:36,440::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206677::DEBUG::2013-12-16 13:41:36,441::task::974::TaskManager.Task::(_decref) Task=`945f7ce4-9a8b-40ee-a21e-79cbeab6bc4e`::ref 0 aborting False
>Thread-73240::DEBUG::2013-12-16 13:41:39,193::task::579::TaskManager.Task::(_updateState) Task=`7478fe39-b47a-476f-b5c3-f580ad90b343`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:41:39,193::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:41:39,193::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:41:39,194::task::1168::TaskManager.Task::(prepare) Task=`7478fe39-b47a-476f-b5c3-f580ad90b343`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:41:39,194::task::579::TaskManager.Task::(_updateState) Task=`7478fe39-b47a-476f-b5c3-f580ad90b343`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:41:39,194::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:41:39,194::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:41:39,194::task::974::TaskManager.Task::(_decref) Task=`7478fe39-b47a-476f-b5c3-f580ad90b343`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:41:40,220::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:41:40,233::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000882574 s, 4.6 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:41:46,454::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:41:46,467::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000712561 s, 2.6 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:41:48,666::task::579::TaskManager.Task::(_updateState) Task=`2ca1d911-0a6c-4c85-9b95-6325742a80af`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:41:48,666::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:41:48,667::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:41:48,667::task::1168::TaskManager.Task::(prepare) Task=`2ca1d911-0a6c-4c85-9b95-6325742a80af`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:41:48,667::task::579::TaskManager.Task::(_updateState) Task=`2ca1d911-0a6c-4c85-9b95-6325742a80af`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:41:48,667::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:41:48,667::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:41:48,667::task::974::TaskManager.Task::(_decref) Task=`2ca1d911-0a6c-4c85-9b95-6325742a80af`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:41:50,240::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:41:50,254::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000966543 s, 4.2 MB/s\n'; <rc> = 0
>Thread-206683::DEBUG::2013-12-16 13:41:52,016::task::579::TaskManager.Task::(_updateState) Task=`c4813184-c2b3-4439-9ee4-0ba930f0ca99`::moving from state init -> state preparing
>Thread-206683::INFO::2013-12-16 13:41:52,016::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206683::INFO::2013-12-16 13:41:52,017::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000712561', 'lastCheck': '5.5', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000966543', 'lastCheck': '1.8', 'valid': True}}
>Thread-206683::DEBUG::2013-12-16 13:41:52,017::task::1168::TaskManager.Task::(prepare) Task=`c4813184-c2b3-4439-9ee4-0ba930f0ca99`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000712561', 'lastCheck': '5.5', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000966543', 'lastCheck': '1.8', 'valid': True}}
>Thread-206683::DEBUG::2013-12-16 13:41:52,017::task::579::TaskManager.Task::(_updateState) Task=`c4813184-c2b3-4439-9ee4-0ba930f0ca99`::moving from state preparing -> state finished
>Thread-206683::DEBUG::2013-12-16 13:41:52,017::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206683::DEBUG::2013-12-16 13:41:52,017::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206683::DEBUG::2013-12-16 13:41:52,017::task::974::TaskManager.Task::(_decref) Task=`c4813184-c2b3-4439-9ee4-0ba930f0ca99`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:41:56,477::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:41:56,489::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000502849 s, 3.7 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:41:57,527::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:42:00,260::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:42:00,274::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000997274 s, 4.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:42:06,498::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:42:06,511::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000710181 s, 2.6 MB/s\n'; <rc> = 0
>Thread-206689::DEBUG::2013-12-16 13:42:07,635::task::579::TaskManager.Task::(_updateState) Task=`3e420415-dde2-4679-b43c-d77de287d2a6`::moving from state init -> state preparing
>Thread-206689::INFO::2013-12-16 13:42:07,635::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206689::INFO::2013-12-16 13:42:07,636::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000710181', 'lastCheck': '1.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000997274', 'lastCheck': '7.4', 'valid': True}}
>Thread-206689::DEBUG::2013-12-16 13:42:07,636::task::1168::TaskManager.Task::(prepare) Task=`3e420415-dde2-4679-b43c-d77de287d2a6`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000710181', 'lastCheck': '1.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000997274', 'lastCheck': '7.4', 'valid': True}}
>Thread-206689::DEBUG::2013-12-16 13:42:07,636::task::579::TaskManager.Task::(_updateState) Task=`3e420415-dde2-4679-b43c-d77de287d2a6`::moving from state preparing -> state finished
>Thread-206689::DEBUG::2013-12-16 13:42:07,636::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206689::DEBUG::2013-12-16 13:42:07,636::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206689::DEBUG::2013-12-16 13:42:07,636::task::974::TaskManager.Task::(_decref) Task=`3e420415-dde2-4679-b43c-d77de287d2a6`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:42:10,281::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:42:10,294::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00100225 s, 4.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:42:16,521::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:42:16,533::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000560511 s, 3.4 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:42:20,301::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:42:20,314::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000931829 s, 4.4 MB/s\n'; <rc> = 0
>Thread-206695::DEBUG::2013-12-16 13:42:23,264::task::579::TaskManager.Task::(_updateState) Task=`0c20737b-f214-4701-8a2f-dbbb237dd4e3`::moving from state init -> state preparing
>Thread-206695::INFO::2013-12-16 13:42:23,265::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206695::INFO::2013-12-16 13:42:23,265::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000560511', 'lastCheck': '6.7', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000931829', 'lastCheck': '2.9', 'valid': True}}
>Thread-206695::DEBUG::2013-12-16 13:42:23,265::task::1168::TaskManager.Task::(prepare) Task=`0c20737b-f214-4701-8a2f-dbbb237dd4e3`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000560511', 'lastCheck': '6.7', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000931829', 'lastCheck': '2.9', 'valid': True}}
>Thread-206695::DEBUG::2013-12-16 13:42:23,265::task::579::TaskManager.Task::(_updateState) Task=`0c20737b-f214-4701-8a2f-dbbb237dd4e3`::moving from state preparing -> state finished
>Thread-206695::DEBUG::2013-12-16 13:42:23,265::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206695::DEBUG::2013-12-16 13:42:23,265::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206695::DEBUG::2013-12-16 13:42:23,265::task::974::TaskManager.Task::(_decref) Task=`0c20737b-f214-4701-8a2f-dbbb237dd4e3`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:42:26,542::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:42:26,554::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000548931 s, 3.4 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:42:28,339::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:42:30,321::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:42:30,334::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000753334 s, 5.4 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:42:36,563::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:42:36,575::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000580434 s, 3.2 MB/s\n'; <rc> = 0
>Thread-206701::DEBUG::2013-12-16 13:42:38,847::task::579::TaskManager.Task::(_updateState) Task=`20f5f888-456c-4ef9-9668-a6781881b788`::moving from state init -> state preparing
>Thread-206701::INFO::2013-12-16 13:42:38,847::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206701::INFO::2013-12-16 13:42:38,847::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000580434', 'lastCheck': '2.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000753334', 'lastCheck': '8.5', 'valid': True}}
>Thread-206701::DEBUG::2013-12-16 13:42:38,848::task::1168::TaskManager.Task::(prepare) Task=`20f5f888-456c-4ef9-9668-a6781881b788`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000580434', 'lastCheck': '2.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000753334', 'lastCheck': '8.5', 'valid': True}}
>Thread-206701::DEBUG::2013-12-16 13:42:38,848::task::579::TaskManager.Task::(_updateState) Task=`20f5f888-456c-4ef9-9668-a6781881b788`::moving from state preparing -> state finished
>Thread-206701::DEBUG::2013-12-16 13:42:38,848::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206701::DEBUG::2013-12-16 13:42:38,848::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206701::DEBUG::2013-12-16 13:42:38,848::task::974::TaskManager.Task::(_decref) Task=`20f5f888-456c-4ef9-9668-a6781881b788`::ref 0 aborting False
>Thread-73240::DEBUG::2013-12-16 13:42:39,255::task::579::TaskManager.Task::(_updateState) Task=`f55d571b-966f-48cc-84b4-90404b5fbde8`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:42:39,256::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:42:39,256::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:42:39,256::task::1168::TaskManager.Task::(prepare) Task=`f55d571b-966f-48cc-84b4-90404b5fbde8`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:42:39,256::task::579::TaskManager.Task::(_updateState) Task=`f55d571b-966f-48cc-84b4-90404b5fbde8`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:42:39,256::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:42:39,257::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:42:39,257::task::974::TaskManager.Task::(_decref) Task=`f55d571b-966f-48cc-84b4-90404b5fbde8`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:42:40,341::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:42:40,355::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000688137 s, 6.0 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:42:46,588::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:42:46,601::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000462095 s, 4.1 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:42:48,732::task::579::TaskManager.Task::(_updateState) Task=`69f55563-0310-483c-8f31-512837b3bbb8`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:42:48,733::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:42:48,733::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:42:48,733::task::1168::TaskManager.Task::(prepare) Task=`69f55563-0310-483c-8f31-512837b3bbb8`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:42:48,734::task::579::TaskManager.Task::(_updateState) Task=`69f55563-0310-483c-8f31-512837b3bbb8`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:42:48,734::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:42:48,734::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:42:48,734::task::974::TaskManager.Task::(_decref) Task=`69f55563-0310-483c-8f31-512837b3bbb8`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:42:50,361::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:42:50,375::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00102104 s, 4.0 MB/s\n'; <rc> = 0
>Thread-206707::DEBUG::2013-12-16 13:42:54,773::task::579::TaskManager.Task::(_updateState) Task=`5070f6ed-d341-4c7d-b810-b4c864698cca`::moving from state init -> state preparing
>Thread-206707::INFO::2013-12-16 13:42:54,773::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206707::INFO::2013-12-16 13:42:54,774::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000462095', 'lastCheck': '8.2', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00102104', 'lastCheck': '4.4', 'valid': True}}
>Thread-206707::DEBUG::2013-12-16 13:42:54,774::task::1168::TaskManager.Task::(prepare) Task=`5070f6ed-d341-4c7d-b810-b4c864698cca`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000462095', 'lastCheck': '8.2', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00102104', 'lastCheck': '4.4', 'valid': True}}
>Thread-206707::DEBUG::2013-12-16 13:42:54,774::task::579::TaskManager.Task::(_updateState) Task=`5070f6ed-d341-4c7d-b810-b4c864698cca`::moving from state preparing -> state finished
>Thread-206707::DEBUG::2013-12-16 13:42:54,774::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206707::DEBUG::2013-12-16 13:42:54,774::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206707::DEBUG::2013-12-16 13:42:54,774::task::974::TaskManager.Task::(_decref) Task=`5070f6ed-d341-4c7d-b810-b4c864698cca`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:42:56,609::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:42:56,621::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000572671 s, 3.3 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:42:59,121::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:43:00,381::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:43:00,395::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000961675 s, 4.3 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:43:06,631::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:43:06,643::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000519855 s, 3.6 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:43:10,401::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:43:10,415::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000992468 s, 4.1 MB/s\n'; <rc> = 0
>Thread-206713::DEBUG::2013-12-16 13:43:10,597::task::579::TaskManager.Task::(_updateState) Task=`590e4523-7de3-41ba-80bf-117bec0d9c98`::moving from state init -> state preparing
>Thread-206713::INFO::2013-12-16 13:43:10,598::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206713::INFO::2013-12-16 13:43:10,598::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000519855', 'lastCheck': '4.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000992468', 'lastCheck': '0.2', 'valid': True}}
>Thread-206713::DEBUG::2013-12-16 13:43:10,598::task::1168::TaskManager.Task::(prepare) Task=`590e4523-7de3-41ba-80bf-117bec0d9c98`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000519855', 'lastCheck': '4.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000992468', 'lastCheck': '0.2', 'valid': True}}
>Thread-206713::DEBUG::2013-12-16 13:43:10,598::task::579::TaskManager.Task::(_updateState) Task=`590e4523-7de3-41ba-80bf-117bec0d9c98`::moving from state preparing -> state finished
>Thread-206713::DEBUG::2013-12-16 13:43:10,598::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206713::DEBUG::2013-12-16 13:43:10,598::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206713::DEBUG::2013-12-16 13:43:10,599::task::974::TaskManager.Task::(_decref) Task=`590e4523-7de3-41ba-80bf-117bec0d9c98`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:43:16,653::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:43:16,665::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000578808 s, 3.2 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:43:20,421::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:43:20,435::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000937735 s, 4.4 MB/s\n'; <rc> = 0
>Thread-206719::DEBUG::2013-12-16 13:43:26,243::task::579::TaskManager.Task::(_updateState) Task=`234a99be-2c46-428d-a7c5-90f0e6c17f97`::moving from state init -> state preparing
>Thread-206719::INFO::2013-12-16 13:43:26,244::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206719::INFO::2013-12-16 13:43:26,244::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000578808', 'lastCheck': '9.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000937735', 'lastCheck': '5.8', 'valid': True}}
>Thread-206719::DEBUG::2013-12-16 13:43:26,244::task::1168::TaskManager.Task::(prepare) Task=`234a99be-2c46-428d-a7c5-90f0e6c17f97`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000578808', 'lastCheck': '9.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000937735', 'lastCheck': '5.8', 'valid': True}}
>Thread-206719::DEBUG::2013-12-16 13:43:26,244::task::579::TaskManager.Task::(_updateState) Task=`234a99be-2c46-428d-a7c5-90f0e6c17f97`::moving from state preparing -> state finished
>Thread-206719::DEBUG::2013-12-16 13:43:26,244::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206719::DEBUG::2013-12-16 13:43:26,244::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206719::DEBUG::2013-12-16 13:43:26,245::task::974::TaskManager.Task::(_decref) Task=`234a99be-2c46-428d-a7c5-90f0e6c17f97`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:43:26,674::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:43:26,686::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000456407 s, 4.1 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:43:29,900::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:43:30,441::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:43:30,455::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000962425 s, 4.3 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:43:36,694::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:43:36,707::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000561244 s, 3.3 MB/s\n'; <rc> = 0
>Thread-73240::DEBUG::2013-12-16 13:43:39,321::task::579::TaskManager.Task::(_updateState) Task=`b6ece980-405b-4c61-9a41-7f0640658477`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:43:39,321::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:43:39,321::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:43:39,322::task::1168::TaskManager.Task::(prepare) Task=`b6ece980-405b-4c61-9a41-7f0640658477`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:43:39,322::task::579::TaskManager.Task::(_updateState) Task=`b6ece980-405b-4c61-9a41-7f0640658477`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:43:39,322::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:43:39,322::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:43:39,322::task::974::TaskManager.Task::(_decref) Task=`b6ece980-405b-4c61-9a41-7f0640658477`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:43:40,462::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:43:40,476::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000870343 s, 4.7 MB/s\n'; <rc> = 0
>Thread-206725::DEBUG::2013-12-16 13:43:41,997::task::579::TaskManager.Task::(_updateState) Task=`bfc75c13-851b-4073-8673-2e8dfa51d069`::moving from state init -> state preparing
>Thread-206725::INFO::2013-12-16 13:43:41,997::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206725::INFO::2013-12-16 13:43:41,998::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000561244', 'lastCheck': '5.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000870343', 'lastCheck': '1.5', 'valid': True}}
>Thread-206725::DEBUG::2013-12-16 13:43:41,998::task::1168::TaskManager.Task::(prepare) Task=`bfc75c13-851b-4073-8673-2e8dfa51d069`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000561244', 'lastCheck': '5.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000870343', 'lastCheck': '1.5', 'valid': True}}
>Thread-206725::DEBUG::2013-12-16 13:43:41,998::task::579::TaskManager.Task::(_updateState) Task=`bfc75c13-851b-4073-8673-2e8dfa51d069`::moving from state preparing -> state finished
>Thread-206725::DEBUG::2013-12-16 13:43:41,998::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206725::DEBUG::2013-12-16 13:43:41,998::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206725::DEBUG::2013-12-16 13:43:41,998::task::974::TaskManager.Task::(_decref) Task=`bfc75c13-851b-4073-8673-2e8dfa51d069`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:43:46,722::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:43:46,735::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000734595 s, 2.6 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:43:48,800::task::579::TaskManager.Task::(_updateState) Task=`05eaf6cc-55d7-45a1-b3bb-43e699a8f169`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:43:48,800::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:43:48,802::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:43:48,802::task::1168::TaskManager.Task::(prepare) Task=`05eaf6cc-55d7-45a1-b3bb-43e699a8f169`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:43:48,802::task::579::TaskManager.Task::(_updateState) Task=`05eaf6cc-55d7-45a1-b3bb-43e699a8f169`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:43:48,803::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:43:48,803::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:43:48,803::task::974::TaskManager.Task::(_decref) Task=`05eaf6cc-55d7-45a1-b3bb-43e699a8f169`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:43:50,482::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:43:50,495::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000904405 s, 4.5 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:43:56,737::domainMonitor::188::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain e1a50b62-693a-412c-bffd-2c9147e4c5b4
>Thread-504::DEBUG::2013-12-16 13:43:56,741::fileSD::154::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4
>Thread-504::DEBUG::2013-12-16 13:43:56,743::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-504::DEBUG::2013-12-16 13:43:56,751::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=isos', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=a0880a4b-2521-4b53-91b1-6d77bccb812c,a33409d2-b875-11e0-8078-eba376b6e797,8c9e3d88-47ac-4826-9a67-c48a70354c85,23e39e7b-bf33-4a0c-8171-dfe0ac2ec7cc,fc66a0ea-bd17-11e0-8e80-52540051f51d,53552856-c2a7-11e0-8ff2-9feb3da58e93,ebc8cf69-e092-44a8-8b01-80240f2952c7,d09f7dfa-d334-11e0-9d73-a37c621ee5cf,c7f97418-e2fb-4cc3-a6a5-b0d4019b5c48,af1f0a6a-da32-11e0-82ee-db1931649314,7cccaa60-e54d-11e0-a0e3-ef56a5ce5e14,5426b244-79d9-4a24-a405-d4bfa3610e4b,4e09e544-7c4b-4a3b-931e-2bca1b3296d6,1501daa3-c851-4285-a79f-3c661e20ea78,9cccfedc-f8ee-11e0-8c1c-7bd4edc156ae,137e7558-0955-11e1-8cf5-525400aec2e1,5f3bfe02-146d-11e1-8c23-52540051e8ec,5399c070-1ac1-11e1-abaa-52540057dbfb,c00b2366-269c-11e1-b5ff-525400484308,bf2014aa-2bee-11e1-8a85-bf0c48e787d5,de352855-8f6a-409d-aa63-64c43a23ca22,7624bbe4-6dec-11e1-beb0-5254001dd915,35330d20-6ecd-11e1-85d0-525400b635c2,85459dae-7379-11e1-ae61-5254003ce2cf,17f6f60d-3167-4c12-b5f3-181415fc0828,5fb2e0da-9302-11e1-b018-52540053bfec,894380b7-c07f-4ad6-9ff8-e3c77bea2fad,6a27df7e-9aa6-11e1-a60e-52540053bfec,ebc98b96-a4fa-11e1-99ff-52540053bfec,1b5da69e-eaec-11e1-99c2-52540053bfec,38cea776-f1fb-11e1-9c9f-52540053bfec,43022794-fb48-11e1-8729-52540053bfec,48d1432c-01c3-11e2-b084-52540053bfec,3119f92e-0324-11e2-968f-52540053bfec,efe1a784-072b-11e2-b747-52540053bfec,72a604c2-1239-11e2-9d40-52540053bfec,8c80424e-29b9-11e2-a3cb-52540053bfec,2ed6ea74-38a7-11e2-b078-52540053bfec,1860a536-3984-11e2-ba68-52540053bfec,8ef05a52-3eed-11e2-a9ba-52540065f8a4,c0c90026-ac0f-11e2-acc0-52540065f8a4,5849b030-626e-47cb-ad90-3ce782d831b3', 'REMOTE_PATH=storage.spice.lab.eng.bos.redhat.com:/rhev/isos', 'ROLE=Regular', 'SDUUID=e1a50b62-693a-412c-bffd-2c9147e4c5b4', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=17678220953f2c63e342af10e676a46e923ffc65']
>Thread-504::DEBUG::2013-12-16 13:43:56,753::fileSD::572::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-504::INFO::2013-12-16 13:43:56,753::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace e1a50b62-693a-412c-bffd-2c9147e4c5b4_imageNS already registered
>Thread-504::INFO::2013-12-16 13:43:56,753::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace e1a50b62-693a-412c-bffd-2c9147e4c5b4_volumeNS already registered
>Thread-504::DEBUG::2013-12-16 13:43:56,759::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:43:56,771::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000509423 s, 3.7 MB/s\n'; <rc> = 0
>Thread-206732::DEBUG::2013-12-16 13:43:57,680::task::579::TaskManager.Task::(_updateState) Task=`28390dbc-5b9a-47eb-9188-e95a29ef862b`::moving from state init -> state preparing
>Thread-206732::INFO::2013-12-16 13:43:57,680::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206732::INFO::2013-12-16 13:43:57,681::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000509423', 'lastCheck': '0.9', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000904405', 'lastCheck': '7.2', 'valid': True}}
>Thread-206732::DEBUG::2013-12-16 13:43:57,681::task::1168::TaskManager.Task::(prepare) Task=`28390dbc-5b9a-47eb-9188-e95a29ef862b`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000509423', 'lastCheck': '0.9', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000904405', 'lastCheck': '7.2', 'valid': True}}
>Thread-206732::DEBUG::2013-12-16 13:43:57,681::task::579::TaskManager.Task::(_updateState) Task=`28390dbc-5b9a-47eb-9188-e95a29ef862b`::moving from state preparing -> state finished
>Thread-206732::DEBUG::2013-12-16 13:43:57,681::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206732::DEBUG::2013-12-16 13:43:57,681::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206732::DEBUG::2013-12-16 13:43:57,681::task::974::TaskManager.Task::(_decref) Task=`28390dbc-5b9a-47eb-9188-e95a29ef862b`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:44:00,502::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:44:00,516::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00101393 s, 4.0 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:44:00,679::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:44:06,782::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:44:06,794::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000596569 s, 3.2 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:44:10,522::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:44:10,535::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00102599 s, 4.0 MB/s\n'; <rc> = 0
>Thread-206738::DEBUG::2013-12-16 13:44:13,396::task::579::TaskManager.Task::(_updateState) Task=`c22df4bf-811c-470e-97a2-836ab68a37ee`::moving from state init -> state preparing
>Thread-206738::INFO::2013-12-16 13:44:13,396::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206738::INFO::2013-12-16 13:44:13,396::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000596569', 'lastCheck': '6.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00102599', 'lastCheck': '2.9', 'valid': True}}
>Thread-206738::DEBUG::2013-12-16 13:44:13,396::task::1168::TaskManager.Task::(prepare) Task=`c22df4bf-811c-470e-97a2-836ab68a37ee`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000596569', 'lastCheck': '6.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00102599', 'lastCheck': '2.9', 'valid': True}}
>Thread-206738::DEBUG::2013-12-16 13:44:13,397::task::579::TaskManager.Task::(_updateState) Task=`c22df4bf-811c-470e-97a2-836ab68a37ee`::moving from state preparing -> state finished
>Thread-206738::DEBUG::2013-12-16 13:44:13,397::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206738::DEBUG::2013-12-16 13:44:13,397::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206738::DEBUG::2013-12-16 13:44:13,397::task::974::TaskManager.Task::(_decref) Task=`c22df4bf-811c-470e-97a2-836ab68a37ee`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:44:16,804::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:44:16,817::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.0007096 s, 2.6 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:44:20,541::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:44:20,555::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00097878 s, 4.2 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:44:26,826::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:44:26,838::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000478445 s, 3.9 MB/s\n'; <rc> = 0
>Thread-206744::DEBUG::2013-12-16 13:44:29,122::task::579::TaskManager.Task::(_updateState) Task=`5220b5ba-a434-4680-80d6-c66f9855ba4a`::moving from state init -> state preparing
>Thread-206744::INFO::2013-12-16 13:44:29,122::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206744::INFO::2013-12-16 13:44:29,122::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000478445', 'lastCheck': '2.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00097878', 'lastCheck': '8.6', 'valid': True}}
>Thread-206744::DEBUG::2013-12-16 13:44:29,122::task::1168::TaskManager.Task::(prepare) Task=`5220b5ba-a434-4680-80d6-c66f9855ba4a`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000478445', 'lastCheck': '2.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00097878', 'lastCheck': '8.6', 'valid': True}}
>Thread-206744::DEBUG::2013-12-16 13:44:29,123::task::579::TaskManager.Task::(_updateState) Task=`5220b5ba-a434-4680-80d6-c66f9855ba4a`::moving from state preparing -> state finished
>Thread-206744::DEBUG::2013-12-16 13:44:29,123::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206744::DEBUG::2013-12-16 13:44:29,123::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206744::DEBUG::2013-12-16 13:44:29,123::task::974::TaskManager.Task::(_decref) Task=`5220b5ba-a434-4680-80d6-c66f9855ba4a`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:44:30,561::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:44:30,574::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000988112 s, 4.1 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:44:31,200::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:44:36,848::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:44:36,861::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000529476 s, 3.6 MB/s\n'; <rc> = 0
>Thread-73240::DEBUG::2013-12-16 13:44:39,384::task::579::TaskManager.Task::(_updateState) Task=`c5f0fc6c-66ea-4f4f-a1cc-10d4465d2985`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:44:39,384::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:44:39,385::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:44:39,385::task::1168::TaskManager.Task::(prepare) Task=`c5f0fc6c-66ea-4f4f-a1cc-10d4465d2985`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:44:39,385::task::579::TaskManager.Task::(_updateState) Task=`c5f0fc6c-66ea-4f4f-a1cc-10d4465d2985`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:44:39,385::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:44:39,385::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:44:39,385::task::974::TaskManager.Task::(_decref) Task=`c5f0fc6c-66ea-4f4f-a1cc-10d4465d2985`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:44:40,580::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:44:40,594::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000996058 s, 4.1 MB/s\n'; <rc> = 0
>Thread-206750::DEBUG::2013-12-16 13:44:44,769::task::579::TaskManager.Task::(_updateState) Task=`5b9ddb33-c487-493b-9a37-db768898efb5`::moving from state init -> state preparing
>Thread-206750::INFO::2013-12-16 13:44:44,770::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206750::INFO::2013-12-16 13:44:44,770::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000529476', 'lastCheck': '7.9', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000996058', 'lastCheck': '4.2', 'valid': True}}
>Thread-206750::DEBUG::2013-12-16 13:44:44,770::task::1168::TaskManager.Task::(prepare) Task=`5b9ddb33-c487-493b-9a37-db768898efb5`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000529476', 'lastCheck': '7.9', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000996058', 'lastCheck': '4.2', 'valid': True}}
>Thread-206750::DEBUG::2013-12-16 13:44:44,770::task::579::TaskManager.Task::(_updateState) Task=`5b9ddb33-c487-493b-9a37-db768898efb5`::moving from state preparing -> state finished
>Thread-206750::DEBUG::2013-12-16 13:44:44,770::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206750::DEBUG::2013-12-16 13:44:44,770::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206750::DEBUG::2013-12-16 13:44:44,770::task::974::TaskManager.Task::(_decref) Task=`5b9ddb33-c487-493b-9a37-db768898efb5`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:44:46,872::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:44:46,885::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000469507 s, 4.0 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:44:48,884::task::579::TaskManager.Task::(_updateState) Task=`141e8f6c-b08b-4bf5-b6a1-97b02b61deba`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:44:48,885::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:44:48,885::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:44:48,886::task::1168::TaskManager.Task::(prepare) Task=`141e8f6c-b08b-4bf5-b6a1-97b02b61deba`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:44:48,886::task::579::TaskManager.Task::(_updateState) Task=`141e8f6c-b08b-4bf5-b6a1-97b02b61deba`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:44:48,886::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:44:48,886::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:44:48,886::task::974::TaskManager.Task::(_decref) Task=`141e8f6c-b08b-4bf5-b6a1-97b02b61deba`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:44:50,600::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:44:50,614::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000977117 s, 4.2 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:44:56,894::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:44:56,906::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000523431 s, 3.6 MB/s\n'; <rc> = 0
>Thread-206756::DEBUG::2013-12-16 13:45:00,391::task::579::TaskManager.Task::(_updateState) Task=`2a81fd7f-dda4-4930-b06f-1d8d4524c02f`::moving from state init -> state preparing
>Thread-206756::INFO::2013-12-16 13:45:00,392::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206756::INFO::2013-12-16 13:45:00,392::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000523431', 'lastCheck': '3.5', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000977117', 'lastCheck': '9.8', 'valid': True}}
>Thread-206756::DEBUG::2013-12-16 13:45:00,392::task::1168::TaskManager.Task::(prepare) Task=`2a81fd7f-dda4-4930-b06f-1d8d4524c02f`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000523431', 'lastCheck': '3.5', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000977117', 'lastCheck': '9.8', 'valid': True}}
>Thread-206756::DEBUG::2013-12-16 13:45:00,392::task::579::TaskManager.Task::(_updateState) Task=`2a81fd7f-dda4-4930-b06f-1d8d4524c02f`::moving from state preparing -> state finished
>Thread-206756::DEBUG::2013-12-16 13:45:00,392::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206756::DEBUG::2013-12-16 13:45:00,392::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206756::DEBUG::2013-12-16 13:45:00,393::task::974::TaskManager.Task::(_decref) Task=`2a81fd7f-dda4-4930-b06f-1d8d4524c02f`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:45:00,617::domainMonitor::188::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 75e24eb3-104c-451f-bf57-056b3b30ffba
>Thread-244::DEBUG::2013-12-16 13:45:00,617::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
>Thread-244::DEBUG::2013-12-16 13:45:00,620::blockSD::326::Storage.Misc.excCmd::(readlines) '/bin/dd iflag=direct skip=0 bs=2048 if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:00,632::blockSD::326::Storage.Misc.excCmd::(readlines) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.000715796 s, 2.9 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:45:00,632::misc::289::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.000715796 s, 2.9 MB/s'], size: 2048
>Thread-244::DEBUG::2013-12-16 13:45:00,632::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
>Thread-244::WARNING::2013-12-16 13:45:00,632::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-244::DEBUG::2013-12-16 13:45:00,632::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
>Thread-244::DEBUG::2013-12-16 13:45:00,633::lvm::516::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-244::DEBUG::2013-12-16 13:45:00,633::lvm::518::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-244::DEBUG::2013-12-16 13:45:00,633::lvm::526::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-244::DEBUG::2013-12-16 13:45:00,633::lvm::538::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-244::DEBUG::2013-12-16 13:45:00,634::lvm::386::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-244::DEBUG::2013-12-16 13:45:00,634::lvm::309::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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/1ATA_WDC_WD6400AAKS-22A7B2_WD-WCASYC833778|/dev/mapper/360a9800044306a31715d436c58414664|/dev/mapper/360a9800044306a31715d436c58414666|/dev/mapper/360a9800044306a31715d436c58414668|/dev/mapper/360a9800044306a31715d436c5841466a|/dev/mapper/360a9800044306a31715d436c5841466c|\', \'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 | --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name 75e24eb3-104c-451f-bf57-056b3b30ffba' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:01,059::lvm::309::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:45:01,061::lvm::428::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-244::DEBUG::2013-12-16 13:45:01,061::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['LEASETIMESEC=60', 'PHYBLKSIZE=4096', 'LOCKPOLICY=', 'VERSION=3', 'TYPE=ISCSI', 'SDUUID=75e24eb3-104c-451f-bf57-056b3b30ffba', 'LOGBLKSIZE=512', 'VGUUID=SuZ7tB-gRcV-4e5F-jzQe-OxhP-ZkVo-RaiyJZ', u'PV0=pv:360a9800044306a31715d436c58414664,uuid:ErDKs4-bAoU-ytRd-whqW-CJxW-J3Sr-lIBwBo,pestart:0,pecount:3998,mapoffset:0', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'DESCRIPTION=netapp-storage', 'CLASS=Data', 'POOL_UUID=5849b030-626e-47cb-ad90-3ce782d831b3', 'POOL_DESCRIPTION=Default', 'ROLE=Master', 'MASTER_VERSION=1', 'POOL_SPM_ID=2', u'POOL_DOMAINS=e1a50b62-693a-412c-bffd-2c9147e4c5b4:Active,75e24eb3-104c-451f-bf57-056b3b30ffba:Active', '_SHA_CKSUM=a730ad4fb83a066bcc5ddb89a1e6c148430342a6', 'POOL_SPM_LVER=1']
>Thread-244::INFO::2013-12-16 13:45:01,062::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 75e24eb3-104c-451f-bf57-056b3b30ffba_imageNS already registered
>Thread-244::INFO::2013-12-16 13:45:01,062::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 75e24eb3-104c-451f-bf57-056b3b30ffba_volumeNS already registered
>Thread-244::INFO::2013-12-16 13:45:01,062::blockSD::446::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 75e24eb3-104c-451f-bf57-056b3b30ffba_lvmActivationNS already registered
>Thread-244::DEBUG::2013-12-16 13:45:01,063::lvm::309::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/360a9800044306a31715d436c58414664|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " 75e24eb3-104c-451f-bf57-056b3b30ffba' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:01,332::lvm::309::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:45:01,336::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:01,350::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000714562 s, 5.7 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:45:01,981::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:45:06,917::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:45:06,929::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000495916 s, 3.8 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:45:11,357::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:11,371::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00103978 s, 3.9 MB/s\n'; <rc> = 0
>Thread-206762::DEBUG::2013-12-16 13:45:15,978::task::579::TaskManager.Task::(_updateState) Task=`b72a8b7e-a57b-4dd4-a139-e2e0d38793d7`::moving from state init -> state preparing
>Thread-206762::INFO::2013-12-16 13:45:15,978::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206762::INFO::2013-12-16 13:45:15,978::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000495916', 'lastCheck': '9.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00103978', 'lastCheck': '4.6', 'valid': True}}
>Thread-206762::DEBUG::2013-12-16 13:45:15,978::task::1168::TaskManager.Task::(prepare) Task=`b72a8b7e-a57b-4dd4-a139-e2e0d38793d7`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000495916', 'lastCheck': '9.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00103978', 'lastCheck': '4.6', 'valid': True}}
>Thread-206762::DEBUG::2013-12-16 13:45:15,978::task::579::TaskManager.Task::(_updateState) Task=`b72a8b7e-a57b-4dd4-a139-e2e0d38793d7`::moving from state preparing -> state finished
>Thread-206762::DEBUG::2013-12-16 13:45:15,979::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206762::DEBUG::2013-12-16 13:45:15,979::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206762::DEBUG::2013-12-16 13:45:15,979::task::974::TaskManager.Task::(_decref) Task=`b72a8b7e-a57b-4dd4-a139-e2e0d38793d7`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:45:16,941::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:45:16,956::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000537222 s, 3.5 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:45:21,377::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:21,391::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00102312 s, 4.0 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:45:26,966::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:45:26,980::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000932976 s, 2.0 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:45:31,396::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:31,415::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00100318 s, 4.1 MB/s\n'; <rc> = 0
>Thread-206768::DEBUG::2013-12-16 13:45:31,550::task::579::TaskManager.Task::(_updateState) Task=`c36e3345-7dc9-407e-9cbc-8fb50477c4dd`::moving from state init -> state preparing
>Thread-206768::INFO::2013-12-16 13:45:31,550::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206768::INFO::2013-12-16 13:45:31,550::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000932976', 'lastCheck': '4.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00100318', 'lastCheck': '0.1', 'valid': True}}
>Thread-206768::DEBUG::2013-12-16 13:45:31,551::task::1168::TaskManager.Task::(prepare) Task=`c36e3345-7dc9-407e-9cbc-8fb50477c4dd`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000932976', 'lastCheck': '4.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00100318', 'lastCheck': '0.1', 'valid': True}}
>Thread-206768::DEBUG::2013-12-16 13:45:31,551::task::579::TaskManager.Task::(_updateState) Task=`c36e3345-7dc9-407e-9cbc-8fb50477c4dd`::moving from state preparing -> state finished
>Thread-206768::DEBUG::2013-12-16 13:45:31,551::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206768::DEBUG::2013-12-16 13:45:31,551::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206768::DEBUG::2013-12-16 13:45:31,551::task::974::TaskManager.Task::(_decref) Task=`c36e3345-7dc9-407e-9cbc-8fb50477c4dd`::ref 0 aborting False
>VM Channels Listener::DEBUG::2013-12-16 13:45:32,760::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:45:36,991::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:45:37,006::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000478957 s, 3.9 MB/s\n'; <rc> = 0
>Thread-73240::DEBUG::2013-12-16 13:45:39,453::task::579::TaskManager.Task::(_updateState) Task=`aa4d1e65-082b-4f99-af3e-68737925e40f`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:45:39,453::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:45:39,454::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:45:39,454::task::1168::TaskManager.Task::(prepare) Task=`aa4d1e65-082b-4f99-af3e-68737925e40f`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:45:39,454::task::579::TaskManager.Task::(_updateState) Task=`aa4d1e65-082b-4f99-af3e-68737925e40f`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:45:39,454::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:45:39,454::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:45:39,454::task::974::TaskManager.Task::(_decref) Task=`aa4d1e65-082b-4f99-af3e-68737925e40f`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:45:41,422::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:41,435::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000807638 s, 5.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:45:47,022::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:45:47,035::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000478998 s, 3.9 MB/s\n'; <rc> = 0
>Thread-206774::DEBUG::2013-12-16 13:45:47,123::task::579::TaskManager.Task::(_updateState) Task=`a5f9a259-875f-4b93-9321-dd1595a77d7e`::moving from state init -> state preparing
>Thread-206774::INFO::2013-12-16 13:45:47,124::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206774::INFO::2013-12-16 13:45:47,124::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000478998', 'lastCheck': '0.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000807638', 'lastCheck': '5.7', 'valid': True}}
>Thread-206774::DEBUG::2013-12-16 13:45:47,124::task::1168::TaskManager.Task::(prepare) Task=`a5f9a259-875f-4b93-9321-dd1595a77d7e`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000478998', 'lastCheck': '0.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000807638', 'lastCheck': '5.7', 'valid': True}}
>Thread-206774::DEBUG::2013-12-16 13:45:47,124::task::579::TaskManager.Task::(_updateState) Task=`a5f9a259-875f-4b93-9321-dd1595a77d7e`::moving from state preparing -> state finished
>Thread-206774::DEBUG::2013-12-16 13:45:47,125::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206774::DEBUG::2013-12-16 13:45:47,125::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206774::DEBUG::2013-12-16 13:45:47,125::task::974::TaskManager.Task::(_decref) Task=`a5f9a259-875f-4b93-9321-dd1595a77d7e`::ref 0 aborting False
>Thread-206525::DEBUG::2013-12-16 13:45:48,957::task::579::TaskManager.Task::(_updateState) Task=`9b1f639e-6d05-4825-9cdc-de0ec467da2a`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:45:48,958::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:45:48,958::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:45:48,959::task::1168::TaskManager.Task::(prepare) Task=`9b1f639e-6d05-4825-9cdc-de0ec467da2a`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:45:48,959::task::579::TaskManager.Task::(_updateState) Task=`9b1f639e-6d05-4825-9cdc-de0ec467da2a`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:45:48,959::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:45:48,959::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:45:48,959::task::974::TaskManager.Task::(_decref) Task=`9b1f639e-6d05-4825-9cdc-de0ec467da2a`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:45:51,441::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:45:51,455::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00101415 s, 4.0 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:45:57,044::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:45:57,056::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.0007212 s, 2.6 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:46:01,461::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:46:01,474::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000915249 s, 4.5 MB/s\n'; <rc> = 0
>Thread-206780::DEBUG::2013-12-16 13:46:02,679::task::579::TaskManager.Task::(_updateState) Task=`e3fcafca-b7c8-41f3-be85-9a15c9762209`::moving from state init -> state preparing
>Thread-206780::INFO::2013-12-16 13:46:02,680::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206780::INFO::2013-12-16 13:46:02,680::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0007212', 'lastCheck': '5.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000915249', 'lastCheck': '1.2', 'valid': True}}
>Thread-206780::DEBUG::2013-12-16 13:46:02,680::task::1168::TaskManager.Task::(prepare) Task=`e3fcafca-b7c8-41f3-be85-9a15c9762209`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0007212', 'lastCheck': '5.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000915249', 'lastCheck': '1.2', 'valid': True}}
>Thread-206780::DEBUG::2013-12-16 13:46:02,680::task::579::TaskManager.Task::(_updateState) Task=`e3fcafca-b7c8-41f3-be85-9a15c9762209`::moving from state preparing -> state finished
>Thread-206780::DEBUG::2013-12-16 13:46:02,680::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206780::DEBUG::2013-12-16 13:46:02,680::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206780::DEBUG::2013-12-16 13:46:02,681::task::974::TaskManager.Task::(_decref) Task=`e3fcafca-b7c8-41f3-be85-9a15c9762209`::ref 0 aborting False
>VM Channels Listener::DEBUG::2013-12-16 13:46:03,542::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:46:07,066::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:46:07,078::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000589903 s, 3.2 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:46:11,479::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:46:11,493::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000989174 s, 4.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:46:17,088::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:46:17,101::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000755896 s, 2.5 MB/s\n'; <rc> = 0
>Thread-206786::DEBUG::2013-12-16 13:46:18,237::task::579::TaskManager.Task::(_updateState) Task=`a44e7ffb-3165-4050-a818-1c238fdf176f`::moving from state init -> state preparing
>Thread-206786::INFO::2013-12-16 13:46:18,237::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206786::INFO::2013-12-16 13:46:18,238::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000755896', 'lastCheck': '1.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000989174', 'lastCheck': '6.7', 'valid': True}}
>Thread-206786::DEBUG::2013-12-16 13:46:18,238::task::1168::TaskManager.Task::(prepare) Task=`a44e7ffb-3165-4050-a818-1c238fdf176f`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000755896', 'lastCheck': '1.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000989174', 'lastCheck': '6.7', 'valid': True}}
>Thread-206786::DEBUG::2013-12-16 13:46:18,238::task::579::TaskManager.Task::(_updateState) Task=`a44e7ffb-3165-4050-a818-1c238fdf176f`::moving from state preparing -> state finished
>Thread-206786::DEBUG::2013-12-16 13:46:18,238::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206786::DEBUG::2013-12-16 13:46:18,238::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206786::DEBUG::2013-12-16 13:46:18,238::task::974::TaskManager.Task::(_decref) Task=`a44e7ffb-3165-4050-a818-1c238fdf176f`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:46:21,499::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:46:21,512::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000948154 s, 4.3 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:46:27,111::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:46:27,123::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000560259 s, 3.4 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:46:31,518::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:46:31,531::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000941022 s, 4.4 MB/s\n'; <rc> = 0
>Thread-206792::DEBUG::2013-12-16 13:46:33,845::task::579::TaskManager.Task::(_updateState) Task=`2a7acb43-38df-4ca5-83e5-5871414e5cb2`::moving from state init -> state preparing
>Thread-206792::INFO::2013-12-16 13:46:33,846::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206792::INFO::2013-12-16 13:46:33,846::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000560259', 'lastCheck': '6.7', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000941022', 'lastCheck': '2.3', 'valid': True}}
>Thread-206792::DEBUG::2013-12-16 13:46:33,846::task::1168::TaskManager.Task::(prepare) Task=`2a7acb43-38df-4ca5-83e5-5871414e5cb2`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000560259', 'lastCheck': '6.7', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000941022', 'lastCheck': '2.3', 'valid': True}}
>Thread-206792::DEBUG::2013-12-16 13:46:33,846::task::579::TaskManager.Task::(_updateState) Task=`2a7acb43-38df-4ca5-83e5-5871414e5cb2`::moving from state preparing -> state finished
>Thread-206792::DEBUG::2013-12-16 13:46:33,846::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206792::DEBUG::2013-12-16 13:46:33,846::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206792::DEBUG::2013-12-16 13:46:33,847::task::974::TaskManager.Task::(_decref) Task=`2a7acb43-38df-4ca5-83e5-5871414e5cb2`::ref 0 aborting False
>VM Channels Listener::DEBUG::2013-12-16 13:46:34,353::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:46:37,133::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:46:37,145::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000690384 s, 2.7 MB/s\n'; <rc> = 0
>Thread-73240::DEBUG::2013-12-16 13:46:39,520::task::579::TaskManager.Task::(_updateState) Task=`6d2cc29c-2ec6-4bb5-a1fa-0d0a3dddf92a`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:46:39,521::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:46:39,521::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:46:39,521::task::1168::TaskManager.Task::(prepare) Task=`6d2cc29c-2ec6-4bb5-a1fa-0d0a3dddf92a`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:46:39,521::task::579::TaskManager.Task::(_updateState) Task=`6d2cc29c-2ec6-4bb5-a1fa-0d0a3dddf92a`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:46:39,521::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:46:39,522::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:46:39,522::task::974::TaskManager.Task::(_decref) Task=`6d2cc29c-2ec6-4bb5-a1fa-0d0a3dddf92a`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:46:41,537::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:46:41,551::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000962843 s, 4.3 MB/s\n'; <rc> = 0
>Thread-206796::DEBUG::2013-12-16 13:46:42,723::BindingXMLRPC::984::vds::(wrapper) client [10.19.168.60]::call vmSetTicket with ('3daf11f5-f831-452c-bad4-3d67886177cc', '5pbKGwJuuxnm', '120', 'disconnect', {'userName': 'rhevmadmin', 'userId': '470ff1cd-9e2a-4cc2-bd96-85b87c6d18f0'}) {} flowID [2ac8de22]
>libvirtEventLoop::DEBUG::2013-12-16 13:46:42,733::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.18.25.159', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:42,734::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.18.25.159', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:42,735::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.18.25.159', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:42,737::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.18.25.159', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:42,739::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.18.25.159', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:42,739::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.18.25.159', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:42,771::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.18.25.159', 'service': '', 'family': 0}authScheme  subject []
>Thread-206796::DEBUG::2013-12-16 13:46:42,771::BindingXMLRPC::991::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>libvirtEventLoop::DEBUG::2013-12-16 13:46:44,186::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>Thread-206797::DEBUG::2013-12-16 13:46:44,735::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206798::DEBUG::2013-12-16 13:46:44,735::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206799::DEBUG::2013-12-16 13:46:44,736::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206800::DEBUG::2013-12-16 13:46:44,738::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206801::DEBUG::2013-12-16 13:46:44,739::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206802::DEBUG::2013-12-16 13:46:44,740::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206803::DEBUG::2013-12-16 13:46:44,773::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,046::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,095::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,096::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,096::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,201::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,204::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,205::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,576::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,577::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,723::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:46:45,724::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>Thread-504::DEBUG::2013-12-16 13:46:47,157::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:46:47,173::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000470683 s, 4.0 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:46:49,052::task::579::TaskManager.Task::(_updateState) Task=`0e888cbe-121f-4f2c-b402-077ee4a15cea`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:46:49,052::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:46:49,053::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:46:49,053::task::1168::TaskManager.Task::(prepare) Task=`0e888cbe-121f-4f2c-b402-077ee4a15cea`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:46:49,053::task::579::TaskManager.Task::(_updateState) Task=`0e888cbe-121f-4f2c-b402-077ee4a15cea`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:46:49,053::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:46:49,053::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:46:49,053::task::974::TaskManager.Task::(_decref) Task=`0e888cbe-121f-4f2c-b402-077ee4a15cea`::ref 0 aborting False
>Thread-206806::DEBUG::2013-12-16 13:46:49,465::task::579::TaskManager.Task::(_updateState) Task=`4632ac73-51e5-4352-b225-40ccad1e9542`::moving from state init -> state preparing
>Thread-206806::INFO::2013-12-16 13:46:49,465::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206806::INFO::2013-12-16 13:46:49,465::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000470683', 'lastCheck': '2.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000962843', 'lastCheck': '7.9', 'valid': True}}
>Thread-206806::DEBUG::2013-12-16 13:46:49,465::task::1168::TaskManager.Task::(prepare) Task=`4632ac73-51e5-4352-b225-40ccad1e9542`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000470683', 'lastCheck': '2.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000962843', 'lastCheck': '7.9', 'valid': True}}
>Thread-206806::DEBUG::2013-12-16 13:46:49,465::task::579::TaskManager.Task::(_updateState) Task=`4632ac73-51e5-4352-b225-40ccad1e9542`::moving from state preparing -> state finished
>Thread-206806::DEBUG::2013-12-16 13:46:49,465::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206806::DEBUG::2013-12-16 13:46:49,466::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206806::DEBUG::2013-12-16 13:46:49,466::task::974::TaskManager.Task::(_decref) Task=`4632ac73-51e5-4352-b225-40ccad1e9542`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:46:51,557::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:46:51,571::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000741467 s, 5.5 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:46:57,186::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:46:57,198::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000492179 s, 3.8 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:47:01,577::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:47:01,590::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00098841 s, 4.1 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:47:04,840::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-206812::DEBUG::2013-12-16 13:47:04,997::task::579::TaskManager.Task::(_updateState) Task=`730822bb-e007-49f6-a8fb-78a50aef17ca`::moving from state init -> state preparing
>Thread-206812::INFO::2013-12-16 13:47:04,997::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206812::INFO::2013-12-16 13:47:04,998::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000492179', 'lastCheck': '7.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00098841', 'lastCheck': '3.4', 'valid': True}}
>Thread-206812::DEBUG::2013-12-16 13:47:04,998::task::1168::TaskManager.Task::(prepare) Task=`730822bb-e007-49f6-a8fb-78a50aef17ca`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000492179', 'lastCheck': '7.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00098841', 'lastCheck': '3.4', 'valid': True}}
>Thread-206812::DEBUG::2013-12-16 13:47:04,998::task::579::TaskManager.Task::(_updateState) Task=`730822bb-e007-49f6-a8fb-78a50aef17ca`::moving from state preparing -> state finished
>Thread-206812::DEBUG::2013-12-16 13:47:04,998::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206812::DEBUG::2013-12-16 13:47:04,998::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206812::DEBUG::2013-12-16 13:47:04,998::task::974::TaskManager.Task::(_decref) Task=`730822bb-e007-49f6-a8fb-78a50aef17ca`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:47:07,210::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:47:07,223::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000505388 s, 3.7 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:47:11,596::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:47:11,609::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000961888 s, 4.3 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:47:17,231::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:47:17,244::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.00150112 s, 1.3 MB/s\n'; <rc> = 0
>Thread-206818::DEBUG::2013-12-16 13:47:20,548::task::579::TaskManager.Task::(_updateState) Task=`c7e0bc3b-18b4-4f48-97e3-9365b885e5e4`::moving from state init -> state preparing
>Thread-206818::INFO::2013-12-16 13:47:20,549::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206818::INFO::2013-12-16 13:47:20,549::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00150112', 'lastCheck': '3.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000961888', 'lastCheck': '8.9', 'valid': True}}
>Thread-206818::DEBUG::2013-12-16 13:47:20,549::task::1168::TaskManager.Task::(prepare) Task=`c7e0bc3b-18b4-4f48-97e3-9365b885e5e4`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00150112', 'lastCheck': '3.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000961888', 'lastCheck': '8.9', 'valid': True}}
>Thread-206818::DEBUG::2013-12-16 13:47:20,549::task::579::TaskManager.Task::(_updateState) Task=`c7e0bc3b-18b4-4f48-97e3-9365b885e5e4`::moving from state preparing -> state finished
>Thread-206818::DEBUG::2013-12-16 13:47:20,549::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206818::DEBUG::2013-12-16 13:47:20,549::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206818::DEBUG::2013-12-16 13:47:20,550::task::974::TaskManager.Task::(_decref) Task=`c7e0bc3b-18b4-4f48-97e3-9365b885e5e4`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:47:21,615::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:47:21,628::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000979665 s, 4.2 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:47:27,253::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:47:27,265::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000576822 s, 3.3 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2013-12-16 13:47:28,707::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:47:28,708::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:47:28,709::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:47:28,709::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:47:28,710::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:47:28,710::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:47:28,711::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 2 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>Thread-206822::DEBUG::2013-12-16 13:47:30,708::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206823::DEBUG::2013-12-16 13:47:30,708::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206824::DEBUG::2013-12-16 13:47:30,710::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206825::DEBUG::2013-12-16 13:47:30,710::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206826::DEBUG::2013-12-16 13:47:30,710::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206827::DEBUG::2013-12-16 13:47:30,711::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-206828::DEBUG::2013-12-16 13:47:30,711::guestIF::278::vm.Vm::(desktopLock) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::desktopLock called
>Thread-244::DEBUG::2013-12-16 13:47:31,634::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:47:31,647::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00080385 s, 5.1 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:47:35,620::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-206831::DEBUG::2013-12-16 13:47:36,254::task::579::TaskManager.Task::(_updateState) Task=`f8c3160e-c35f-46b6-9f4e-4d6ac00107e4`::moving from state init -> state preparing
>Thread-206831::INFO::2013-12-16 13:47:36,254::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206831::INFO::2013-12-16 13:47:36,254::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000576822', 'lastCheck': '9.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00080385', 'lastCheck': '4.6', 'valid': True}}
>Thread-206831::DEBUG::2013-12-16 13:47:36,254::task::1168::TaskManager.Task::(prepare) Task=`f8c3160e-c35f-46b6-9f4e-4d6ac00107e4`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000576822', 'lastCheck': '9.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00080385', 'lastCheck': '4.6', 'valid': True}}
>Thread-206831::DEBUG::2013-12-16 13:47:36,254::task::579::TaskManager.Task::(_updateState) Task=`f8c3160e-c35f-46b6-9f4e-4d6ac00107e4`::moving from state preparing -> state finished
>Thread-206831::DEBUG::2013-12-16 13:47:36,254::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206831::DEBUG::2013-12-16 13:47:36,255::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206831::DEBUG::2013-12-16 13:47:36,255::task::974::TaskManager.Task::(_decref) Task=`f8c3160e-c35f-46b6-9f4e-4d6ac00107e4`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:47:37,274::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:47:37,289::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000495701 s, 3.8 MB/s\n'; <rc> = 0
>Thread-73240::DEBUG::2013-12-16 13:47:39,585::task::579::TaskManager.Task::(_updateState) Task=`658a17c8-6ebc-424f-b8a1-c0be0dcb309c`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:47:39,585::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:47:39,586::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:47:39,586::task::1168::TaskManager.Task::(prepare) Task=`658a17c8-6ebc-424f-b8a1-c0be0dcb309c`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:47:39,586::task::579::TaskManager.Task::(_updateState) Task=`658a17c8-6ebc-424f-b8a1-c0be0dcb309c`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:47:39,586::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:47:39,586::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:47:39,586::task::974::TaskManager.Task::(_decref) Task=`658a17c8-6ebc-424f-b8a1-c0be0dcb309c`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:47:41,653::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:47:41,667::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000947229 s, 4.3 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:47:47,300::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:47:47,313::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000718412 s, 2.6 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:47:49,118::task::579::TaskManager.Task::(_updateState) Task=`9ced1619-b25e-4361-9e98-47e94be19b9d`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:47:49,118::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:47:49,119::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:47:49,119::task::1168::TaskManager.Task::(prepare) Task=`9ced1619-b25e-4361-9e98-47e94be19b9d`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:47:49,119::task::579::TaskManager.Task::(_updateState) Task=`9ced1619-b25e-4361-9e98-47e94be19b9d`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:47:49,119::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:47:49,120::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:47:49,120::task::974::TaskManager.Task::(_decref) Task=`9ced1619-b25e-4361-9e98-47e94be19b9d`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:47:51,672::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:47:51,686::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00097527 s, 4.2 MB/s\n'; <rc> = 0
>Thread-206837::DEBUG::2013-12-16 13:47:51,829::task::579::TaskManager.Task::(_updateState) Task=`1d11c7bf-6a93-4ca4-bee6-6b9b39bbbc3c`::moving from state init -> state preparing
>Thread-206837::INFO::2013-12-16 13:47:51,829::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206837::INFO::2013-12-16 13:47:51,829::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000718412', 'lastCheck': '4.5', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00097527', 'lastCheck': '0.1', 'valid': True}}
>Thread-206837::DEBUG::2013-12-16 13:47:51,829::task::1168::TaskManager.Task::(prepare) Task=`1d11c7bf-6a93-4ca4-bee6-6b9b39bbbc3c`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000718412', 'lastCheck': '4.5', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00097527', 'lastCheck': '0.1', 'valid': True}}
>Thread-206837::DEBUG::2013-12-16 13:47:51,829::task::579::TaskManager.Task::(_updateState) Task=`1d11c7bf-6a93-4ca4-bee6-6b9b39bbbc3c`::moving from state preparing -> state finished
>Thread-206837::DEBUG::2013-12-16 13:47:51,830::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206837::DEBUG::2013-12-16 13:47:51,830::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206837::DEBUG::2013-12-16 13:47:51,830::task::974::TaskManager.Task::(_decref) Task=`1d11c7bf-6a93-4ca4-bee6-6b9b39bbbc3c`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:47:57,322::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:47:57,335::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000470876 s, 4.0 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:48:01,692::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:48:01,705::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000960754 s, 4.3 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:48:06,401::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:48:07,344::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:48:07,357::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000442425 s, 4.2 MB/s\n'; <rc> = 0
>Thread-206843::DEBUG::2013-12-16 13:48:07,439::task::579::TaskManager.Task::(_updateState) Task=`8838f124-b265-4f22-8d3f-3ab66c522a61`::moving from state init -> state preparing
>Thread-206843::INFO::2013-12-16 13:48:07,440::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206843::INFO::2013-12-16 13:48:07,440::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000442425', 'lastCheck': '0.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000960754', 'lastCheck': '5.7', 'valid': True}}
>Thread-206843::DEBUG::2013-12-16 13:48:07,440::task::1168::TaskManager.Task::(prepare) Task=`8838f124-b265-4f22-8d3f-3ab66c522a61`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000442425', 'lastCheck': '0.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000960754', 'lastCheck': '5.7', 'valid': True}}
>Thread-206843::DEBUG::2013-12-16 13:48:07,440::task::579::TaskManager.Task::(_updateState) Task=`8838f124-b265-4f22-8d3f-3ab66c522a61`::moving from state preparing -> state finished
>Thread-206843::DEBUG::2013-12-16 13:48:07,440::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206843::DEBUG::2013-12-16 13:48:07,440::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206843::DEBUG::2013-12-16 13:48:07,441::task::974::TaskManager.Task::(_decref) Task=`8838f124-b265-4f22-8d3f-3ab66c522a61`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:48:11,711::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:48:11,724::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000898225 s, 4.6 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:48:17,366::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:48:17,378::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000472969 s, 4.0 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:48:21,730::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:48:21,744::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00105796 s, 3.9 MB/s\n'; <rc> = 0
>Thread-206849::DEBUG::2013-12-16 13:48:23,036::task::579::TaskManager.Task::(_updateState) Task=`e92fdef7-bfdf-4abf-ab1a-f5033a721041`::moving from state init -> state preparing
>Thread-206849::INFO::2013-12-16 13:48:23,037::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206849::INFO::2013-12-16 13:48:23,037::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000472969', 'lastCheck': '5.7', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00105796', 'lastCheck': '1.3', 'valid': True}}
>Thread-206849::DEBUG::2013-12-16 13:48:23,037::task::1168::TaskManager.Task::(prepare) Task=`e92fdef7-bfdf-4abf-ab1a-f5033a721041`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000472969', 'lastCheck': '5.7', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00105796', 'lastCheck': '1.3', 'valid': True}}
>Thread-206849::DEBUG::2013-12-16 13:48:23,037::task::579::TaskManager.Task::(_updateState) Task=`e92fdef7-bfdf-4abf-ab1a-f5033a721041`::moving from state preparing -> state finished
>Thread-206849::DEBUG::2013-12-16 13:48:23,037::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206849::DEBUG::2013-12-16 13:48:23,038::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206849::DEBUG::2013-12-16 13:48:23,038::task::974::TaskManager.Task::(_decref) Task=`e92fdef7-bfdf-4abf-ab1a-f5033a721041`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:48:27,387::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:48:27,400::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000449202 s, 4.2 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:48:31,750::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:48:31,763::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00081019 s, 5.1 MB/s\n'; <rc> = 0
>Thread-206855::DEBUG::2013-12-16 13:48:36,253::BindingXMLRPC::984::vds::(wrapper) client [10.19.168.60]::call vmSetTicket with ('3daf11f5-f831-452c-bad4-3d67886177cc', 'ln+NoZoM5HlM', '120', 'disconnect', {'userName': 'rhevmadmin', 'userId': '470ff1cd-9e2a-4cc2-bd96-85b87c6d18f0'}) {} flowID [4586a930]
>Thread-206855::DEBUG::2013-12-16 13:48:36,299::BindingXMLRPC::991::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>VM Channels Listener::DEBUG::2013-12-16 13:48:37,213::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-504::DEBUG::2013-12-16 13:48:37,408::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:48:37,421::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000495729 s, 3.8 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2013-12-16 13:48:37,755::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>Thread-206856::DEBUG::2013-12-16 13:48:38,629::task::579::TaskManager.Task::(_updateState) Task=`fdb74783-f969-4c76-ba98-968ba6134e96`::moving from state init -> state preparing
>Thread-206856::INFO::2013-12-16 13:48:38,630::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206856::INFO::2013-12-16 13:48:38,630::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000495729', 'lastCheck': '1.2', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00081019', 'lastCheck': '6.9', 'valid': True}}
>Thread-206856::DEBUG::2013-12-16 13:48:38,630::task::1168::TaskManager.Task::(prepare) Task=`fdb74783-f969-4c76-ba98-968ba6134e96`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000495729', 'lastCheck': '1.2', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00081019', 'lastCheck': '6.9', 'valid': True}}
>Thread-206856::DEBUG::2013-12-16 13:48:38,630::task::579::TaskManager.Task::(_updateState) Task=`fdb74783-f969-4c76-ba98-968ba6134e96`::moving from state preparing -> state finished
>Thread-206856::DEBUG::2013-12-16 13:48:38,630::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206856::DEBUG::2013-12-16 13:48:38,630::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206856::DEBUG::2013-12-16 13:48:38,631::task::974::TaskManager.Task::(_decref) Task=`fdb74783-f969-4c76-ba98-968ba6134e96`::ref 0 aborting False
>libvirtEventLoop::DEBUG::2013-12-16 13:48:38,962::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,013::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,013::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,014::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,140::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,144::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,145::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>Thread-73240::DEBUG::2013-12-16 13:48:39,646::task::579::TaskManager.Task::(_updateState) Task=`93454572-b4a7-432a-8fe7-2d980ba70b58`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:48:39,647::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:48:39,647::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:48:39,647::task::1168::TaskManager.Task::(prepare) Task=`93454572-b4a7-432a-8fe7-2d980ba70b58`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:48:39,647::task::579::TaskManager.Task::(_updateState) Task=`93454572-b4a7-432a-8fe7-2d980ba70b58`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:48:39,647::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:48:39,647::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:48:39,648::task::974::TaskManager.Task::(_decref) Task=`93454572-b4a7-432a-8fe7-2d980ba70b58`::ref 0 aborting False
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,798::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,798::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 0 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,862::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2013-12-16 13:48:39,863::clientIF::583::vm.Vm::(dispatchLibvirtEvents) vmId=`3daf11f5-f831-452c-bad4-3d67886177cc`::graphics event phase 1 localAddr {'node': '10.19.168.12', 'service': '', 'family': 0} remoteAddr {'node': '10.19.24.65', 'service': '', 'family': 0}authScheme spice subject []
>Thread-244::DEBUG::2013-12-16 13:48:41,769::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:48:41,782::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000844823 s, 4.8 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:48:47,431::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:48:47,444::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000533755 s, 3.5 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:48:49,184::task::579::TaskManager.Task::(_updateState) Task=`097da631-ed5c-4fe2-b559-07a995dd53ca`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:48:49,185::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:48:49,185::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:48:49,185::task::1168::TaskManager.Task::(prepare) Task=`097da631-ed5c-4fe2-b559-07a995dd53ca`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:48:49,185::task::579::TaskManager.Task::(_updateState) Task=`097da631-ed5c-4fe2-b559-07a995dd53ca`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:48:49,186::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:48:49,186::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:48:49,186::task::974::TaskManager.Task::(_decref) Task=`097da631-ed5c-4fe2-b559-07a995dd53ca`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:48:51,787::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:48:51,801::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000965927 s, 4.2 MB/s\n'; <rc> = 0
>Thread-206862::DEBUG::2013-12-16 13:48:54,197::task::579::TaskManager.Task::(_updateState) Task=`ba387c8d-3fdd-4428-bb65-7e1a3cb2277e`::moving from state init -> state preparing
>Thread-206862::INFO::2013-12-16 13:48:54,197::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206862::INFO::2013-12-16 13:48:54,197::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000533755', 'lastCheck': '6.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000965927', 'lastCheck': '2.4', 'valid': True}}
>Thread-206862::DEBUG::2013-12-16 13:48:54,198::task::1168::TaskManager.Task::(prepare) Task=`ba387c8d-3fdd-4428-bb65-7e1a3cb2277e`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000533755', 'lastCheck': '6.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000965927', 'lastCheck': '2.4', 'valid': True}}
>Thread-206862::DEBUG::2013-12-16 13:48:54,198::task::579::TaskManager.Task::(_updateState) Task=`ba387c8d-3fdd-4428-bb65-7e1a3cb2277e`::moving from state preparing -> state finished
>Thread-206862::DEBUG::2013-12-16 13:48:54,198::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206862::DEBUG::2013-12-16 13:48:54,198::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206862::DEBUG::2013-12-16 13:48:54,198::task::974::TaskManager.Task::(_decref) Task=`ba387c8d-3fdd-4428-bb65-7e1a3cb2277e`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:48:57,446::domainMonitor::188::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain e1a50b62-693a-412c-bffd-2c9147e4c5b4
>Thread-504::DEBUG::2013-12-16 13:48:57,450::fileSD::154::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4
>Thread-504::DEBUG::2013-12-16 13:48:57,452::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-504::DEBUG::2013-12-16 13:48:57,459::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=isos', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=a0880a4b-2521-4b53-91b1-6d77bccb812c,a33409d2-b875-11e0-8078-eba376b6e797,8c9e3d88-47ac-4826-9a67-c48a70354c85,23e39e7b-bf33-4a0c-8171-dfe0ac2ec7cc,fc66a0ea-bd17-11e0-8e80-52540051f51d,53552856-c2a7-11e0-8ff2-9feb3da58e93,ebc8cf69-e092-44a8-8b01-80240f2952c7,d09f7dfa-d334-11e0-9d73-a37c621ee5cf,c7f97418-e2fb-4cc3-a6a5-b0d4019b5c48,af1f0a6a-da32-11e0-82ee-db1931649314,7cccaa60-e54d-11e0-a0e3-ef56a5ce5e14,5426b244-79d9-4a24-a405-d4bfa3610e4b,4e09e544-7c4b-4a3b-931e-2bca1b3296d6,1501daa3-c851-4285-a79f-3c661e20ea78,9cccfedc-f8ee-11e0-8c1c-7bd4edc156ae,137e7558-0955-11e1-8cf5-525400aec2e1,5f3bfe02-146d-11e1-8c23-52540051e8ec,5399c070-1ac1-11e1-abaa-52540057dbfb,c00b2366-269c-11e1-b5ff-525400484308,bf2014aa-2bee-11e1-8a85-bf0c48e787d5,de352855-8f6a-409d-aa63-64c43a23ca22,7624bbe4-6dec-11e1-beb0-5254001dd915,35330d20-6ecd-11e1-85d0-525400b635c2,85459dae-7379-11e1-ae61-5254003ce2cf,17f6f60d-3167-4c12-b5f3-181415fc0828,5fb2e0da-9302-11e1-b018-52540053bfec,894380b7-c07f-4ad6-9ff8-e3c77bea2fad,6a27df7e-9aa6-11e1-a60e-52540053bfec,ebc98b96-a4fa-11e1-99ff-52540053bfec,1b5da69e-eaec-11e1-99c2-52540053bfec,38cea776-f1fb-11e1-9c9f-52540053bfec,43022794-fb48-11e1-8729-52540053bfec,48d1432c-01c3-11e2-b084-52540053bfec,3119f92e-0324-11e2-968f-52540053bfec,efe1a784-072b-11e2-b747-52540053bfec,72a604c2-1239-11e2-9d40-52540053bfec,8c80424e-29b9-11e2-a3cb-52540053bfec,2ed6ea74-38a7-11e2-b078-52540053bfec,1860a536-3984-11e2-ba68-52540053bfec,8ef05a52-3eed-11e2-a9ba-52540065f8a4,c0c90026-ac0f-11e2-acc0-52540065f8a4,5849b030-626e-47cb-ad90-3ce782d831b3', 'REMOTE_PATH=storage.spice.lab.eng.bos.redhat.com:/rhev/isos', 'ROLE=Regular', 'SDUUID=e1a50b62-693a-412c-bffd-2c9147e4c5b4', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=17678220953f2c63e342af10e676a46e923ffc65']
>Thread-504::DEBUG::2013-12-16 13:48:57,461::fileSD::572::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-504::INFO::2013-12-16 13:48:57,461::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace e1a50b62-693a-412c-bffd-2c9147e4c5b4_imageNS already registered
>Thread-504::INFO::2013-12-16 13:48:57,461::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace e1a50b62-693a-412c-bffd-2c9147e4c5b4_volumeNS already registered
>Thread-504::DEBUG::2013-12-16 13:48:57,467::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:48:57,480::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000485463 s, 3.9 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:49:01,807::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:49:01,820::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000958477 s, 4.3 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:49:07,488::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:49:07,501::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000485893 s, 3.9 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:49:07,993::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-206869::DEBUG::2013-12-16 13:49:09,767::task::579::TaskManager.Task::(_updateState) Task=`9ce0cc67-7f22-4d0e-bf5e-9948c2e6b6cd`::moving from state init -> state preparing
>Thread-206869::INFO::2013-12-16 13:49:09,767::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206869::INFO::2013-12-16 13:49:09,767::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000485893', 'lastCheck': '2.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000958477', 'lastCheck': '7.9', 'valid': True}}
>Thread-206869::DEBUG::2013-12-16 13:49:09,767::task::1168::TaskManager.Task::(prepare) Task=`9ce0cc67-7f22-4d0e-bf5e-9948c2e6b6cd`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000485893', 'lastCheck': '2.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000958477', 'lastCheck': '7.9', 'valid': True}}
>Thread-206869::DEBUG::2013-12-16 13:49:09,767::task::579::TaskManager.Task::(_updateState) Task=`9ce0cc67-7f22-4d0e-bf5e-9948c2e6b6cd`::moving from state preparing -> state finished
>Thread-206869::DEBUG::2013-12-16 13:49:09,767::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206869::DEBUG::2013-12-16 13:49:09,768::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206869::DEBUG::2013-12-16 13:49:09,768::task::974::TaskManager.Task::(_decref) Task=`9ce0cc67-7f22-4d0e-bf5e-9948c2e6b6cd`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:49:11,826::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:49:11,840::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00125845 s, 3.3 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:49:17,510::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:49:17,523::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.00126513 s, 1.5 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:49:21,846::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:49:21,860::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000949444 s, 4.3 MB/s\n'; <rc> = 0
>Thread-206875::DEBUG::2013-12-16 13:49:25,338::task::579::TaskManager.Task::(_updateState) Task=`db70a4fb-d146-4461-b98b-6374661c0b6c`::moving from state init -> state preparing
>Thread-206875::INFO::2013-12-16 13:49:25,338::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206875::INFO::2013-12-16 13:49:25,338::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00126513', 'lastCheck': '7.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000949444', 'lastCheck': '3.5', 'valid': True}}
>Thread-206875::DEBUG::2013-12-16 13:49:25,338::task::1168::TaskManager.Task::(prepare) Task=`db70a4fb-d146-4461-b98b-6374661c0b6c`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00126513', 'lastCheck': '7.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000949444', 'lastCheck': '3.5', 'valid': True}}
>Thread-206875::DEBUG::2013-12-16 13:49:25,339::task::579::TaskManager.Task::(_updateState) Task=`db70a4fb-d146-4461-b98b-6374661c0b6c`::moving from state preparing -> state finished
>Thread-206875::DEBUG::2013-12-16 13:49:25,339::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206875::DEBUG::2013-12-16 13:49:25,339::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206875::DEBUG::2013-12-16 13:49:25,339::task::974::TaskManager.Task::(_decref) Task=`db70a4fb-d146-4461-b98b-6374661c0b6c`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:49:27,532::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:49:27,544::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000545429 s, 3.4 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:49:31,866::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:49:31,879::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000703077 s, 5.8 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:49:37,553::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:49:37,566::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000724182 s, 2.6 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:49:38,482::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-73240::DEBUG::2013-12-16 13:49:39,710::task::579::TaskManager.Task::(_updateState) Task=`94a3e82c-7846-409e-affd-77fd9ff75054`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:49:39,711::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:49:39,711::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:49:39,711::task::1168::TaskManager.Task::(prepare) Task=`94a3e82c-7846-409e-affd-77fd9ff75054`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:49:39,711::task::579::TaskManager.Task::(_updateState) Task=`94a3e82c-7846-409e-affd-77fd9ff75054`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:49:39,711::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:49:39,711::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:49:39,711::task::974::TaskManager.Task::(_decref) Task=`94a3e82c-7846-409e-affd-77fd9ff75054`::ref 0 aborting False
>Thread-206881::DEBUG::2013-12-16 13:49:40,890::task::579::TaskManager.Task::(_updateState) Task=`f382e061-e81f-4cd5-849f-af6542b73ade`::moving from state init -> state preparing
>Thread-206881::INFO::2013-12-16 13:49:40,890::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206881::INFO::2013-12-16 13:49:40,891::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000724182', 'lastCheck': '3.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000703077', 'lastCheck': '9.0', 'valid': True}}
>Thread-206881::DEBUG::2013-12-16 13:49:40,891::task::1168::TaskManager.Task::(prepare) Task=`f382e061-e81f-4cd5-849f-af6542b73ade`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000724182', 'lastCheck': '3.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000703077', 'lastCheck': '9.0', 'valid': True}}
>Thread-206881::DEBUG::2013-12-16 13:49:40,891::task::579::TaskManager.Task::(_updateState) Task=`f382e061-e81f-4cd5-849f-af6542b73ade`::moving from state preparing -> state finished
>Thread-206881::DEBUG::2013-12-16 13:49:40,891::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206881::DEBUG::2013-12-16 13:49:40,891::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206881::DEBUG::2013-12-16 13:49:40,891::task::974::TaskManager.Task::(_decref) Task=`f382e061-e81f-4cd5-849f-af6542b73ade`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:49:41,885::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:49:41,898::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00101745 s, 4.0 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:49:47,576::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:49:47,589::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.0005493 s, 3.4 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:49:49,250::task::579::TaskManager.Task::(_updateState) Task=`3552c218-550a-4fdf-9712-ad63adb601bc`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:49:49,250::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:49:49,251::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:49:49,251::task::1168::TaskManager.Task::(prepare) Task=`3552c218-550a-4fdf-9712-ad63adb601bc`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:49:49,251::task::579::TaskManager.Task::(_updateState) Task=`3552c218-550a-4fdf-9712-ad63adb601bc`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:49:49,251::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:49:49,251::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:49:49,251::task::974::TaskManager.Task::(_decref) Task=`3552c218-550a-4fdf-9712-ad63adb601bc`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:49:51,904::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:49:51,917::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000993865 s, 4.1 MB/s\n'; <rc> = 0
>Thread-206887::DEBUG::2013-12-16 13:49:56,461::task::579::TaskManager.Task::(_updateState) Task=`a59a33a4-6293-4cc6-8888-d0095f1f377c`::moving from state init -> state preparing
>Thread-206887::INFO::2013-12-16 13:49:56,461::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206887::INFO::2013-12-16 13:49:56,461::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0005493', 'lastCheck': '8.9', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000993865', 'lastCheck': '4.5', 'valid': True}}
>Thread-206887::DEBUG::2013-12-16 13:49:56,461::task::1168::TaskManager.Task::(prepare) Task=`a59a33a4-6293-4cc6-8888-d0095f1f377c`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0005493', 'lastCheck': '8.9', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000993865', 'lastCheck': '4.5', 'valid': True}}
>Thread-206887::DEBUG::2013-12-16 13:49:56,462::task::579::TaskManager.Task::(_updateState) Task=`a59a33a4-6293-4cc6-8888-d0095f1f377c`::moving from state preparing -> state finished
>Thread-206887::DEBUG::2013-12-16 13:49:56,462::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206887::DEBUG::2013-12-16 13:49:56,462::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206887::DEBUG::2013-12-16 13:49:56,462::task::974::TaskManager.Task::(_decref) Task=`a59a33a4-6293-4cc6-8888-d0095f1f377c`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:49:57,599::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:49:57,612::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000569843 s, 3.3 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:50:01,920::domainMonitor::188::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 75e24eb3-104c-451f-bf57-056b3b30ffba
>Thread-244::DEBUG::2013-12-16 13:50:01,922::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
>Thread-244::DEBUG::2013-12-16 13:50:01,932::blockSD::326::Storage.Misc.excCmd::(readlines) '/bin/dd iflag=direct skip=0 bs=2048 if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:01,946::blockSD::326::Storage.Misc.excCmd::(readlines) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.0009829 s, 2.1 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:50:01,946::misc::289::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.0009829 s, 2.1 MB/s'], size: 2048
>Thread-244::DEBUG::2013-12-16 13:50:01,947::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
>Thread-244::WARNING::2013-12-16 13:50:01,947::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-244::DEBUG::2013-12-16 13:50:01,947::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
>Thread-244::DEBUG::2013-12-16 13:50:01,947::lvm::516::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-244::DEBUG::2013-12-16 13:50:01,947::lvm::518::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-244::DEBUG::2013-12-16 13:50:01,948::lvm::526::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-244::DEBUG::2013-12-16 13:50:01,948::lvm::538::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-244::DEBUG::2013-12-16 13:50:01,948::lvm::386::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-244::DEBUG::2013-12-16 13:50:01,949::lvm::309::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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/1ATA_WDC_WD6400AAKS-22A7B2_WD-WCASYC833778|/dev/mapper/360a9800044306a31715d436c58414664|/dev/mapper/360a9800044306a31715d436c58414666|/dev/mapper/360a9800044306a31715d436c58414668|/dev/mapper/360a9800044306a31715d436c5841466a|/dev/mapper/360a9800044306a31715d436c5841466c|\', \'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 | --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name 75e24eb3-104c-451f-bf57-056b3b30ffba' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:02,328::lvm::309::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:50:02,330::lvm::428::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-244::DEBUG::2013-12-16 13:50:02,330::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['LEASETIMESEC=60', 'PHYBLKSIZE=4096', 'LOCKPOLICY=', 'VERSION=3', 'TYPE=ISCSI', 'SDUUID=75e24eb3-104c-451f-bf57-056b3b30ffba', 'LOGBLKSIZE=512', 'VGUUID=SuZ7tB-gRcV-4e5F-jzQe-OxhP-ZkVo-RaiyJZ', u'PV0=pv:360a9800044306a31715d436c58414664,uuid:ErDKs4-bAoU-ytRd-whqW-CJxW-J3Sr-lIBwBo,pestart:0,pecount:3998,mapoffset:0', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'DESCRIPTION=netapp-storage', 'CLASS=Data', 'POOL_UUID=5849b030-626e-47cb-ad90-3ce782d831b3', 'POOL_DESCRIPTION=Default', 'ROLE=Master', 'MASTER_VERSION=1', 'POOL_SPM_ID=2', u'POOL_DOMAINS=e1a50b62-693a-412c-bffd-2c9147e4c5b4:Active,75e24eb3-104c-451f-bf57-056b3b30ffba:Active', '_SHA_CKSUM=a730ad4fb83a066bcc5ddb89a1e6c148430342a6', 'POOL_SPM_LVER=1']
>Thread-244::INFO::2013-12-16 13:50:02,331::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 75e24eb3-104c-451f-bf57-056b3b30ffba_imageNS already registered
>Thread-244::INFO::2013-12-16 13:50:02,333::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 75e24eb3-104c-451f-bf57-056b3b30ffba_volumeNS already registered
>Thread-244::INFO::2013-12-16 13:50:02,334::blockSD::446::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 75e24eb3-104c-451f-bf57-056b3b30ffba_lvmActivationNS already registered
>Thread-244::DEBUG::2013-12-16 13:50:02,334::lvm::309::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/360a9800044306a31715d436c58414664|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " 75e24eb3-104c-451f-bf57-056b3b30ffba' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:02,612::lvm::309::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:50:02,616::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:02,629::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000879744 s, 4.7 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:50:07,623::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:50:07,635::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000759525 s, 2.5 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:50:09,259::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-206893::DEBUG::2013-12-16 13:50:12,046::task::579::TaskManager.Task::(_updateState) Task=`437f1c92-433e-4249-8132-b11c034543be`::moving from state init -> state preparing
>Thread-206893::INFO::2013-12-16 13:50:12,047::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206893::INFO::2013-12-16 13:50:12,047::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000759525', 'lastCheck': '4.4', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000879744', 'lastCheck': '9.4', 'valid': True}}
>Thread-206893::DEBUG::2013-12-16 13:50:12,047::task::1168::TaskManager.Task::(prepare) Task=`437f1c92-433e-4249-8132-b11c034543be`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000759525', 'lastCheck': '4.4', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000879744', 'lastCheck': '9.4', 'valid': True}}
>Thread-206893::DEBUG::2013-12-16 13:50:12,047::task::579::TaskManager.Task::(_updateState) Task=`437f1c92-433e-4249-8132-b11c034543be`::moving from state preparing -> state finished
>Thread-206893::DEBUG::2013-12-16 13:50:12,047::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206893::DEBUG::2013-12-16 13:50:12,048::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206893::DEBUG::2013-12-16 13:50:12,048::task::974::TaskManager.Task::(_decref) Task=`437f1c92-433e-4249-8132-b11c034543be`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:50:12,636::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:12,649::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00100662 s, 4.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:50:17,643::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:50:17,656::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.00045323 s, 4.1 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:50:22,655::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:22,669::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000733767 s, 5.6 MB/s\n'; <rc> = 0
>Thread-206899::DEBUG::2013-12-16 13:50:27,635::task::579::TaskManager.Task::(_updateState) Task=`c8d6d64b-1d96-4f0f-9ba1-d94dd49b935a`::moving from state init -> state preparing
>Thread-206899::INFO::2013-12-16 13:50:27,635::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206899::INFO::2013-12-16 13:50:27,636::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00045323', 'lastCheck': '10.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000733767', 'lastCheck': '5.0', 'valid': True}}
>Thread-206899::DEBUG::2013-12-16 13:50:27,636::task::1168::TaskManager.Task::(prepare) Task=`c8d6d64b-1d96-4f0f-9ba1-d94dd49b935a`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00045323', 'lastCheck': '10.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000733767', 'lastCheck': '5.0', 'valid': True}}
>Thread-206899::DEBUG::2013-12-16 13:50:27,636::task::579::TaskManager.Task::(_updateState) Task=`c8d6d64b-1d96-4f0f-9ba1-d94dd49b935a`::moving from state preparing -> state finished
>Thread-206899::DEBUG::2013-12-16 13:50:27,636::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206899::DEBUG::2013-12-16 13:50:27,636::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206899::DEBUG::2013-12-16 13:50:27,636::task::974::TaskManager.Task::(_decref) Task=`c8d6d64b-1d96-4f0f-9ba1-d94dd49b935a`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:50:27,664::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:50:27,677::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000494896 s, 3.8 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:50:32,675::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:32,688::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000936193 s, 4.4 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:50:37,685::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:50:37,698::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000551035 s, 3.4 MB/s\n'; <rc> = 0
>Thread-73240::DEBUG::2013-12-16 13:50:39,775::task::579::TaskManager.Task::(_updateState) Task=`9d300393-c783-4d82-8215-bef73a3db980`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:50:39,776::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:50:39,776::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:50:39,776::task::1168::TaskManager.Task::(prepare) Task=`9d300393-c783-4d82-8215-bef73a3db980`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:50:39,776::task::579::TaskManager.Task::(_updateState) Task=`9d300393-c783-4d82-8215-bef73a3db980`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:50:39,776::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:50:39,777::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:50:39,777::task::974::TaskManager.Task::(_decref) Task=`9d300393-c783-4d82-8215-bef73a3db980`::ref 0 aborting False
>VM Channels Listener::DEBUG::2013-12-16 13:50:40,070::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:50:42,694::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:42,708::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000942188 s, 4.3 MB/s\n'; <rc> = 0
>Thread-206905::DEBUG::2013-12-16 13:50:43,203::task::579::TaskManager.Task::(_updateState) Task=`a86e00cf-834b-42da-921b-85fd26680169`::moving from state init -> state preparing
>Thread-206905::INFO::2013-12-16 13:50:43,204::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206905::INFO::2013-12-16 13:50:43,204::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000551035', 'lastCheck': '5.5', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000942188', 'lastCheck': '0.5', 'valid': True}}
>Thread-206905::DEBUG::2013-12-16 13:50:43,204::task::1168::TaskManager.Task::(prepare) Task=`a86e00cf-834b-42da-921b-85fd26680169`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000551035', 'lastCheck': '5.5', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000942188', 'lastCheck': '0.5', 'valid': True}}
>Thread-206905::DEBUG::2013-12-16 13:50:43,204::task::579::TaskManager.Task::(_updateState) Task=`a86e00cf-834b-42da-921b-85fd26680169`::moving from state preparing -> state finished
>Thread-206905::DEBUG::2013-12-16 13:50:43,205::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206905::DEBUG::2013-12-16 13:50:43,205::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206905::DEBUG::2013-12-16 13:50:43,205::task::974::TaskManager.Task::(_decref) Task=`a86e00cf-834b-42da-921b-85fd26680169`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:50:47,708::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:50:47,721::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.0005435 s, 3.5 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:50:49,318::task::579::TaskManager.Task::(_updateState) Task=`6892d7ee-e279-47cd-ae10-60a69c8f160f`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:50:49,318::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:50:49,319::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:50:49,319::task::1168::TaskManager.Task::(prepare) Task=`6892d7ee-e279-47cd-ae10-60a69c8f160f`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:50:49,319::task::579::TaskManager.Task::(_updateState) Task=`6892d7ee-e279-47cd-ae10-60a69c8f160f`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:50:49,320::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:50:49,320::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:50:49,320::task::974::TaskManager.Task::(_decref) Task=`6892d7ee-e279-47cd-ae10-60a69c8f160f`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:50:52,714::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:50:52,728::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000999411 s, 4.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:50:57,729::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:50:57,742::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000575928 s, 3.3 MB/s\n'; <rc> = 0
>Thread-206911::DEBUG::2013-12-16 13:50:58,769::task::579::TaskManager.Task::(_updateState) Task=`63a14b20-4b25-4f9d-8a12-3ddba83e2bb8`::moving from state init -> state preparing
>Thread-206911::INFO::2013-12-16 13:50:58,769::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206911::INFO::2013-12-16 13:50:58,770::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000575928', 'lastCheck': '1.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000999411', 'lastCheck': '6.0', 'valid': True}}
>Thread-206911::DEBUG::2013-12-16 13:50:58,770::task::1168::TaskManager.Task::(prepare) Task=`63a14b20-4b25-4f9d-8a12-3ddba83e2bb8`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000575928', 'lastCheck': '1.0', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000999411', 'lastCheck': '6.0', 'valid': True}}
>Thread-206911::DEBUG::2013-12-16 13:50:58,770::task::579::TaskManager.Task::(_updateState) Task=`63a14b20-4b25-4f9d-8a12-3ddba83e2bb8`::moving from state preparing -> state finished
>Thread-206911::DEBUG::2013-12-16 13:50:58,770::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206911::DEBUG::2013-12-16 13:50:58,770::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206911::DEBUG::2013-12-16 13:50:58,770::task::974::TaskManager.Task::(_decref) Task=`63a14b20-4b25-4f9d-8a12-3ddba83e2bb8`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:51:02,733::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:51:02,747::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00092078 s, 4.4 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:51:07,751::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:51:07,763::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000597199 s, 3.1 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:51:10,854::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:51:12,753::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:51:12,767::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000960371 s, 4.3 MB/s\n'; <rc> = 0
>Thread-206917::DEBUG::2013-12-16 13:51:14,357::task::579::TaskManager.Task::(_updateState) Task=`0ba8a229-581a-48e8-ae91-b9d2b5195bae`::moving from state init -> state preparing
>Thread-206917::INFO::2013-12-16 13:51:14,357::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206917::INFO::2013-12-16 13:51:14,357::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000597199', 'lastCheck': '6.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000960371', 'lastCheck': '1.6', 'valid': True}}
>Thread-206917::DEBUG::2013-12-16 13:51:14,358::task::1168::TaskManager.Task::(prepare) Task=`0ba8a229-581a-48e8-ae91-b9d2b5195bae`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000597199', 'lastCheck': '6.6', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000960371', 'lastCheck': '1.6', 'valid': True}}
>Thread-206917::DEBUG::2013-12-16 13:51:14,358::task::579::TaskManager.Task::(_updateState) Task=`0ba8a229-581a-48e8-ae91-b9d2b5195bae`::moving from state preparing -> state finished
>Thread-206917::DEBUG::2013-12-16 13:51:14,358::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206917::DEBUG::2013-12-16 13:51:14,358::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206917::DEBUG::2013-12-16 13:51:14,358::task::974::TaskManager.Task::(_decref) Task=`0ba8a229-581a-48e8-ae91-b9d2b5195bae`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:51:17,772::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:51:17,784::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.00057556 s, 3.3 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:51:22,773::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:51:22,786::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000911459 s, 4.5 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:51:27,793::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:51:27,805::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000450082 s, 4.2 MB/s\n'; <rc> = 0
>Thread-206923::DEBUG::2013-12-16 13:51:29,922::task::579::TaskManager.Task::(_updateState) Task=`1d049710-bbaa-41bc-884f-147ce0120e08`::moving from state init -> state preparing
>Thread-206923::INFO::2013-12-16 13:51:29,922::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206923::INFO::2013-12-16 13:51:29,922::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000450082', 'lastCheck': '2.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000911459', 'lastCheck': '7.1', 'valid': True}}
>Thread-206923::DEBUG::2013-12-16 13:51:29,922::task::1168::TaskManager.Task::(prepare) Task=`1d049710-bbaa-41bc-884f-147ce0120e08`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000450082', 'lastCheck': '2.1', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000911459', 'lastCheck': '7.1', 'valid': True}}
>Thread-206923::DEBUG::2013-12-16 13:51:29,923::task::579::TaskManager.Task::(_updateState) Task=`1d049710-bbaa-41bc-884f-147ce0120e08`::moving from state preparing -> state finished
>Thread-206923::DEBUG::2013-12-16 13:51:29,923::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206923::DEBUG::2013-12-16 13:51:29,923::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206923::DEBUG::2013-12-16 13:51:29,923::task::974::TaskManager.Task::(_decref) Task=`1d049710-bbaa-41bc-884f-147ce0120e08`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:51:32,792::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:51:32,806::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000719652 s, 5.7 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:51:37,813::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:51:37,826::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000449223 s, 4.2 MB/s\n'; <rc> = 0
>Thread-73240::DEBUG::2013-12-16 13:51:39,842::task::579::TaskManager.Task::(_updateState) Task=`a8bbf77b-2d8d-4519-a26e-effefe00822b`::moving from state init -> state preparing
>Thread-73240::INFO::2013-12-16 13:51:39,843::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='2cdf6493-7fd1-4f4b-9af0-62e1e9505a7c', volUUID='df3a6dad-4202-4942-b759-f1bccd6cb5e1', options=None)
>Thread-73240::INFO::2013-12-16 13:51:39,843::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:51:39,843::task::1168::TaskManager.Task::(prepare) Task=`a8bbf77b-2d8d-4519-a26e-effefe00822b`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-73240::DEBUG::2013-12-16 13:51:39,843::task::579::TaskManager.Task::(_updateState) Task=`a8bbf77b-2d8d-4519-a26e-effefe00822b`::moving from state preparing -> state finished
>Thread-73240::DEBUG::2013-12-16 13:51:39,844::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73240::DEBUG::2013-12-16 13:51:39,844::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73240::DEBUG::2013-12-16 13:51:39,844::task::974::TaskManager.Task::(_decref) Task=`a8bbf77b-2d8d-4519-a26e-effefe00822b`::ref 0 aborting False
>VM Channels Listener::DEBUG::2013-12-16 13:51:41,635::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:51:42,812::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:51:42,825::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000912498 s, 4.5 MB/s\n'; <rc> = 0
>Thread-206929::DEBUG::2013-12-16 13:51:45,553::task::579::TaskManager.Task::(_updateState) Task=`9a605b22-0b17-4e41-9825-fa95d582110d`::moving from state init -> state preparing
>Thread-206929::INFO::2013-12-16 13:51:45,554::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206929::INFO::2013-12-16 13:51:45,554::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000449223', 'lastCheck': '7.7', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000912498', 'lastCheck': '2.7', 'valid': True}}
>Thread-206929::DEBUG::2013-12-16 13:51:45,554::task::1168::TaskManager.Task::(prepare) Task=`9a605b22-0b17-4e41-9825-fa95d582110d`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000449223', 'lastCheck': '7.7', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000912498', 'lastCheck': '2.7', 'valid': True}}
>Thread-206929::DEBUG::2013-12-16 13:51:45,554::task::579::TaskManager.Task::(_updateState) Task=`9a605b22-0b17-4e41-9825-fa95d582110d`::moving from state preparing -> state finished
>Thread-206929::DEBUG::2013-12-16 13:51:45,554::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206929::DEBUG::2013-12-16 13:51:45,555::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206929::DEBUG::2013-12-16 13:51:45,555::task::974::TaskManager.Task::(_decref) Task=`9a605b22-0b17-4e41-9825-fa95d582110d`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:51:47,836::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:51:47,849::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000493905 s, 3.8 MB/s\n'; <rc> = 0
>Thread-206525::DEBUG::2013-12-16 13:51:49,389::task::579::TaskManager.Task::(_updateState) Task=`818c9917-5f29-4c51-a433-31406121a398`::moving from state init -> state preparing
>Thread-206525::INFO::2013-12-16 13:51:49,389::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='75e24eb3-104c-451f-bf57-056b3b30ffba', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='6e2225cb-b5e7-435c-b507-ee4d570ecbd9', volUUID='370056b7-c569-4a37-9b33-fdf11d024a9c', options=None)
>Thread-206525::INFO::2013-12-16 13:51:49,390::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:51:49,390::task::1168::TaskManager.Task::(prepare) Task=`818c9917-5f29-4c51-a433-31406121a398`::finished: {'truesize': '21474836480', 'apparentsize': '21474836480'}
>Thread-206525::DEBUG::2013-12-16 13:51:49,390::task::579::TaskManager.Task::(_updateState) Task=`818c9917-5f29-4c51-a433-31406121a398`::moving from state preparing -> state finished
>Thread-206525::DEBUG::2013-12-16 13:51:49,391::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206525::DEBUG::2013-12-16 13:51:49,391::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206525::DEBUG::2013-12-16 13:51:49,391::task::974::TaskManager.Task::(_decref) Task=`818c9917-5f29-4c51-a433-31406121a398`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:51:52,831::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:51:52,845::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000955487 s, 4.3 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:51:57,858::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:51:57,870::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000683937 s, 2.7 MB/s\n'; <rc> = 0
>Thread-206935::DEBUG::2013-12-16 13:52:01,140::task::579::TaskManager.Task::(_updateState) Task=`3b259702-1e10-473a-98ff-47771c680336`::moving from state init -> state preparing
>Thread-206935::INFO::2013-12-16 13:52:01,140::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206935::INFO::2013-12-16 13:52:01,140::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000683937', 'lastCheck': '3.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000955487', 'lastCheck': '8.3', 'valid': True}}
>Thread-206935::DEBUG::2013-12-16 13:52:01,140::task::1168::TaskManager.Task::(prepare) Task=`3b259702-1e10-473a-98ff-47771c680336`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000683937', 'lastCheck': '3.3', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000955487', 'lastCheck': '8.3', 'valid': True}}
>Thread-206935::DEBUG::2013-12-16 13:52:01,140::task::579::TaskManager.Task::(_updateState) Task=`3b259702-1e10-473a-98ff-47771c680336`::moving from state preparing -> state finished
>Thread-206935::DEBUG::2013-12-16 13:52:01,141::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206935::DEBUG::2013-12-16 13:52:01,141::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206935::DEBUG::2013-12-16 13:52:01,141::task::974::TaskManager.Task::(_decref) Task=`3b259702-1e10-473a-98ff-47771c680336`::ref 0 aborting False
>Thread-244::DEBUG::2013-12-16 13:52:02,851::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:52:02,865::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00100089 s, 4.1 MB/s\n'; <rc> = 0
>Thread-504::DEBUG::2013-12-16 13:52:07,879::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:52:07,891::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.0006409 s, 2.9 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2013-12-16 13:52:12,123::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-244::DEBUG::2013-12-16 13:52:12,870::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:52:12,885::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000918168 s, 4.5 MB/s\n'; <rc> = 0
>Thread-206941::DEBUG::2013-12-16 13:52:16,693::task::579::TaskManager.Task::(_updateState) Task=`63b4d6c0-436e-4e85-8b31-c46e161f1c6e`::moving from state init -> state preparing
>Thread-206941::INFO::2013-12-16 13:52:16,693::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-206941::INFO::2013-12-16 13:52:16,694::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0006409', 'lastCheck': '8.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000918168', 'lastCheck': '3.8', 'valid': True}}
>Thread-206941::DEBUG::2013-12-16 13:52:16,694::task::1168::TaskManager.Task::(prepare) Task=`63b4d6c0-436e-4e85-8b31-c46e161f1c6e`::finished: {u'e1a50b62-693a-412c-bffd-2c9147e4c5b4': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0006409', 'lastCheck': '8.8', 'valid': True}, '75e24eb3-104c-451f-bf57-056b3b30ffba': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000918168', 'lastCheck': '3.8', 'valid': True}}
>Thread-206941::DEBUG::2013-12-16 13:52:16,694::task::579::TaskManager.Task::(_updateState) Task=`63b4d6c0-436e-4e85-8b31-c46e161f1c6e`::moving from state preparing -> state finished
>Thread-206941::DEBUG::2013-12-16 13:52:16,694::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-206941::DEBUG::2013-12-16 13:52:16,694::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-206941::DEBUG::2013-12-16 13:52:16,694::task::974::TaskManager.Task::(_decref) Task=`63b4d6c0-436e-4e85-8b31-c46e161f1c6e`::ref 0 aborting False
>Thread-504::DEBUG::2013-12-16 13:52:17,900::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.19.168.10:_rhev_isos/e1a50b62-693a-412c-bffd-2c9147e4c5b4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-504::DEBUG::2013-12-16 13:52:17,912::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1880 bytes (1.9 kB) copied, 0.000473155 s, 4.0 MB/s\n'; <rc> = 0
>Thread-244::DEBUG::2013-12-16 13:52:22,891::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/75e24eb3-104c-451f-bf57-056b3b30ffba/metadata bs=4096 count=1' (cwd None)
>Thread-244::DEBUG::2013-12-16 13:52:22,905::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00100923 s, 4.1 MB/s\n'; <rc> = 0

Actions: View

Attachments on bug 1038822: 837388 | 837390