[VDSM] FAIL: test_intra_domain_copy('block', 'cow', 'cow') (storage_sdm_copy_data_test.TestCopyDataDIV)
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 << ---------------------
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@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 << ---------------------
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@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
On Thu, Nov 17, 2016 at 4:57 PM, Adam Litke <alitke@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@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
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@redhat.com> wrote:
On Thu, Nov 17, 2016 at 4:57 PM, Adam Litke <alitke@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@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
participants (2)
-
Adam Litke -
Nir Soffer