[Libguestfs] virt-v2v stuck EDAC sbridge

[Seth Tanner]

>>Rich,
>>Here you go
>>I also noticed that if I use the direct backend rather than libvirt, the conversion gets farther, but still does not complete, when pulling directly from vSphere. please let me know if you would like the output of direct as well.
>>starting version 233
>>+ udevadm trigger
>>+ udevadm settle --timeout=600
>>[    3.124522] EDAC MC: Ver: 3.0.0
>>[    3.135246] EDAC sbridge:  Ver: 1.1.1 

>Ugh, looks like this is actually a qemu or kernel bug.
>
>Is it reproducible when you just do:
>
>  libguestfs-test-tool
>
>?

No it's not reproducible that way.
Tests finish OK, both with libvirt and direct backend


>Is there anything peculiar about the environment, eg. nested virt,
>running inside VMware, peculiar hardware?

The virt-v2v machine is running inside openstack, so there is nested virtualization. To the best of my understanding all of the appropriate flags have been set to support nested virtualization.
I don't think that any of the hardware is especially peculiar, it's standard off the shelf supermicro server hardware with fairly modern intel processors and NIC's.
I'll see if I can round up some bare metal and try it that way.

>You could also try running without using KVM.  It'll be a bit slower
>but is usually less buggy than nested virt:

>  export LIBGUESTFS_BACKEND_SETTINGS=force_tcg

If the backend is set to direct, it hangs at image conversion

[3016.9] Copying disk 1/2 to /var/tmp/glance.hzY7jr/sda (raw)
target_file = /var/tmp/glance.hzY7jr/sda
target_format = raw
target_estimated_size = None
target_overlay = /var/tmp/v2vovle834c2.qcow2
target_overlay.ov_source = json: { "file.cookie": "vmware_soap_session=\"5260d7c2-d736-7539-b6f6-59d845655690\"", "file.sslverify": "off", "file.driver": "https", "file.url": "https://192.168.28.9/folder/Axia-DEV/Axia-DEV-flat.vmdk?dcPath=Axia&dsName=datastore2", "file.timeout": 2000 }

libguestfs: trace: set_verbose true
libguestfs: trace: set_verbose = 0
libguestfs: trace: set_backend "direct"
libguestfs: trace: set_backend = 0
libguestfs: trace: set_backend_settings "force_tcg"
libguestfs: trace: set_backend_settings = 0
libguestfs: create: flags = 0, handle = 0xe8ac60, program = virt-v2v
libguestfs: trace: set_trace true
libguestfs: trace: set_trace = 0
libguestfs: trace: set_verbose true
libguestfs: trace: set_verbose = 0
libguestfs: trace: disk_has_backing_file "/var/tmp/v2vovle834c2.qcow2"
libguestfs: command: run: qemu-img
libguestfs: command: run: \ info
libguestfs: command: run: \ --output json
libguestfs: command: run: \ /dev/fd/4
libguestfs: parse_json: qemu-img info JSON output:\n{\n    "backing-filename-format": "raw",\n    "virtual-size": 42949672960,\n    "filename": "/dev/fd/4",\n    "cluster-size": 65536,\n    "format": "qcow2",\n    "actual-size": 675815424,\n    "format-specific": {\n        "type": "qcow2",\n        "data": {\n            "compat": "1.1",\n            "lazy-refcounts": false,\n            "refcount-bits": 16,\n            "corrupt": false\n        }\n    },\n    "full-backing-filename": "json: { \"file.cookie\": \"vmware_soap_session=\\\"5260d7c2-d736-7539-b6f6-59d845655690\\\"\", \"file.sslverify\": \"off\", \"file.driver\": \"https\", \"file.url\": \"https://192.168.28.9/folder/Axia-DEV/Axia-DEV-flat.vmdk?dcPath=Axia&dsName=datastore2\", \"file.timeout\": 2000 }",\n    "backing-filename": "json: { \"file.cookie\": \"vmware_soap_session=\\\"5260d7c2-d736-7539-b6f6-59d845655690\\\"\", \"file.sslverify\": \"off\", \"file.driver\": \"https\", \"file.url\": \"https://192.168.28.9/folder/Axia-DEV/Axia-DEV-flat.vmdk?dcPath=Axia&dsName=datastore2\", \"file.timeout\": 2000 }",\n    "dirty-flag": false\n}\n\n
libguestfs: trace: disk_has_backing_file = 1
vcenter: json parameters: { "file.cookie": "vmware_soap_session=\"5260d7c2-d736-7539-b6f6-59d845655690\"", "file.sslverify": "off", "file.readahead": 67108864, "file.driver": "https", "file.url": "https://192.168.28.9/folder/Axia-DEV/Axia-DEV-flat.vmdk?dcPath=Axia&dsName=datastore2", "file.timeout": 2000 }
qemu-img 'rebase' '-u' '-b' 'json: { "file.cookie": "vmware_soap_session=\"5260d7c2-d736-7539-b6f6-59d845655690\"", "file.sslverify": "off", "file.readahead": 67108864, "file.driver": "https", "file.url": "https://192.168.28.9/folder/Axia-DEV/Axia-DEV-flat.vmdk?dcPath=Axia&dsName=datastore2", "file.timeout": 2000 }' '/var/tmp/v2vovle834c2.qcow2'
libguestfs: trace: set_verbose true
libguestfs: trace: set_verbose = 0
libguestfs: trace: set_backend "direct"
libguestfs: trace: set_backend = 0
libguestfs: trace: set_backend_settings "force_tcg"
libguestfs: trace: set_backend_settings = 0
libguestfs: create: flags = 0, handle = 0xebbaf0, program = virt-v2v
libguestfs: trace: set_trace true
libguestfs: trace: set_trace = 0
libguestfs: trace: set_verbose true
libguestfs: trace: set_verbose = 0
libguestfs: trace: disk_create "/var/tmp/glance.hzY7jr/sda" "raw" 42949672960 "preallocation:sparse"
libguestfs: trace: disk_create = 0
qemu-img 'convert' '-p' '-n' '-f' 'qcow2' '-O' 'raw' '/var/tmp/v2vovle834c2.qcow2' '/var/tmp/glance.hzY7jr/sda'
    (0.00/100%)

