Bug 1837840

Summary: V2V conversion will hang during converting guest from ESXi5.5 via vddk if nbdkit>=1.16.2-3
Product: Red Hat Enterprise Linux Advanced Virtualization Reporter: mxie <mxie>
Component: nbdkitAssignee: Virtualization Maintenance <virt-maint>
Status: CLOSED CURRENTRELEASE QA Contact: Virtualization Bugs <virt-bugs>
Severity: high Docs Contact:
Priority: high    
Version: 8.3CC: eblake, fdeutsch, jherrman, jsuchane, juzhou, mtessun, mzhan, rjones, tyan, tzheng, virt-maint, xiaodwan, zili
Target Milestone: rcKeywords: Automation, Regression
Target Release: 8.3   
Hardware: x86_64   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-07-14 11:20:52 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
esx5.5-vddk6.5.png
none
esx5.5-vddk6.5-hang.log
none
esx5.5-vddk6.7.3-hang-picture.png
none
esx5.5-vddk7.0-hang-picture.png
none
esx5.5-vddk6.7.3-hang.log
none
esx5.5-vddk7.0-hang.log none

Description mxie@redhat.com 2020-05-20 06:25:51 UTC 
Description of problem:
V2V conversion will hang at copying disk during converting guest from ESXi5.5 via vddk6.5 if nbdkit>=1.16.2-3

Version-Release number of selected component (if applicable):
virt-v2v-1.42.0-3.module+el8.3.0+6497+b190d2a5.x86_64
libguestfs-1.42.0-1.module+el8.3.0+6496+d39ac712.x86_64
libvirt-6.3.0-1.module+el8.3.0+6478+69f490bb.x86_64
qemu-kvm-5.0.0-0.module+el8.3.0+6620+5d5e1420.x86_64
nbdkit-1.20.1-1.module+el8.3.0+6491+7f1d5b30.x86_64
VMware-vix-disklib-6.5.2-6195444.x86_64.tar.gz

How reproducible:
100%

Automated test report:
https://libvirt-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/v2v/view/RHEL-8.3/job/v2v-RHEL-8.3-runtest-x86_64-acceptance-ovirt/5/testReport/rhel/convert_vm_to_ovirt/esx_vm_5_5_windows_win10_arch_x86_64_raw_f_NFS_rhv_upload_rhv_direct_rhv_verifypeer_nopreallocated_it_vddk/


Steps to Reproduce by manual testing:
1.Convert guest from ESXi5.5 via vddk6.5 by virt-v2v, the conversion can't finished in 4 hours
# virt-v2v -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 -it vddk -io vddk-libdir=/root/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D esx5.5-rhel6.10-x86_64 -on 5.5-have-vddk -ip /home/passwd -o local -os /home
[   0.2] Opening the source -i libvirt -ic vpx://root.73.148:443/data/10.73.3.19/?no_verify=1 esx5.5-rhel6.10-x86_64 -it vddk  -io vddk-libdir=/root/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
[   1.7] Creating an overlay to protect the source from being modified
[   4.9] Opening the overlay
[  13.7] Inspecting the overlay
[  34.7] Checking for sufficient free disk space in the guest
[  34.7] Estimating space required on target for each disk
[  34.7] Converting Red Hat Enterprise Linux Workstation release 6.10 (Santiago) to run on KVM
virt-v2v: This guest has virtio drivers installed.
[ 191.0] Mapping filesystem data to avoid copying unused and blank areas
[ 191.7] Closing the overlay
[ 192.0] Assigning disks to buses
[ 192.0] Checking if the guest needs BIOS or UEFI to boot
[ 192.0] Initializing the target -o local -os /home
[ 192.0] Copying disk 1/1 to /home/5.5-have-vddk-sda (raw)
    (0.00/100%)

2.Convert guest from ESXi5.5 without vddk by virt-v2v, the conversion can finish successfully
# virt-v2v -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 esx5.5-rhel7.8-x86_64 -on 5.5-no-vddk -ip /home/passwd -o local -os /home
[   0.2] Opening the source -i libvirt -ic vpx://root.73.148:443/data/10.73.3.19/?no_verify=1 esx5.5-rhel7.8-x86_64
[   2.6] Creating an overlay to protect the source from being modified
[   3.1] Opening the overlay
[  29.4] Inspecting the overlay
[ 102.9] Checking for sufficient free disk space in the guest
[ 102.9] Estimating space required on target for each disk
[ 102.9] Converting Red Hat Enterprise Linux Server 7.8 (Maipo) to run on KVM
virt-v2v: This guest has virtio drivers installed.
[1528.5] Mapping filesystem data to avoid copying unused and blank areas
[1530.0] Closing the overlay
[1530.3] Assigning disks to buses
[1530.3] Checking if the guest needs BIOS or UEFI to boot
[1530.3] Initializing the target -o local -os /home
[1530.3] Copying disk 1/1 to /home/5.5-no-vddk-sda (raw)
    (100.00/100%)
