[ovirt-devel] [VDSM] FAIL: test_intra_domain_copy('block', 'cow', 'cow') (storage_sdm_copy_data_test.TestCopyDataDIV)
Adam Litke
alitke at redhat.com
Thu Nov 17 14:57:32 UTC 2016
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.
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.
>
>
>
>On Wed, Nov 16, 2016 at 11:33 PM, Nir Soffer <nsoffer at 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
More information about the Devel
mailing list