If the backend is set to libvirt 
It hangs inspecting the overlay

[ 122.8] Inspecting the overlay
libguestfs: trace: v2v: inspect_os
libguestfs: trace: v2v: umount_all
guestfsd: main_loop: new request, len 0x28
umount-all: /proc/mounts: fsname=/dev/root dir=/ type=ext2 opts=rw,noatime,block_validity,barrier,user_xattr,acl freq=0 passno=0
umount-all: /proc/mounts: fsname=/proc dir=/proc type=proc opts=rw,relatime freq=0 passno=0
umount-all: /proc/mounts: fsname=/sys dir=/sys type=sysfs opts=rw,relatime freq=0 passno=0
umount-all: /proc/mounts: fsname=tmpfs dir=/run type=tmpfs opts=rw,nosuid,relatime,size=399708k,mode=755 freq=0 passno=0
umount-all: /proc/mounts: fsname=/dev dir=/dev type=devtmpfs opts=rw,relatime,size=996920k,nr_inodes=249230,mode=755 freq=0 passno=0
umount-all: /proc/mounts: fsname=/dev/pts dir=/dev/pts type=devpts opts=rw,relatime,mode=600,ptmxmode=000 freq=0 passno=0
libguestfs: trace: v2v: umount_all = 0
libguestfs: trace: v2v: list_filesystems
libguestfs: trace: v2v: feature_available "lvm2"
libguestfs: trace: v2v: internal_feature_available "lvm2"
guestfsd: main_loop: proc 47 (umount_all) took 0.01 seconds
guestfsd: main_loop: new request, len 0x30
libguestfs: trace: v2v: internal_feature_available = 0
libguestfs: trace: v2v: feature_available = 1
libguestfs: trace: v2v: feature_available "ldm"
libguestfs: trace: v2v: internal_feature_available "ldm"
guestfsd: main_loop: proc 458 (internal_feature_available) took 0.00 seconds
guestfsd: main_loop: new request, len 0x30
libguestfs: trace: v2v: internal_feature_available = 0
libguestfs: trace: v2v: feature_available = 1
libguestfs: trace: v2v: list_devices
guestfsd: main_loop: proc 458 (internal_feature_available) took 0.00 seconds
guestfsd: main_loop: new request, len 0x28
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdb
calling: settle
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdc
calling: settle
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda
calling: settle
libguestfs: trace: v2v: list_devices = ["/dev/sda", "/dev/sdb"]
libguestfs: trace: v2v: list_partitions
guestfsd: main_loop: proc 7 (list_devices) took 0.29 seconds
guestfsd: main_loop: new request, len 0x28
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdb
calling: settle
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdc
calling: settle
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda
calling: settle
libguestfs: trace: v2v: list_partitions = ["/dev/sda1", "/dev/sda2", "/dev/sda5", "/dev/sdb1"]
libguestfs: trace: v2v: list_md_devices
guestfsd: main_loop: proc 8 (list_partitions) took 0.29 seconds
guestfsd: main_loop: new request, len 0x28
libguestfs: trace: v2v: list_md_devices = []
libguestfs: trace: v2v: part_to_dev "/dev/sda1"
guestfsd: main_loop: proc 300 (list_md_devices) took 0.00 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda1
calling: settle
libguestfs: trace: v2v: part_to_dev = "/dev/sda"
libguestfs: trace: v2v: part_to_dev "/dev/sda2"
guestfsd: main_loop: proc 272 (part_to_dev) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda2
calling: settle
libguestfs: trace: v2v: part_to_dev = "/dev/sda"
libguestfs: trace: v2v: part_to_dev "/dev/sda5"
guestfsd: main_loop: proc 272 (part_to_dev) took 0.10 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda5
calling: settle
libguestfs: trace: v2v: part_to_dev = "/dev/sda"
libguestfs: trace: v2v: part_to_dev "/dev/sdb1"
guestfsd: main_loop: proc 272 (part_to_dev) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdb1
calling: settle
libguestfs: trace: v2v: part_to_dev = "/dev/sdb"
libguestfs: trace: v2v: part_to_partnum "/dev/sda1"
guestfsd: main_loop: proc 272 (part_to_dev) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda1
calling: settle
libguestfs: trace: v2v: part_to_partnum = 1
libguestfs: trace: v2v: part_to_dev "/dev/sda1"
guestfsd: main_loop: proc 293 (part_to_partnum) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda1
calling: settle
libguestfs: trace: v2v: part_to_dev = "/dev/sda"
libguestfs: trace: v2v: part_get_mbr_id "/dev/sda" 1
guestfsd: main_loop: proc 272 (part_to_dev) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: sfdisk --help
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: sfdisk --part-type /dev/sda 1
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle
calling: settle
libguestfs: trace: v2v: part_get_mbr_id = 131
libguestfs: trace: v2v: vfs_type "/dev/sda1"
guestfsd: main_loop: proc 235 (part_get_mbr_id) took 1.13 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda1
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: blkid -c /dev/null -o value -s TYPE /dev/sda1
libguestfs: trace: v2v: vfs_type = "ext4"
libguestfs: trace: v2v: part_to_partnum "/dev/sda2"
guestfsd: main_loop: proc 198 (vfs_type) took 2.87 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda2
calling: settle
libguestfs: trace: v2v: part_to_partnum = 2
libguestfs: trace: v2v: part_to_dev "/dev/sda2"
guestfsd: main_loop: proc 293 (part_to_partnum) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda2
calling: settle
libguestfs: trace: v2v: part_to_dev = "/dev/sda"
libguestfs: trace: v2v: part_get_mbr_id "/dev/sda" 2
guestfsd: main_loop: proc 272 (part_to_dev) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda
calling: settle
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: sfdisk --part-type /dev/sda 2
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle
calling: settle
libguestfs: trace: v2v: part_get_mbr_id = 5
libguestfs: trace: v2v: vfs_type "/dev/sda2"
guestfsd: main_loop: proc 235 (part_get_mbr_id) took 0.95 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda2
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: blkid -c /dev/null -o value -s TYPE /dev/sda2
libguestfs: trace: v2v: vfs_type = ""
libguestfs: trace: v2v: part_to_partnum "/dev/sda5"
guestfsd: main_loop: proc 198 (vfs_type) took 0.17 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda5
calling: settle
libguestfs: trace: v2v: part_to_partnum = 5
libguestfs: trace: v2v: part_to_dev "/dev/sda5"
guestfsd: main_loop: proc 293 (part_to_partnum) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda5
calling: settle
libguestfs: trace: v2v: part_to_dev = "/dev/sda"
libguestfs: trace: v2v: part_get_mbr_id "/dev/sda" 5
guestfsd: main_loop: proc 272 (part_to_dev) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda
calling: settle
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: sfdisk --part-type /dev/sda 5
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle
calling: settle
libguestfs: trace: v2v: part_get_mbr_id = 130
libguestfs: trace: v2v: vfs_type "/dev/sda5"
guestfsd: main_loop: proc 235 (part_get_mbr_id) took 0.36 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda5
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: blkid -c /dev/null -o value -s TYPE /dev/sda5
libguestfs: trace: v2v: vfs_type = ""
libguestfs: trace: v2v: part_to_partnum "/dev/sdb1"
guestfsd: main_loop: proc 198 (vfs_type) took 3.15 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdb1
calling: settle
libguestfs: trace: v2v: part_to_partnum = 1
libguestfs: trace: v2v: part_to_dev "/dev/sdb1"
guestfsd: main_loop: proc 293 (part_to_partnum) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdb1
calling: settle
libguestfs: trace: v2v: part_to_dev = "/dev/sdb"
libguestfs: trace: v2v: part_get_mbr_id "/dev/sdb" 1
guestfsd: main_loop: proc 272 (part_to_dev) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdb
calling: settle
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: sfdisk --part-type /dev/sdb 1
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle
calling: settle
libguestfs: trace: v2v: part_get_mbr_id = 131
libguestfs: trace: v2v: vfs_type "/dev/sdb1"
guestfsd: main_loop: proc 235 (part_get_mbr_id) took 0.88 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sdb1
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: blkid -c /dev/null -o value -s TYPE /dev/sdb1
libguestfs: trace: v2v: vfs_type = "swap"
libguestfs: trace: v2v: lvs
guestfsd: main_loop: proc 198 (vfs_type) took 2.84 seconds
guestfsd: main_loop: new request, len 0x28
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: lvm lvs --help
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: lvm lvs -o vg_name,lv_name -S "lv_role=public && lv_skip_activation!=yes" --noheadings --separator /
libguestfs: trace: v2v: lvs = []
libguestfs: trace: v2v: list_ldm_volumes
guestfsd: main_loop: proc 11 (lvs) took 2.45 seconds
guestfsd: main_loop: new request, len 0x28
libguestfs: trace: v2v: list_ldm_volumes = []
libguestfs: trace: v2v: list_ldm_partitions
guestfsd: main_loop: proc 380 (list_ldm_volumes) took 0.00 seconds
guestfsd: main_loop: new request, len 0x28
libguestfs: trace: v2v: list_ldm_partitions = []
libguestfs: trace: v2v: list_filesystems = ["/dev/sda1", "ext4", "/dev/sda2", "unknown", "/dev/sda5", "unknown", "/dev/sdb1", "swap"]
libguestfs: trace: v2v: vfs_type "/dev/sda1"
guestfsd: main_loop: proc 381 (list_ldm_partitions) took 0.00 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda1
calling: settle
commandrvf: stdout=y stderr=y flags=0x0
commandrvf: blkid -c /dev/null -o value -s TYPE /dev/sda1
libguestfs: trace: v2v: vfs_type = "ext4"
libguestfs: check_for_filesystem_on: /dev/sda1 (ext4)
libguestfs: trace: v2v: internal_parse_mountable "/dev/sda1"
guestfsd: main_loop: proc 198 (vfs_type) took 3.54 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda1
calling: settle
libguestfs: trace: v2v: internal_parse_mountable = <struct guestfs_internal_mountable = im_type: 0, im_device: /dev/sda1, im_volume: , >
libguestfs: trace: v2v: is_whole_device "/dev/sda1"
guestfsd: main_loop: proc 396 (internal_parse_mountable) took 0.09 seconds
guestfsd: main_loop: new request, len 0x38
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda1
calling: settle
libguestfs: trace: v2v: is_whole_device = 0
libguestfs: trace: v2v: mount_ro "/dev/sda1" "/"
guestfsd: main_loop: proc 395 (is_whole_device) took 0.09 seconds
guestfsd: main_loop: new request, len 0x40
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: udevadm --debug settle -E /dev/sda1
calling: settle
commandrvf: stdout=n stderr=y flags=0x0
commandrvf: mount -o ro /dev/sda1 /sysroot/