[2106.6] Creating output metadata
[2106.6] Finishing off


Actual results:
As above description

Expected results:
V2V conversion can finish successfully when convert guest from ESXi5.5 via vddk6.5

Additional info:
I think the bug is caused by nbdkit>=1.16.2-3

When nbdkit version is 1.16.2-2, v2v conversion can finish successfully when convert guest from ESXi5.5 via vddk6.5, pls refer to below automated test report:

https://libvirt-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/v2v/view/RHEL-8.2/job/v2v-RHEL-8.2-runtest-x86_64-acceptance-ovirt/32/testReport/rhel/convert_vm_to_ovirt/esx_vm_5_5_windows_win10_arch_i386_raw_f_NFS_rhv_upload_rhv_direct_rhv_verifypeer_nopreallocated_it_vddk/


But when nbdkit version is 1.16.2-3, v2v conversion can't finish in 4 hours when convert guest from ESXi5.5 via vddk6.5, pls refer to below automated test report:

https://libvirt-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/v2v/view/RHEL-8.2/job/v2v-RHEL-8.2-runtest-x86_64-acceptance-ovirt/34/testReport/rhel/convert_vm_to_ovirt/esx_vm_5_5_windows_win10_arch_i386_raw_f_NFS_rhv_upload_rhv_direct_rhv_verifypeer_nopreallocated_it_vddk/
Comment 1 Richard W.M. Jones 2020-05-26 11:00:48 UTC 
The only change in nbdkit from -2 to -3 was the addition of this patch which
seems as if it couldn't possibly affect this, *unless* VDDK 7 was also installed on
the test machine.

https://github.com/libguestfs/nbdkit/commit/7f53999179af98aa47569c6771517f7dfa08c5d0
Comment 2 Richard W.M. Jones 2020-05-26 11:33:21 UTC 
I manually compared the packages between the two test runs and, apart from nbdkit,
all the main packages are the same.  Also according to the logs VDDK 6.5 and 6.7 are
installed (in both builds), but not VDDK 7.0.

So this is a very strange and inexplicable regression.
Comment 3 mxie@redhat.com 2020-05-27 06:59:38 UTC 
Hi Richard,

   I found v2v will hang at new position during converting guest from ESXi5.5 via vddk6.5,pls check sceenshot "esx6.5-vddk6.5" and v2v debug log "esx5.5-vddk6.5.log"

Packages:
virt-v2v-1.42.0-3.module+el8.3.0+6497+b190d2a5.x86_64
libguestfs-1.42.0-1.module+el8.3.0+6496+d39ac712.x86_64
libvirt-client-6.3.0-1.module+el8.3.0+6478+69f490bb.x86_64
qemu-kvm-5.0.0-0.module+el8.3.0+6620+5d5e1420.x86_64
nbdkit-1.20.2-1.module+el8.3.0+6764+cc503f20.x86_64
VMware-vix-disklib-6.5.2-6195444.x86_64.tar.gz

Steps:

