Bug 1996110

Summary: cdi importer fails for a CirrOS VM import to NFS (but not to Cepf-rbd/block)
Product: Container Native Virtualization (CNV) Reporter: Ilanit Stein <istein>
Component: V2VAssignee: Fabien Dupont <fdupont>
Status: CLOSED ERRATA QA Contact: kpunwatk
Severity: high Docs Contact:
Priority: high    
Version: 4.8.1CC: alitke, cnv-qe-bugs, fdupont, kpunwatk, marnold, mrashish, ycui
Target Milestone: ---Flags: istein: needinfo+
Target Release: 4.8.2   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-09-21 11:08:02 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
importer.log
none
Screenshot of VM Import fail none

Description Ilanit Stein 2021-08-20 15:05:52 UTC 
Created attachment 1816085 [details]
importer.log

Description of problem:
MTV migration of a CirrOS VM to NFS target storage is running endlessly.
The reason:
The VM import of a CirrOS VM to NFS target storage fails - the cdi importer pod crashes (importer pod log attached).

MTV migration of a CirrOS VM to Ceph-rbd/Block target storage ends successfully (the VM import it runs ends successfully). 

Version-Release number of selected component (if applicable):
CNV-4.8.1-18, iib-97626
MTV-2.1.0-53

How reproducible:
always
Comment 1 Maya Rashish 2021-08-22 08:02:35 UTC 
Bumped severity because I think that it's a bigger problem.

Might be because MTV assumes we round to 512 bytes in https://github.com/kubevirt/vm-import-operator/pull/479/files
But as of https://github.com/kubevirt/containerized-data-importer/pull/1873 we align to 1Mi (also backported to all release branches)
Comment 2 Fabien Dupont 2021-08-30 16:06:35 UTC 
Can you please verify with hco-bundle-registry-container-v4.8.2-9.
Comment 3 Fabien Dupont 2021-08-31 12:57:56 UTC 
Actually, it's not part of hco-bundle-registry-container-v4.8.2-9. Moving the BZ back to MODIFIED.
Comment 4 Fabien Dupont 2021-08-31 14:26:26 UTC 
Can you please verify with hco-bundle-registry-container-v4.8.2-10 ?
Comment 5 kpunwatk 2021-09-01 13:08:21 UTC 
Created attachment 1819642 [details]
Screenshot of VM Import fail
Comment 6 kpunwatk 2021-09-01 13:10:17 UTC 
Bug was tested on CNV-4.8.2-12 and it failed (Screenshot is attached)
Comment 7 Fabien Dupont 2021-09-01 14:19:03 UTC 
Is it possible to get the pod log? The screenshot shows that the pod is in CrashLoopBackoff state. So, the log may have more explicit info about why it fails.
Comment 8 Ilanit Stein 2021-09-01 16:14:17 UTC 
I0901 16:10:38.236729       1 importer.go:52] Starting importer
I0901 16:10:38.237170       1 importer.go:135] begin import process
I0901 16:10:38.332294       1 imageio-datasource.go:304] waiting for disk to unlock
I0901 16:10:54.198856       1 http-datasource.go:251] Attempting to get certs from /certs/ca.pem
I0901 16:10:54.212895       1 data-processor.go:323] Calculating available size
E0901 16:10:54.214515       1 data-processor.go:327] exit status 1, blockdev: ioctl error on BLKGETSIZE64: Inappropriate ioctl for device
I0901 16:10:54.214527       1 data-processor.go:335] Checking out file system volume size.
I0901 16:10:54.214629       1 data-processor.go:343] Request image size not empty.
I0901 16:10:54.214639       1 data-processor.go:348] Target size 42Mi.
I0901 16:10:54.215074       1 util.go:39] deleting file: /data/disk.img
I0901 16:10:54.215685       1 data-processor.go:231] New phase: TransferDataFile
I0901 16:10:54.216358       1 util.go:170] Writing data...
I0901 16:10:54.330444       1 data-processor.go:231] New phase: Resize
W0901 16:10:54.341011       1 data-processor.go:310] Available space less than requested size, resizing image to available space 40894464.
I0901 16:10:54.341031       1 data-processor.go:316] Expanding image size to: 40894464
E0901 16:10:54.345650       1 prlimit.go:174] qemu-img failed output is:
E0901 16:10:54.345664       1 prlimit.go:175] 
E0901 16:10:54.345673       1 prlimit.go:176] qemu-img: Use the --shrink option to perform a shrink operation.
qemu-img: warning: Shrinking an image will delete all data beyond the shrunken image's end. Before performing such an operation, make sure there is no important data there.

