Bug 1884164

Summary: [v2v][VMware to CNV VM import API] Importer fails on "Unable to start nbdkit"
Product: Container Native Virtualization (CNV) Reporter: Ilanit Stein <istein>
Component: V2VAssignee: Fabien Dupont <fdupont>
Status: CLOSED ERRATA QA Contact: Ilanit Stein <istein>
Severity: high Docs Contact:
Priority: urgent    
Version: 2.5.0CC: cnv-qe-bugs, fdupont
Target Milestone: ---   
Target Release: 2.5.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: v2.5.0-274 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-11-17 13:24:55 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:

Description Ilanit Stein 2020-10-01 08:33:34 UTC 
Description of problem:
when trying to import  a RHEL7/8 VM from VM to CNV, importer fails on:
$ oc logs importer-vmw-import-harddisk1
I0930 18:22:15.998048       1 importer.go:52] Starting importer
I0930 18:22:15.998995       1 importer.go:116] begin import process
I0930 18:22:16.087579       1 vddk-datasource.go:99] VM 42037aff-4d6f-cf89-7979-e98cbc406c0e found in datacenter Datacenter:datacenter-2 @ /Datacenter: vm-390
I0930 18:22:16.094469       1 vddk-datasource.go:192] Unable to start nbdkit: exec: "nbdkit": executable file not found in $PATH
E0930 18:22:16.094603       1 importer.go:154] exec: "nbdkit": executable file not found in $PATH

Version-Release number of selected component (if applicable):
CNV-2.5 installed from osbs on Sep 30 2020.

How reproducible:
100%

Additional info - How it was tested:
Secret:
------
cat <<EOF | oc create -f -
---
apiVersion: v1
kind: Secret
metadata:
 name: vmw-secret
type: Opaque
stringData:
 vmware: |-
   # API URL of the vCenter or ESXi host
   apiUrl: "https://<Vcenter IP address>/sdk"
   # Username provided in the format of username@domain.
   username: <username>
   password: <password>
   # The certificate thumbprint of the vCenter or ESXi host, in colon-separated hexidecimal octets.
   thumbprint: 31:14:..
EOF

External mapping
----------------

cat <<EOF | oc create -f -
apiVersion: v2v.kubevirt.io/v1beta1
kind: ResourceMapping
metadata:
 name: example-vmware-resourcemappings
 namespace: default
spec:
  vmware:
    networkMappings:
    - source:
        name: VM Network # map network name to network attachment definition
      target: 
        name: pod
      type: pod
    storageMappings:
    - source:
        id: datastore-12 
      target: 
        name: nfs
EOF

VM import create
----------------
cat <<EOF | oc create -f -
apiVersion: v2v.kubevirt.io/v1beta1
kind: VirtualMachineImport
metadata:
  name: vmware-import-1
  namespace: default
spec:
  providerCredentialsSecret:
    name: vmw-secret
    namespace: default # optional, if not specified, use CR's namespace
  resourceMapping:
    name: example-vmware-resourcemappings
    namespace: default
  targetVmName: vmw-import
  startVm: false
  source:
    vmware:
      vm:
        id: 42037aff-4d6f-cf89-7979-e98cbc406c0e
EOF
Comment 2 Ilanit Stein 2020-10-07 19:22:15 UTC 
Verified on CNV-2.5 
$ oc get csv -n openshift-cnv  kubevirt-hyperconverged-operator.v2.5.0 -o yaml | grep createdAt
    createdAt: "2020-10-06 07:31:33"

VM import from VMware to CNV no longer fail on starting nbdkit.
importer log shows import is complete, however the VM import process got stuck at 75% (as seen in the CNV UI).