1.Convert a guest from ESXi5.5 via vddk6.5 by virt-v2v, there is no any progress at one conversion position after waiting for 2hours
#  virt-v2v -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 -it vddk -io vddk-libdir=/home/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D esx5.5-rhel6.10-x86_64 -on 5.5-have-vddk -ip /home/passwd -v -x |& ts
.....
May 27 12:58:02 nbdkit: vddk[2]: debug: cacheextents: can_cache
May 27 12:58:02 nbdkit: vddk[2]: debug: readahead: can_cache
May 27 12:58:02 nbdkit: vddk[2]: debug: cacheextents: can_extents
May 27 12:58:02 nbdkit: vddk[2]: debug: readahead: can_extents
May 27 12:58:02 nbdkit: vddk[2]: debug: retry: can_extents
May 27 12:58:02 nbdkit: vddk[2]: debug: vddk: can_extents
May 27 12:58:02 nbdkit: vddk[2]: debug: can_extents: VixDiskLib_QueryAllocatedBlocks == NULL, probably this is VDDK < 6.7
May 27 12:58:02 nbdkit: vddk[2]: debug: newstyle negotiation: flags: export 0x487
May 27 12:58:02 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE)
May 27 12:58:02 nbdkit: vddk[2]: debug: handshake complete, processing requests serially
Comment 4 mxie@redhat.com 2020-05-27 07:00:29 UTC 
Created attachment 1692569 [details]
esx5.5-vddk6.5.png
Comment 5 mxie@redhat.com 2020-05-27 07:01:43 UTC 
Created attachment 1692572 [details]
esx5.5-vddk6.5-hang.log
Comment 6 mxie@redhat.com 2020-05-27 08:11:23 UTC 
Add some research info for the bug:

Packages:
virt-v2v-1.42.0-3.module+el8.3.0+6497+b190d2a5.x86_64
libguestfs-1.42.0-1.module+el8.3.0+6496+d39ac712.x86_64
libvirt-client-6.3.0-1.module+el8.3.0+6478+69f490bb.x86_64
qemu-kvm-5.0.0-0.module+el8.3.0+6620+5d5e1420.x86_64
nbdkit-1.20.2-1.module+el8.3.0+6764+cc503f20.x86_64
VMware-vix-disklib-6.7.3-14389676.x86_64.tar.gz
VMware-vix-disklib-7.0.0-15832853.x86_64.tar.gz


Scenario1: ESXi5.5 + vddk6.7.3
1.1 v2v will not only hang during converting guest from ESXi5.5 via vddk6.7.3, but also meet the error of bug1709211 , pls check screenshot "esx6.5-vddk6.7.3-hang-picture" and v2v debug log "esx5.5-vddk6.7.3-hang.log"
#  virt-v2v -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 -it vddk -io vddk-libdir=/root/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D esx5.5-rhel6.10-x86_64 -on esx5.5-vddk6.7 -ip /home/passwd -v -x |& ts
......
May 27 14:16:07 nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvr_IOEx: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_MULTIIO_EX
May 27 14:16:07 nbdkit: vddk[2]: debug: DISKLIB-LIB   : RWv failed ioId: #1 (290) (34) .
May 27 14:16:07 nbdkit: vddk[2]: debug: VixDiskLib: Detected DiskLib error 290 (NBD_ERR_GENERIC).
May 27 14:16:07 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_Read: Read 128 sectors at 0 failed. Error 1 (Unknown error) (DiskLib error 290: NBD_ERR_GENERIC) at 5814.
May 27 14:16:07 nbdkit: vddk[2]: error: VixDiskLib_Read: Unknown error
May 27 14:16:07 nbdkit: vddk[2]: debug: pread failed: original errno = 5
May 27 14:16:07 nbdkit: vddk[2]: debug: retry 1: waiting 2 seconds before retrying
May 27 14:16:09 nbdkit: vddk[2]: debug: vddk: reopen readonly=1
May 27 14:16:09 nbdkit: vddk[2]: debug: vddk: finalize
May 27 14:16:09 nbdkit: vddk[2]: debug: vddk: close
May 27 14:16:09 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_Close (handle)
May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_Close: Close disk.
May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpSetError: Broken pipe
May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 32.
May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvr_Close: Failed to send close message: The operation experienced a network error (NFC_NETWORK_ERROR)
May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpSetError: Broken pipe
May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 32.
May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
.....
May 27 14:16:12 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_FreeInfo (info)
May 27 14:16:12 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_FreeInfo: Clean up VixDiskLib.