E0901 16:10:54.345698       1 data-processor.go:228] exit status 1
qemu-img execution failed
kubevirt.io/containerized-data-importer/pkg/system.executeWithLimits
        /remote-source/app/pkg/system/prlimit.go:178
kubevirt.io/containerized-data-importer/pkg/system.ExecWithLimits
        /remote-source/app/pkg/system/prlimit.go:111
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Resize
        /remote-source/app/pkg/image/qemu.go:160
kubevirt.io/containerized-data-importer/pkg/importer.ResizeImage
        /remote-source/app/pkg/importer/data-processor.go:317
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).resize
        /remote-source/app/pkg/importer/data-processor.go:268
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
        /remote-source/app/pkg/importer/data-processor.go:220
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
        /remote-source/app/pkg/importer/data-processor.go:165
main.main
        /remote-source/app/cmd/cdi-importer/importer.go:189
runtime.main
        /usr/lib/golang/src/runtime/proc.go:204
runtime.goexit
        /usr/lib/golang/src/runtime/asm_amd64.s:1374
Error resizing image /data/disk.img
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Resize
        /remote-source/app/pkg/image/qemu.go:163
kubevirt.io/containerized-data-importer/pkg/importer.ResizeImage
        /remote-source/app/pkg/importer/data-processor.go:317
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).resize
        /remote-source/app/pkg/importer/data-processor.go:268
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
        /remote-source/app/pkg/importer/data-processor.go:220
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
        /remote-source/app/pkg/importer/data-processor.go:165
main.main
        /remote-source/app/cmd/cdi-importer/importer.go:189
runtime.main
        /usr/lib/golang/src/runtime/proc.go:204
runtime.goexit
        /usr/lib/golang/src/runtime/asm_amd64.s:1374
Resize of image failed
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).resize
        /remote-source/app/pkg/importer/data-processor.go:270
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
        /remote-source/app/pkg/importer/data-processor.go:220
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
        /remote-source/app/pkg/importer/data-processor.go:165
main.main
        /remote-source/app/cmd/cdi-importer/importer.go:189
runtime.main
        /usr/lib/golang/src/runtime/proc.go:204
runtime.goexit
        /usr/lib/golang/src/runtime/asm_amd64.s:1374
Unable to resize disk image to requested size
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
        /remote-source/app/pkg/importer/data-processor.go:222
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
        /remote-source/app/pkg/importer/data-processor.go:165
main.main
        /remote-source/app/cmd/cdi-importer/importer.go:189
runtime.main
        /usr/lib/golang/src/runtime/proc.go:204
runtime.goexit
        /usr/lib/golang/src/runtime/asm_amd64.s:1374
E0901 16:10:54.345812       1 importer.go:191] exit status 1
qemu-img execution failed
kubevirt.io/containerized-data-importer/pkg/system.executeWithLimits
        /remote-source/app/pkg/system/prlimit.go:178
kubevirt.io/containerized-data-importer/pkg/system.ExecWithLimits
        /remote-source/app/pkg/system/prlimit.go:111
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Resize
        /remote-source/app/pkg/image/qemu.go:160
kubevirt.io/containerized-data-importer/pkg/importer.ResizeImage
        /remote-source/app/pkg/importer/data-processor.go:317
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).resize
        /remote-source/app/pkg/importer/data-processor.go:268
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
        /remote-source/app/pkg/importer/data-processor.go:220
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
        /remote-source/app/pkg/importer/data-processor.go:165
main.main
        /remote-source/app/cmd/cdi-importer/importer.go:189
runtime.main
        /usr/lib/golang/src/runtime/proc.go:204
runtime.goexit
        /usr/lib/golang/src/runtime/asm_amd64.s:1374
