2:15 a.m.
I tried to reproduce this by adding a specific progress test and using
permutations to
run 1000 tests per run.
This revealed that we have a leak in the jobs framework - each job
holding 7 file descriptors open until the job is deleted automatically
after 1 hour, so running many tests fail with too many open files.
These patches fix this issue:
https://gerrit.ovirt.org/#/q/topic:qemuimg-progress
After fixing this, the new tests can run, but the progress failure is
not reproduced.
So it seems that we don't this problem with these patches.
Separating the progress test is a good idea anyway.
Nir
On Thu, Nov 17, 2016 at 7:00 PM, Nir Soffer <nsoffer(a)redhat.com> wrote:
On Thu, Nov 17, 2016 at 4:57 PM, Adam Litke <alitke(a)redhat.com>
wrote:
> On 17/11/16 01:11 +0200, Nir Soffer wrote:
>>
>> I got very consistent failures with this patch, which should not be
>> related in any way to the failing code:
>> https://gerrit.ovirt.org/66109
>>
>> After adding logs in qemuinfo.Operation, the problem disappear:
>> https://gerrit.ovirt.org/66943
>
>
> This confirms my suspicion of a timing issue. I think it's inherently
> racy to rely on progress == 100.0 when job.status == 'DONE' because
> QemuImgOperation can read partial progress output. When this happens,
> the output is discarded and an update is attempted during the next
> read.
This will be a bug, we don't drop data from stdout, we accumulate it and
will check when the next data arrive.
I added some debug logs here, maybe it will reveal some info.
https://gerrit.ovirt.org/67019/
> tldr; I think the solution is to drop the asserts about progress for
> all tests other than progress-specific tests since progress is
> advisory anyhow.
I agree.
>> On Wed, Nov 16, 2016 at 11:33 PM, Nir Soffer <nsoffer(a)redhat.com> wrote:
>>>
>>> This test pass usually, Adam, can you check this?
>>>
>>> 21:15:52
>>> ======================================================================
>>> 21:15:52 FAIL: test_intra_domain_copy('block', 'cow',
'cow')
>>> (storage_sdm_copy_data_test.TestCopyDataDIV)
>>> 21:15:52
>>> ----------------------------------------------------------------------
>>> 21:15:52 Traceback (most recent call last):
>>> 21:15:52 File
>>>
>>>
"/home/jenkins/workspace/vdsm_master_check-patch-fc24-x86_64/vdsm/tests/testlib.py",
>>> line 133, in wrapper
>>> 21:15:52 return f(self, *args)
>>> 21:15:52 File
>>>
>>>
"/home/jenkins/workspace/vdsm_master_check-patch-fc24-x86_64/vdsm/tests/storage_sdm_copy_data_test.py",
>>> line 138, in test_intra_domain_copy
>>> 21:15:52 self.assertEqual(100.0, job.progress)
>>> 21:15:52 AssertionError: 100.0 != 0.0
>>> 21:15:52 -------------------- >> begin captured logging <<
>>> --------------------
>>> 21:15:52 2016-11-16 21:14:26,096 DEBUG (MainThread)
>>> [storage.PersistentDict] Created a persistent dict with
>>> VGTagMetadataRW backend (persistent:194)
>>> 21:15:52 2016-11-16 21:14:26,096 DEBUG (MainThread)
>>> [storage.PersistentDict] read lines (VGTagMetadataRW)=[]
>>> (persistent:236)
>>> 21:15:52 2016-11-16 21:14:26,097 DEBUG (MainThread)
>>> [storage.PersistentDict] Empty metadata (persistent:254)
>>> 21:15:52 2016-11-16 21:14:26,097 DEBUG (MainThread)
>>> [storage.PersistentDict] Starting transaction (persistent:169)
>>> 21:15:52 2016-11-16 21:14:26,097 DEBUG (MainThread)
>>> [storage.PersistentDict] Flushing changes (persistent:175)
>>> 21:15:52 2016-11-16 21:14:26,097 DEBUG (MainThread)
>>> [storage.PersistentDict] about to write lines
>>> (VGTagMetadataRW)=['CLASS=Data',
>>> 'POOL_UUID=fb6edad8-51ab-4aad-9090-a833efd6a1e2',
>>> 'SDUUID=beb999a9-a90b-4c49-9d4c-7b21b3adb164', 'VERSION=3',
>>> '_SHA_CKSUM=63ec9e7bc3d23a7da8ef5e318fdd65203ac7c3fe']
>>> (persistent:307)
>>> 21:15:52 2016-11-16 21:14:26,098 DEBUG (MainThread)
>>> [storage.Metadata.VGTagMetadataRW] Updating metadata
>>> adding=MDT__SHA_CKSUM=63ec9e7bc3d23a7da8ef5e318fdd65203ac7c3fe,
>>> MDT_VERSION=3, MDT_POOL_UUID=fb6edad8-51ab-4aad-9090-a833efd6a1e2,
>>> MDT_CLASS=Data, MDT_SDUUID=beb999a9-a90b-4c49-9d4c-7b21b3adb164
>>> removing= (blockSD:296)
>>> 21:15:52 2016-11-16 21:14:26,098 DEBUG (MainThread)
>>> [storage.PersistentDict] Finished transaction (persistent:177)
>>> 21:15:52 2016-11-16 21:14:26,101 WARNING (MainThread)
>>> [storage.StorageDomainManifest] Could not find mapping for lv
>>> beb999a9-a90b-4c49-9d4c-7b21b3adb164/1b8476de-236b-4c8e-aea0-134b213b7cb7
>>> (blockSD:786)
>>> 21:15:52 2016-11-16 21:14:26,101 DEBUG (MainThread)
>>> [storage.StorageDomainManifest] Found freeSlot 4 in VG
>>> beb999a9-a90b-4c49-9d4c-7b21b3adb164 (blockSD:759)
>>> 21:15:52 2016-11-16 21:14:26,103 DEBUG (MainThread)
>>> [storage.VolumeManifest] Creating symlink from
>>>
>>>
/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/1b8476de-236b-4c8e-aea0-134b213b7cb7
>>> to
>>>
/var/tmp/tmpKpf5ys/mnt/blockSD/beb999a9-a90b-4c49-9d4c-7b21b3adb164/images/c406fa29-72c8-4a26-9601-2bd5e0b1cbd0/1b8476de-236b-4c8e-aea0-134b213b7cb7
>>> (blockVolume:147)
>>> 21:15:52 2016-11-16 21:14:26,103 DEBUG (MainThread) [root]
>>> /usr/bin/taskset --cpu-list 0-3 /usr/bin/qemu-img create -f qcow2 -o
>>> compat=0.10
>>>
/var/tmp/tmpKpf5ys/mnt/blockSD/beb999a9-a90b-4c49-9d4c-7b21b3adb164/images/c406fa29-72c8-4a26-9601-2bd5e0b1cbd0/1b8476de-236b-4c8e-aea0-134b213b7cb7
>>> 1048576 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,144 DEBUG (MainThread) [root] SUCCESS:
>>> <err> = ''; <rc> = 0 (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,148 WARNING (MainThread)
>>> [storage.StorageDomainManifest] Could not find mapping for lv
>>> beb999a9-a90b-4c49-9d4c-7b21b3adb164/0e7c49ae-6c7c-4526-89c2-17b923c70dfa
>>> (blockSD:786)
>>> 21:15:52 2016-11-16 21:14:26,148 DEBUG (MainThread)
>>> [storage.StorageDomainManifest] Found freeSlot 5 in VG
>>> beb999a9-a90b-4c49-9d4c-7b21b3adb164 (blockSD:759)
>>> 21:15:52 2016-11-16 21:14:26,149 DEBUG (MainThread)
>>> [storage.VolumeManifest] Creating symlink from
>>>
>>>
/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/0e7c49ae-6c7c-4526-89c2-17b923c70dfa
>>> to
>>>
/var/tmp/tmpKpf5ys/mnt/blockSD/beb999a9-a90b-4c49-9d4c-7b21b3adb164/images/939d015f-e57e-4bf1-9013-b648fae347ae/0e7c49ae-6c7c-4526-89c2-17b923c70dfa
>>> (blockVolume:147)
>>> 21:15:52 2016-11-16 21:14:26,150 DEBUG (MainThread) [root]
>>> /usr/bin/taskset --cpu-list 0-3 /usr/bin/qemu-img create -f qcow2 -o
>>> compat=0.10
>>>
/var/tmp/tmpKpf5ys/mnt/blockSD/beb999a9-a90b-4c49-9d4c-7b21b3adb164/images/939d015f-e57e-4bf1-9013-b648fae347ae/0e7c49ae-6c7c-4526-89c2-17b923c70dfa
>>> 1048576 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,195 DEBUG (MainThread) [root] SUCCESS:
>>> <err> = ''; <rc> = 0 (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,196 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=4 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,207 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000394548 s, 1.3 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,208 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000394548 s, 1.3 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,209 DEBUG (MainThread) [root]
>>> /usr/bin/taskset --cpu-list 0-3 qemu-io -f qcow2 -c 'write -P 240 0
>>> 1024'
>>>
/var/tmp/tmpKpf5ys/mnt/blockSD/beb999a9-a90b-4c49-9d4c-7b21b3adb164/images/c406fa29-72c8-4a26-9601-2bd5e0b1cbd0/1b8476de-236b-4c8e-aea0-134b213b7cb7
>>> (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,257 DEBUG (MainThread) [root] SUCCESS:
>>> <err> = ''; <rc> = 0 (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,260 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=5 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,274 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000359356 s, 1.4 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,274 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000359356 s, 1.4 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,275 DEBUG (MainThread) [root]
>>> /usr/bin/taskset --cpu-list 0-3 qemu-io -f qcow2 -c 'read -P 240 -s 0
>>> -l 1024 0 1024'
>>>
>>>
/var/tmp/tmpKpf5ys/mnt/blockSD/beb999a9-a90b-4c49-9d4c-7b21b3adb164/images/939d015f-e57e-4bf1-9013-b648fae347ae/0e7c49ae-6c7c-4526-89c2-17b923c70dfa
>>> (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,316 DEBUG (MainThread) [root] SUCCESS:
>>> <err> = ''; <rc> = 0 (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,318 INFO (MainThread) [root] Running job
>>> 'f8a60ab8-2ba9-473d-bf46-82080c283137'... (jobs:179)
>>> 21:15:52 2016-11-16 21:14:26,320 INFO (MainThread)
>>> [storage.VolumeManifest] Volume: preparing volume
>>> beb999a9-a90b-4c49-9d4c-7b21b3adb164/1b8476de-236b-4c8e-aea0-134b213b7cb7
>>> (volume:462)
>>> 21:15:52 2016-11-16 21:14:26,321 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=4 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,335 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000302993 s, 1.7 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,336 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000302993 s, 1.7 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,338 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=4 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,351 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000368094 s, 1.4 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,352 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000368094 s, 1.4 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,354 INFO (MainThread)
>>> [storage.VolumeManifest] Volume: preparing volume
>>> beb999a9-a90b-4c49-9d4c-7b21b3adb164/0e7c49ae-6c7c-4526-89c2-17b923c70dfa
>>> (volume:462)
>>> 21:15:52 2016-11-16 21:14:26,355 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=5 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,368 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000382558 s, 1.3 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,369 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000382558 s, 1.3 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,370 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=5 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,388 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000326875 s, 1.6 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,389 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000326875 s, 1.6 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,391 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=5 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,404 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000335536 s, 1.5 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,405 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000335536 s, 1.5 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,406 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=4 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,420 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000292733 s, 1.7 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,421 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000292733 s, 1.7 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,422 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=4 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,436 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000359596 s, 1.4 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,437 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000359596 s, 1.4 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,438 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=4 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,451 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000322085 s, 1.6 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,452 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000322085 s, 1.6 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,454 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=5 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:15:52 2016-11-16 21:14:26,467 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.00033405 s, 1.5 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:15:52 2016-11-16 21:14:26,468 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.00033405 s, 1.5 MB/s'], size: 512 (misc:138)
>>> 21:15:52 2016-11-16 21:14:26,469 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=5 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:16:08 2016-11-16 21:14:26,481 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.00030909 s, 1.7 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:16:08 2016-11-16 21:14:26,482 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.00030909 s, 1.7 MB/s'], size: 512 (misc:138)
>>> 21:16:08 2016-11-16 21:14:26,483 INFO (MainThread)
>>> [storage.VolumeManifest] sdUUID=beb999a9-a90b-4c49-9d4c-7b21b3adb164
>>> imgUUID=939d015f-e57e-4bf1-9013-b648fae347ae volUUID =
>>> 0e7c49ae-6c7c-4526-89c2-17b923c70dfa legality = ILLEGAL (volume:368)
>>> 21:16:08 2016-11-16 21:14:26,484 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=5 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:16:08 2016-11-16 21:14:26,497 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000307797 s, 1.7 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:16:08 2016-11-16 21:14:26,498 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000307797 s, 1.7 MB/s'], size: 512 (misc:138)
>>> 21:16:08 2016-11-16 21:14:26,502 DEBUG (MainThread) [QemuImg]
>>> /usr/bin/taskset --cpu-list 0-3 /usr/bin/nice -n 19 /usr/bin/ionice -c
>>> 3 /usr/bin/qemu-img convert -p -t none -T none -f qcow2
>>>
>>>
/var/tmp/tmpKpf5ys/mnt/blockSD/beb999a9-a90b-4c49-9d4c-7b21b3adb164/images/c406fa29-72c8-4a26-9601-2bd5e0b1cbd0/1b8476de-236b-4c8e-aea0-134b213b7cb7
>>> -O qcow2 -o compat=0.10
>>>
>>>
/var/tmp/tmpKpf5ys/mnt/blockSD/beb999a9-a90b-4c49-9d4c-7b21b3adb164/images/939d015f-e57e-4bf1-9013-b648fae347ae/0e7c49ae-6c7c-4526-89c2-17b923c70dfa
>>> (cwd None) (qemuimg:247)
>>> 21:16:08 2016-11-16 21:14:26,805 DEBUG (MainThread)
>>> [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd
>>> iflag=direct skip=5 bs=512
>>> if=/var/tmp/tmpKpf5ys/dev/beb999a9-a90b-4c49-9d4c-7b21b3adb164/metadata
>>> count=1 (cwd None) (commands:69)
>>> 21:16:08 2016-11-16 21:14:26,820 DEBUG (MainThread)
>>> [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0
records
>>> out\n512 bytes copied, 0.000380116 s, 1.3 MB/s\n'; <rc> = 0
>>> (commands:93)
>>> 21:16:08 2016-11-16 21:14:26,821 DEBUG (MainThread) [storage.Misc]
>>> err: ['1+0 records in', '1+0 records out', '512 bytes
copied,
>>> 0.000380116 s, 1.3 MB/s'], size: 512 (misc:138)
>>> 21:16:08 2016-11-16 21:14:26,823 INFO (MainThread)
>>> [storage.VolumeManifest] Tearing down volume
>>> beb999a9-a90b-4c49-9d4c-7b21b3adb164/0e7c49ae-6c7c-4526-89c2-17b923c70dfa
>>> justme True (blockVolume:386)
>>> 21:16:08 2016-11-16 21:14:26,824 INFO (MainThread)
>>> [storage.VolumeManifest] Tearing down volume
>>> beb999a9-a90b-4c49-9d4c-7b21b3adb164/1b8476de-236b-4c8e-aea0-134b213b7cb7
>>> justme True (blockVolume:386)
>>> 21:16:08 2016-11-16 21:14:26,824 INFO (MainThread) [root] Job
>>> 'f8a60ab8-2ba9-473d-bf46-82080c283137' completed (jobs:203)
>>> 21:16:08 2016-11-16 21:14:26,825 INFO (MainThread) [root] Job
>>> 'f8a60ab8-2ba9-473d-bf46-82080c283137' will be deleted in 3600
seconds
>>> (jobs:245)
>>> 21:16:08 --------------------- >> end captured logging <<
>>> ---------------------
>
>
> --
> Adam Litke