Scenario2: ESXi5.5 + vddk7.0
2.1 Have same result with scenario1, v2v will not only hang during converting guest from ESXi5.5 via vddk6.7.3, but also meet the error of bug1709211 , pls check screenshot "esx6.5-vddk7.0-hang-picture" and v2v debug log "esx5.5-vddk7.0-hang.log"
#  virt-v2v -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 -it vddk -io vddk-libdir=/home/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D esx5.5-rhel6.10-x86_64 -on esx5.5--vddk7.0 -ip /home/passwd -v -x |& ts
.....
May 27 15:40:41 nbdkit: vddk[2]: error: [NFC ERROR]NfcNetTcpSetError: Broken pipe
May 27 15:40:41 nbdkit: vddk[2]: error: [NFC ERROR]NfcNetTcpWrite: bWritten: -1. Errno: 32.
May 27 15:40:41 nbdkit: vddk[2]: error: [NFC ERROR]NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
May 27 15:40:41 nbdkit: vddk[2]: error: [NFC ERROR]NfcFssrvr_Close: Failed to send close message: The operation experienced a network error (NFC_NETWORK_ERROR)
May 27 15:40:41 nbdkit: vddk[2]: error: [NFC ERROR]NfcNetTcpSetError: Broken pipe
May 27 15:40:41 nbdkit: vddk[2]: error: [NFC ERROR]NfcNetTcpWrite: bWritten: -1. Errno: 32.
May 27 15:40:41 nbdkit: vddk[2]: error: [NFC ERROR]NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
.....
May 27 15:40:44 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_FreeInfo: Clean up VixDiskLib.
May 27 15:41:11 nbdkit: debug: 2020-05-27T15:41:11.590+08:00 warning -[21368] [Originator@6876 sub=Default] Closing Response processing in unexpected state: 3
Comment 7 mxie@redhat.com 2020-05-27 08:12:22 UTC 
Created attachment 1692596 [details]
esx5.5-vddk6.7.3-hang-picture.png
Comment 8 mxie@redhat.com 2020-05-27 08:12:54 UTC 
Created attachment 1692597 [details]
esx5.5-vddk7.0-hang-picture.png
Comment 9 mxie@redhat.com 2020-05-27 08:13:27 UTC 
Created attachment 1692598 [details]
esx5.5-vddk6.7.3-hang.log
Comment 10 mxie@redhat.com 2020-05-27 08:14:29 UTC 
Created attachment 1692600 [details]
esx5.5-vddk7.0-hang.log
Comment 11 mxie@redhat.com 2020-07-07 06:06:21 UTC 
Hi Richard,

   Did you do some fix in nbdkit recently? It's strange that I can't reproduce the bug with nbdkit-1.20.4-2.module+el8.3.0+7165+edc86943.x86_64 now, v2v can convert guest from ESXi5.5 host with vddk6.5,vddk6.7 and vddk7.0 successfully, can also find the success result in auto job, pls refer to https://libvirt-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/v2v/view/RHEL-8.3/job/v2v-RHEL-8.3-runtest-x86_64-acceptance-ovirt/10/testReport/rhel/convert_vm_to_ovirt/esx_vm_5_5_windows_win10_arch_x86_64_raw_f_NFS_rhv_upload_rhv_direct_rhv_verifypeer_nopreallocated_it_vddk/


Packages:
virt-v2v-1.42.0-5.module+el8.3.0+7152+ab3787c3.x86_64
libguestfs-1.42.0-2.module+el8.3.0+6798+ad6e66be.x86_64
libvirt-6.4.0-1.module+el8.3.0+6881+88468c00.x86_64
qemu-kvm-5.0.0-0.module+el8.3.0+6620+5d5e1420.x86_64
nbdkit-1.20.4-2.module+el8.3.0+7165+edc86943.x86_64


Scenario1: ESXi5.5 + vddk6.5
# virt-v2v -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 -it vddk -io vddk-libdir=/media/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D esx5.5-rhel6.10-x86_64 -on esx5.5-vddk6.5 -ip /home/passwd 
[   0.0] Opening the source -i libvirt -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 esx5.5-rhel6.10-x86_64 -it vddk  -io vddk-libdir=/media/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
[   1.7] Creating an overlay to protect the source from being modified
[   5.0] Opening the overlay
[  14.9] Inspecting the overlay
[  40.8] Checking for sufficient free disk space in the guest
[  40.8] Estimating space required on target for each disk
[  40.8] Converting Red Hat Enterprise Linux Workstation release 6.10 (Santiago) to run on KVM
virt-v2v: This guest has virtio drivers installed.
[ 243.5] Mapping filesystem data to avoid copying unused and blank areas
[ 244.8] Closing the overlay
[ 245.1] Assigning disks to buses
[ 245.1] Checking if the guest needs BIOS or UEFI to boot
[ 245.1] Initializing the target -o libvirt -os default
[ 245.2] Copying disk 1/1 to /var/lib/libvirt/images/esx5.5-vddk6.5-sda (raw)
    (100.00/100%)