Error resizing image /data/disk.img
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Resize
        /remote-source/app/pkg/image/qemu.go:163
kubevirt.io/containerized-data-importer/pkg/importer.ResizeImage
        /remote-source/app/pkg/importer/data-processor.go:317
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).resize
        /remote-source/app/pkg/importer/data-processor.go:268
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
        /remote-source/app/pkg/importer/data-processor.go:220
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
        /remote-source/app/pkg/importer/data-processor.go:165
main.main
        /remote-source/app/cmd/cdi-importer/importer.go:189
runtime.main
        /usr/lib/golang/src/runtime/proc.go:204
runtime.goexit
        /usr/lib/golang/src/runtime/asm_amd64.s:1374
Resize of image failed
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).resize
        /remote-source/app/pkg/importer/data-processor.go:270
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
        /remote-source/app/pkg/importer/data-processor.go:220
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
        /remote-source/app/pkg/importer/data-processor.go:165
main.main
        /remote-source/app/cmd/cdi-importer/importer.go:189
runtime.main
        /usr/lib/golang/src/runtime/proc.go:204
runtime.goexit
        /usr/lib/golang/src/runtime/asm_amd64.s:1374
Unable to resize disk image to requested size
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
        /remote-source/app/pkg/importer/data-processor.go:222
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
        /remote-source/app/pkg/importer/data-processor.go:165
main.main
        /remote-source/app/cmd/cdi-importer/importer.go:189
runtime.main
        /usr/lib/golang/src/runtime/proc.go:204
runtime.goexit
        /usr/lib/golang/src/runtime/asm_amd64.s:1374
Comment 9 Adam Litke 2021-09-02 18:58:19 UTC 
Does this need a backport or can it be moved to ON_QA?  The 4.8.2 train is leaving the station soon and we need to get this finished or pushed out.
Comment 10 Fabien Dupont 2021-09-06 07:52:04 UTC 
It needs to be backported to 4.8, since the initial calculation change was backported to 4.8 and even further back.
Then, the decision to have it in 4.8.2 is not really mine. The code freeze is on Tuesday, September 7th, so we should be able to get it in, but today is Labor Day, so it might be tough.
Comment 11 Fabien Dupont 2021-09-07 20:27:23 UTC 
Please verify with hco-registry-bundle-container-v4.8.2-15 / iib:106992.
Comment 12 kpunwatk 2021-09-09 07:31:45 UTC 
Verified on CNV-4.8.2-15. The cdi Importer log given below:

I0909 05:28:02.838932       1 importer.go:52] Starting importer
I0909 05:28:02.840285       1 importer.go:135] begin import process
I0909 05:28:03.840096       1 http-datasource.go:251] Attempting to get certs from /certs/ca.pem
I0909 05:28:03.878360       1 data-processor.go:323] Calculating available size
I0909 05:28:03.880009       1 data-processor.go:335] Checking out file system volume size.
I0909 05:28:03.880549       1 data-processor.go:343] Request image size not empty.
I0909 05:28:03.880595       1 data-processor.go:348] Target size 1136234735.
I0909 05:28:03.883500       1 data-processor.go:231] New phase: TransferDataFile
I0909 05:28:03.886762       1 util.go:170] Writing data...
I0909 05:28:04.883925       1 prometheus.go:69] 100.00
I0909 05:28:05.884885       1 prometheus.go:69] 100.00
I0909 05:28:06.885250       1 prometheus.go:69] 100.00
I0909 05:28:07.239082       1 data-processor.go:231] New phase: Resize
W0909 05:28:07.459376       1 data-processor.go:310] Available space less than requested size, resizing image to available space 1073741824.
I0909 05:28:07.459416       1 data-processor.go:313] No need to resize image. Requested size: 1136234735, Image size: 1073741824.
I0909 05:28:07.459429       1 data-processor.go:237] Validating image
I0909 05:28:07.474175       1 data-processor.go:231] New phase: Complete
I0909 05:28:07.474427       1 importer.go:217] Import Complete
Comment 17 errata-xmlrpc 2021-09-21 11:08:02 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 (Moderate: OpenShift Virtualization 4.8.2 Images security and bug fix update), 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/RHSA-2021:3598