[VDSM] FAIL: test_intra_domain_copy('block', 'cow', 'cow') (storage_sdm_copy_data_test.TestCopyDataDIV)
6:33 a.m.
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 <<
---------------------
8:11 a.m.
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
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 <<
---------------------
11:57 p.m.
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(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
2 a.m.
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
8: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
2712
days inactive
2718
days old
4 comments
2 participants
participants (2)
-
Adam Litke -
Nir Soffer