[ 929.4] Creating output metadata
[ 930.1] Finishing off


Scenario2: ESXi5.5 + vddk6.7.3
# virt-v2v -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 -it vddk -io vddk-libdir=/root/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D esx5.5-rhel6.10-x86_64 -on esx5.5-vddk6.7 -ip /home/passwd 
[   0.0] Opening the source -i libvirt -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 esx5.5-rhel6.10-x86_64 -it vddk  -io vddk-libdir=/root/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
[   1.7] Creating an overlay to protect the source from being modified
nbdkit: vddk[1]: error: [NFC ERROR] NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
nbdkit: vddk[1]: error: [NFC ERROR] NfcFssrvr_Close: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_CLOSE
[   5.0] Opening the overlay
nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvr_IOEx: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_MULTIIO_EX
nbdkit: vddk[2]: error: VixDiskLib_Read: Unknown error
nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpSetError: Broken pipe
nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 32.
nbdkit: vddk[2]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvr_Close: Failed to send close message: The operation experienced a network error (NFC_NETWORK_ERROR)
nbdkit: vddk[2]: error: SSL: Unknown SSL Error
nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpSetError: Success
nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 0.
nbdkit: vddk[2]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
[  19.3] Inspecting the overlay
[  41.2] Checking for sufficient free disk space in the guest
[  41.2] Estimating space required on target for each disk
[  41.2] Converting Red Hat Enterprise Linux Workstation release 6.10 (Santiago) to run on KVM
virt-v2v: This guest has virtio drivers installed.
[ 202.5] Mapping filesystem data to avoid copying unused and blank areas
[ 203.6] Closing the overlay
[ 203.9] Assigning disks to buses
[ 203.9] Checking if the guest needs BIOS or UEFI to boot
[ 203.9] Initializing the target -o libvirt -os default
[ 204.0] Copying disk 1/1 to /var/lib/libvirt/images/esx5.5-vddk6.7-sda (raw)
nbdkit: vddk[3]: error: [NFC ERROR] NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
nbdkit: vddk[3]: error: [NFC ERROR] NfcFssrvr_IOEx: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_MULTIIO_EX
nbdkit: vddk[3]: error: VixDiskLib_Read: Unknown error
nbdkit: vddk[3]: error: [NFC ERROR] NfcNetTcpSetError: Broken pipe
nbdkit: vddk[3]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 32.
nbdkit: vddk[3]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
nbdkit: vddk[3]: error: [NFC ERROR] NfcFssrvr_Close: Failed to send close message: The operation experienced a network error (NFC_NETWORK_ERROR)
nbdkit: vddk[3]: error: SSL: Unknown SSL Error
nbdkit: vddk[3]: error: [NFC ERROR] NfcNetTcpSetError: Success
nbdkit: vddk[3]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 0.
nbdkit: vddk[3]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
    (100.00/100%)
[ 756.7] Creating output metadata
[ 756.7] Finishing off