$ oc logs importer-vmw-import-harddisk1 -f
I1007 18:28:48.087668       1 importer.go:52] Starting importer
I1007 18:28:48.088830       1 importer.go:116] begin import process
I1007 18:28:48.182993       1 vddk-datasource.go:99] VM 42037aff-4d6f-cf89-7979-e98cbc406c0e found in datacenter Datacenter:datacenter-2 @ /Datacenter: vm-390
I1007 18:28:48.689831       1 vddk-datasource.go:119] Checking for nbdkit PID.
I1007 18:28:48.689903       1 vddk-datasource.go:133] nbdkit ready.
I1007 18:28:48.689945       1 data-processor.go:302] Calculating available size
I1007 18:28:48.691230       1 data-processor.go:314] Checking out file system volume size.
I1007 18:28:48.691672       1 data-processor.go:322] Request image size not empty.
I1007 18:28:48.691710       1 data-processor.go:327] Target size 25Gi.
I1007 18:28:51.952139       1 vddk-datasource.go:221] qemu-img info: format raw, backing file , virtual size 26843545600, actual size 0
I1007 18:28:51.952193       1 data-processor.go:224] New phase: TransferDataFile
I1007 18:28:51.960538       1 qemu.go:226] 0.00
I1007 18:29:08.044588       1 qemu.go:226] 1.03
I1007 18:29:08.750692       1 qemu.go:226] 2.06
I1007 18:29:09.382850       1 qemu.go:226] 3.09
I1007 18:29:09.971381       1 qemu.go:226] 4.12
I1007 18:29:10.695472       1 qemu.go:226] 5.15
I1007 18:29:11.561367       1 qemu.go:226] 6.19
I1007 18:29:13.184793       1 qemu.go:226] 7.22
I1007 18:29:13.621430       1 qemu.go:226] 8.25
I1007 18:29:14.321681       1 qemu.go:226] 9.28
I1007 18:29:16.356295       1 qemu.go:226] 10.37
I1007 18:29:20.744857       1 qemu.go:226] 11.40
I1007 18:29:21.288980       1 qemu.go:226] 12.44
I1007 18:29:21.929865       1 qemu.go:226] 13.47
I1007 18:29:22.551343       1 qemu.go:226] 14.50
I1007 18:29:23.174989       1 qemu.go:226] 15.53
I1007 18:29:23.916980       1 qemu.go:226] 16.56
I1007 18:29:24.450807       1 qemu.go:226] 17.59
I1007 18:29:25.051621       1 qemu.go:226] 18.62
I1007 18:29:25.658805       1 qemu.go:226] 19.65
I1007 18:29:26.223307       1 qemu.go:226] 20.68
I1007 18:29:26.904266       1 qemu.go:226] 21.71
I1007 18:29:27.460840       1 qemu.go:226] 22.74
I1007 18:29:28.060491       1 qemu.go:226] 23.78
I1007 18:29:28.678135       1 qemu.go:226] 24.81
I1007 18:29:29.278831       1 qemu.go:226] 25.84
I1007 18:29:29.803853       1 qemu.go:226] 26.87
I1007 18:29:30.369784       1 qemu.go:226] 27.90
I1007 18:29:30.941296       1 qemu.go:226] 28.93
I1007 18:29:31.476964       1 qemu.go:226] 29.96
I1007 18:29:32.054337       1 qemu.go:226] 30.99
I1007 18:29:34.185366       1 qemu.go:226] 32.09
I1007 18:29:34.453802       1 qemu.go:226] 33.12
I1007 18:29:35.044731       1 qemu.go:226] 34.15
I1007 18:29:35.670436       1 qemu.go:226] 35.18
I1007 18:29:36.220310       1 qemu.go:226] 36.21
I1007 18:29:36.736704       1 qemu.go:226] 37.24
I1007 18:29:37.316858       1 qemu.go:226] 38.27
I1007 18:29:37.968648       1 qemu.go:226] 39.30
I1007 18:29:38.608910       1 qemu.go:226] 40.34
I1007 18:29:39.334657       1 qemu.go:226] 41.37
I1007 18:29:39.957794       1 qemu.go:226] 42.40
I1007 18:29:40.592771       1 qemu.go:226] 43.43
I1007 18:29:41.304063       1 qemu.go:226] 44.46
I1007 18:29:42.129509       1 qemu.go:226] 45.49
I1007 18:29:42.816460       1 qemu.go:226] 46.52
I1007 18:29:43.441778       1 qemu.go:226] 47.55
I1007 18:29:44.180272       1 qemu.go:226] 48.58
I1007 18:29:44.816941       1 qemu.go:226] 49.61
I1007 18:29:47.075473       1 qemu.go:226] 50.71
I1007 18:29:47.456090       1 qemu.go:226] 51.74
I1007 18:29:48.024994       1 qemu.go:226] 52.77
I1007 18:29:48.681491       1 qemu.go:226] 53.80
I1007 18:29:49.293407       1 qemu.go:226] 54.83
I1007 18:29:49.875923       1 qemu.go:226] 55.86
I1007 18:29:50.458412       1 qemu.go:226] 56.89
I1007 18:29:51.064783       1 qemu.go:226] 57.93
I1007 18:29:51.680032       1 qemu.go:226] 58.96
I1007 18:29:52.313480       1 qemu.go:226] 59.99
I1007 18:29:52.891010       1 qemu.go:226] 61.02
I1007 18:29:53.544079       1 qemu.go:226] 62.05
I1007 18:29:54.059974       1 qemu.go:226] 63.08
I1007 18:29:54.546386       1 qemu.go:226] 64.11
I1007 18:29:55.103828       1 qemu.go:226] 65.14
I1007 18:29:55.915086       1 qemu.go:226] 66.17
I1007 18:29:56.649306       1 qemu.go:226] 67.20
I1007 18:29:57.351458       1 qemu.go:226] 68.23
I1007 18:29:58.006997       1 qemu.go:226] 69.27
I1007 18:29:58.659531       1 qemu.go:226] 70.30
I1007 18:29:59.258446       1 qemu.go:226] 71.33
I1007 18:29:59.805130       1 qemu.go:226] 72.36
I1007 18:30:00.291559       1 qemu.go:226] 73.39
I1007 18:30:02.695845       1 qemu.go:226] 74.48
I1007 18:30:02.877923       1 qemu.go:226] 75.52
I1007 18:30:03.504287       1 qemu.go:226] 76.55
I1007 18:30:03.985763       1 qemu.go:226] 77.58
I1007 18:30:04.532936       1 qemu.go:226] 78.61
I1007 18:30:05.133104       1 qemu.go:226] 79.64
I1007 18:30:05.810857       1 qemu.go:226] 80.67
I1007 18:30:06.514043       1 qemu.go:226] 81.70
I1007 18:30:07.111706       1 qemu.go:226] 82.73
I1007 18:30:07.844034       1 qemu.go:226] 83.76
I1007 18:30:08.673638       1 qemu.go:226] 84.79
I1007 18:30:09.381229       1 qemu.go:226] 85.82
I1007 18:30:10.134453       1 qemu.go:226] 86.86
I1007 18:30:11.027814       1 qemu.go:226] 87.89
I1007 18:30:11.893350       1 qemu.go:226] 88.92
I1007 18:30:12.649712       1 qemu.go:226] 89.95
I1007 18:30:13.444735       1 qemu.go:226] 90.98
I1007 18:30:14.287100       1 qemu.go:226] 92.01
I1007 18:30:14.996509       1 qemu.go:226] 93.04
I1007 18:30:15.846067       1 qemu.go:226] 94.07
I1007 18:30:16.573176       1 qemu.go:226] 95.10
I1007 18:30:17.267115       1 qemu.go:226] 96.13
I1007 18:30:17.890537       1 qemu.go:226] 97.16
I1007 18:30:18.610796       1 qemu.go:226] 98.20
I1007 18:30:19.219991       1 qemu.go:226] 99.23
I1007 18:30:22.614062       1 data-processor.go:224] New phase: Complete
I1007 18:30:22.614342       1 importer.go:189] Import complete
Comment 5 errata-xmlrpc 2020-11-17 13:24:55 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (OpenShift Virtualization 2.5.0 Images), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2020:5127