Scenario3: ESXi5.5 + vddk7.0
# virt-v2v -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 -it vddk -io vddk-libdir=/home/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D esx5.5-rhel6.10-x86_64 -on esx5.5-vddk7.0 -ip /home/passwd 
[   0.0] Opening the source -i libvirt -ic vpx://root.73.148/data/10.73.3.19/?no_verify=1 esx5.5-rhel6.10-x86_64 -it vddk  -io vddk-libdir=/home/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
[   1.7] Creating an overlay to protect the source from being modified
nbdkit: vddk[1]: error: VixDiskLib: VixDiskLib_Connect: Get CEIP status failed, treat CEIP as disabled. Invalid request. at 4844.
nbdkit: vddk[1]: error: [NFC ERROR]NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
nbdkit: vddk[1]: error: [NFC ERROR]NfcFssrvr_Close: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_CLOSE
[   5.3] Opening the overlay
nbdkit: vddk[2]: error: VixDiskLib: VixDiskLib_Connect: Get CEIP status failed, treat CEIP as disabled. Invalid request. at 4844.
nbdkit: vddk[2]: error: [NFC ERROR]NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
nbdkit: vddk[2]: error: [NFC ERROR]NfcFssrvr_IOEx: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_IO_EX
nbdkit: vddk[2]: error: VixDiskLib_Read: Unknown error
nbdkit: vddk[2]: error: [NFC ERROR]NfcNetTcpSetError: Broken pipe
nbdkit: vddk[2]: error: [NFC ERROR]NfcNetTcpWrite: bWritten: -1. Errno: 32.
nbdkit: vddk[2]: error: [NFC ERROR]NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
nbdkit: vddk[2]: error: [NFC ERROR]NfcFssrvr_Close: Failed to send close message: The operation experienced a network error (NFC_NETWORK_ERROR)
nbdkit: vddk[2]: error: SSL: Unknown SSL Error
nbdkit: vddk[2]: error: [NFC ERROR]NfcNetTcpSetError: Success
nbdkit: vddk[2]: error: [NFC ERROR]NfcNetTcpWrite: bWritten: -1. Errno: 0.
nbdkit: vddk[2]: error: [NFC ERROR]NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
nbdkit: vddk[2]: error: VixDiskLib: VixDiskLib_Connect: Get CEIP status failed, treat CEIP as disabled. Invalid request. at 4844.
[  20.1] Inspecting the overlay
[  42.0] Checking for sufficient free disk space in the guest
[  42.0] Estimating space required on target for each disk
[  42.0] Converting Red Hat Enterprise Linux Workstation release 6.10 (Santiago) to run on KVM
virt-v2v: This guest has virtio drivers installed.
[ 203.1] Mapping filesystem data to avoid copying unused and blank areas
[ 204.2] Closing the overlay
[ 204.6] Assigning disks to buses
[ 204.6] Checking if the guest needs BIOS or UEFI to boot
[ 204.6] Initializing the target -o libvirt -os default
[ 204.6] Copying disk 1/1 to /var/lib/libvirt/images/esx5.5-vddk7.0-sda (raw)
nbdkit: vddk[3]: error: VixDiskLib: VixDiskLib_Connect: Get CEIP status failed, treat CEIP as disabled. Invalid request. at 4844.
nbdkit: vddk[3]: error: [NFC ERROR]NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
nbdkit: vddk[3]: error: [NFC ERROR]NfcFssrvr_IOEx: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_IO_EX
nbdkit: vddk[3]: error: VixDiskLib_Read: Unknown error
nbdkit: vddk[3]: error: [NFC ERROR]NfcNetTcpSetError: Broken pipe
nbdkit: vddk[3]: error: [NFC ERROR]NfcNetTcpWrite: bWritten: -1. Errno: 32.
nbdkit: vddk[3]: error: [NFC ERROR]NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
nbdkit: vddk[3]: error: [NFC ERROR]NfcFssrvr_Close: Failed to send close message: The operation experienced a network error (NFC_NETWORK_ERROR)
nbdkit: vddk[3]: error: SSL: Unknown SSL Error
nbdkit: vddk[3]: error: [NFC ERROR]NfcNetTcpSetError: Success
nbdkit: vddk[3]: error: [NFC ERROR]NfcNetTcpWrite: bWritten: -1. Errno: 0.
nbdkit: vddk[3]: error: [NFC ERROR]NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
nbdkit: vddk[3]: error: VixDiskLib: VixDiskLib_Connect: Get CEIP status failed, treat CEIP as disabled. Invalid request. at 4844.
    (100.00/100%)
[ 763.5] Creating output metadata
[ 763.5] Finishing off
Comment 12 Richard W.M. Jones 2020-07-07 10:07:26 UTC 
> Did you do some fix in nbdkit recently? It's strange that I can't reproduce the bug with nbdkit-1.20.4-2.module+el8.3.0+7165+edc86943.x86_64 now

Yes indeed I did!  We fixed a problem with background threads upstream:

  https://www.redhat.com/archives/libguestfs/2020-June/msg00102.html
  https://www.redhat.com/archives/libguestfs/2020-June/msg00103.html

and I have backported all this to nbdkit in >= 1.20.4-2 (in RHEL AV 8.3.0).

This should fix a lot of "weird" problems we were having with VDDK including:

 - The one where it hangs for 2 minutes when connecting.

 - The one where it couldn't connect in some circumstances
   (https://bugzilla.redhat.com/show_bug.cgi?id=1846309#c9).
Comment 13 Richard W.M. Jones 2020-07-07 10:08:14 UTC 
Commits in RHEL AV 8.3.0:
https://github.com/libguestfs/nbdkit/commits/rhel-8.3
Comment 19 mxie@redhat.com 2020-07-08 15:39:24 UTC 
Hi rjones,

    Here is the test result after testing the bug on rhel8.3 fast stream, rhel8.3 slow stream and rhel8.2.1, I think your fix in nbdkit-1.20.4-2 already fixed the problem of comment2 of bug1709211. As I can't reproduce the bug now,please help to close the bug, thanks!

*Packages of rhel8.3 fast stream:
virt-v2v-1.42.0-5.module+el8.3.0+7152+ab3787c3.x86_64
libguestfs-1.42.0-2.module+el8.3.0+6798+ad6e66be.x86_64
libvirt-6.4.0-1.module+el8.3.0+6881+88468c00.x86_64
qemu-kvm-5.0.0-0.module+el8.3.0+6620+5d5e1420.x86_64
nbdkit-1.20.4-2.module+el8.3.0+7165+edc86943.x86_64

Result on rhel8.3 fast stream:
 ESXi5.5 + vddk6.5-> PASS
 ESXi5.5 + vddk6.7-> conversion can finish but has the NFC error(problem of comment0 of bug1709211)
 ESXi5.5 + vddk7.0-> conversion can finish but has the NFC error(problem of comment0 of bug1709211)

--------------------------
*Packages of rhel8.3 slow stream:
virt-v2v-1.40.2-24.module+el8.3.0+7176+57f10f42.x86_64
libguestfs-1.40.2-24.module+el8.3.0+7176+57f10f42.x86_64
libvirt-6.0.0-25.module+el8.3.0+7176+57f10f42.x86_64
qemu-kvm-4.2.0-29.module+el8.3.0+7212+401047e6.x86_64
nbdkit-1.16.2-4.module+el8.3.0+6922+fd575af8.x86_64

Result on rhel8.3 slow stream:
 ESXi5.5 + vddk6.5-> PASS 
 ESXi5.5 + vddk6.7-> conversion is failed (problem of comment2 of bug1709211)
 ESXi5.5 + vddk7.0-> conversion is failed (problem of comment2 of bug1709211)

--------------------------
*Packages of rhel8.2.1:
virt-v2v-1.40.2-24.module+el8.2.1+7154+47ffd890.x86_64
libguestfs-1.40.2-24.module+el8.2.1+7154+47ffd890.x86_64
libvirt-6.0.0-25.module+el8.2.1+7154+47ffd890.x86_64
qemu-kvm-4.2.0-28.module+el8.2.1+7211+16dfe810.x86_64
nbdkit-1.16.2-4.module+el8.2.1+6710+effcb1df.x86_64

Result on rhel8.2.1:
 ESXi5.5 + vddk6.5-> PASS 
 ESXi5.5 + vddk6.7-> conversion is failed (problem of comment2 of bug1709211)
 ESXi5.5 + vddk7.0-> conversion is failed (problem of comment2 of bug1709211)
Comment 20 Richard W.M. Jones 2020-07-09 08:17:32 UTC 
About:

nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpSetError: Broken pipe
nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 32.
nbdkit: vddk[2]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvr_IOEx: Failed to send io message: The operation experienced a network error (NFC_NETWORK_ERROR)
nbdkit: vddk[2]: error: VixDiskLib_Read: The server refused connection

(This is bug 1709211 comment 2, but is not related to bug 1709211 and does
not have its own bug number).  This bug might have been fixed by fixing
threading issues in VDDK, but I don't know for sure.  If it's gone away, then good.

--

About:

nbdkit: vddk[1]: error: [NFC ERROR] NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
nbdkit: vddk[1]: error: [NFC ERROR] NfcFssrvr_Close: received unexpected message 4 from server

(Bug 1709211)  This bug has not been fixed in nbdkit 1.20.4.  It is
fixed upstream in nbdkit 1.21 but I did not backport the patch because
it's quite invasive, the bug is only cosmetic, and it only happens when
you use a rare combination of VMware ESXi (<= 5.5) and VDDK (>= 6.7)
together.  I moved bug 1709211 to RHEL AV 8.4.0 to give us more time
to test the patch upstream.

--

This bug is filed against RHEL AV 8.3.0, and seems to be fixed, so shall we
close this bug?
Comment 21 mxie@redhat.com 2020-07-10 13:48:18 UTC 
(In reply to Richard W.M. Jones from comment #20)
> About:
> 
> nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpSetError: Broken pipe
> nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 32.
> nbdkit: vddk[2]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed:
> NFC_NETWORK_ERROR
> nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvr_IOEx: Failed to send io
> message: The operation experienced a network error (NFC_NETWORK_ERROR)
> nbdkit: vddk[2]: error: VixDiskLib_Read: The server refused connection
> 
> (This is bug 1709211 comment 2, but is not related to bug 1709211 and does
> not have its own bug number).  This bug might have been fixed by fixing
> threading issues in VDDK, but I don't know for sure.  If it's gone away,
> then good.
>
 
Do I need to file a bug to track the problem of bug 1709211 comment 2 on rhel8.3 slow and rhel8.2.1?

> This bug is filed against RHEL AV 8.3.0, and seems to be fixed, so shall we
> close this bug?

Yes, please help close, thanks!
Comment 22 Richard W.M. Jones 2020-07-14 07:33:31 UTC 
Martin:

It looks as if we're going to use nbdkit in KubeVirt.  nbdkit in RHEL slow train 8.3.0
has some fairly serious bugs w.r.t. VDDK.  I have only fixed these in RHEL AV 8.3.0.

If we do nothing RHEL (slow) 8.3.0 will get the buggy package from RHEL AV 8.2.1,
but it will at least require no patching / work in RHEL slow train.

Now since I believe CNV/OSV will always(?) use RHEL AV, that would indicate there's
no need to bother fixing slow train, but I'd like your input on this.
Comment 23 Martin Tessun 2020-07-14 07:50:15 UTC 
(In reply to Richard W.M. Jones from comment #22)
> Martin:
> 
> It looks as if we're going to use nbdkit in KubeVirt.  nbdkit in RHEL slow
> train 8.3.0
> has some fairly serious bugs w.r.t. VDDK.  I have only fixed these in RHEL
> AV 8.3.0.
> 
> If we do nothing RHEL (slow) 8.3.0 will get the buggy package from RHEL AV
> 8.2.1,
> but it will at least require no patching / work in RHEL slow train.

Some questions on the necessity to get this fixed in RHEL 8.3:
1. nbdkit does only affect v2v from VMWare
2. nbdkit is no pre-requisite for doing so

In case the above is true (or RHEL v2v can work around/not use nbdkit, we can easily document this as unsupported usecase in RHEL 8 - and mention that it has quite some known issues that won't get fixed soon.
We probably need Jiri to document this then.

> 
> Now since I believe CNV/OSV will always(?) use RHEL AV, that would indicate
> there's
> no need to bother fixing slow train, but I'd like your input on this.

Ack from my side.
Adding Fabian and Jiri for awareness.
Comment 24 Richard W.M. Jones 2020-07-14 08:00:41 UTC 
(In reply to Martin Tessun from comment #23)
> (In reply to Richard W.M. Jones from comment #22)
> > Martin:
> > 
> > It looks as if we're going to use nbdkit in KubeVirt.  nbdkit in RHEL slow
> > train 8.3.0
> > has some fairly serious bugs w.r.t. VDDK.  I have only fixed these in RHEL
> > AV 8.3.0.
> > 
> > If we do nothing RHEL (slow) 8.3.0 will get the buggy package from RHEL AV
> > 8.2.1,
> > but it will at least require no patching / work in RHEL slow train.
> 
> Some questions on the necessity to get this fixed in RHEL 8.3:
> 1. nbdkit does only affect v2v from VMWare
> 2. nbdkit is no pre-requisite for doing so

At the moment nbdkit is required for v2v from VMware starting with
RHEL AV >= 8.3.0.  Virt-v2v will not work otherwise (from AV 8.3.0).

The issue is that (and this is only in the research stage) we are
looking into whether to use nbdkit much more in KubeVirt (and therefore OSV),
in which case it will be used for many import flows including basic importing
of KVM disk images from things like Amazon S3 buckets, Docker registries etc.
IOW it would become a required package for OSV.

That doesn't matter as long as OSV will always use RHEL AV (never slow train).
But if OSV will use slow train sometimes when we will need to pay attention
to bugs in RHEL, and there are several quite important bugs we found
recently which we are not planning to fix in RHEL non-AV 8.3.
Comment 27 Richard W.M. Jones 2020-07-14 11:20:52 UTC 
Closing this bug because it has gone away for reasons not fully understood.
However if observed again please feel free to reopen.  Note that
"NfcNetTcpSetError: Broken pipe" is something not related to this bug.