Bug 1893529

Summary: [v2v][VM import from RHV to CNV] VM import resource is removed, when there's no space left on target Ceph-RBD/Block storage
Product: Container Native Virtualization (CNV) Reporter: Ilanit Stein <istein>
Component: V2VAssignee: Piotr Kliczewski <pkliczew>
Status: CLOSED NOTABUG QA Contact: Ilanit Stein <istein>
Severity: high Docs Contact:
Priority: unspecified    
Version: 2.5.0CC: cnv-qe-bugs, fdupont
Target Milestone: ---   
Target Release: future   
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-02-22 07:51:18 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:
Bug Depends On: 1858595    
Bug Blocks:    

Description Ilanit Stein 2020-11-01 13:33:10 UTC 
When importing from RHV to CNV a VM with a 100GB disk that is larger 
then the Ceph-RBD/Block available space - 50GB, the VM import is hanging for some time on 39%, while the cdi importer pod keeps reporting 47%.
There is no notification to the user that there a problem with the import

After a couple of minutes, the importer pod failed, and began a "New phase" that showed 0% progress. 
See below the importer pod log.

After the cdi importer pod gets into a "crash loopback" state it is going back to status "running".
Eventually, after a couple of "New phase" trials of the cdi importer pod turn into a "Terminating" state.
The VM import is removed automatically.
 
The Ceph-RBD/Block storage that was populated cannot be released in no means.

Importer pod log:
================
Part of the cdi importer log that we managed to capture:
1029 16:00:16.785152       1 importer.go:52] Starting importer
I1029 16:00:16.786785       1 importer.go:116] begin import process
I1029 16:00:18.495650       1 http-datasource.go:219] Attempting to get certs from /certs/ca.pem
I1029 16:00:18.546153       1 data-processor.go:302] Calculating available size
I1029 16:00:18.547157       1 data-processor.go:310] Checking out block volume size.
I1029 16:00:18.547170       1 data-processor.go:322] Request image size not empty.
I1029 16:00:18.547199       1 data-processor.go:327] Target size 100Gi.
I1029 16:00:18.547320       1 data-processor.go:224] New phase: TransferDataFile
I1029 16:00:18.548337       1 util.go:161] Writing data...
I1029 16:00:19.547661       1 prometheus.go:69] 0.00
...
I1029 16:02:57.603779       1 prometheus.go:69] 0.01
E1029 16:02:58.540140       1 util.go:163] Unable to write file from dataReader: unexpected EOF
E1029 16:02:58.540307       1 data-processor.go:221] unexpected EOF
unable to write to file
kubevirt.io/containerized-data-importer/pkg/util.StreamDataToFile
	/go/src/kubevirt.io/containerized-data-importer/pkg/util/util.go:165
kubevirt.io/containerized-data-importer/pkg/importer.(*ImageioDataSource).TransferFile
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/imageio-datasource.go:115
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:191
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:153
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:171
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1357
Unable to transfer source data to target file
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:193
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:153
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:171
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1357
E1029 16:02:58.540491       1 importer.go:173] unexpected EOF
unable to write to file
kubevirt.io/containerized-data-importer/pkg/util.StreamDataToFile
	/go/src/kubevirt.io/containerized-data-importer/pkg/util/util.go:165
kubevirt.io/containerized-data-importer/pkg/importer.(*ImageioDataSource).TransferFile
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/imageio-datasource.go:115
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:191
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:153
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:171
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1357
Unable to transfer source data to target file
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:193
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:153
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:171
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1357
 
Version-Release number of selected component (if applicable):
CNV-2.5: iib-22696 hco-v2.5.0-396

How reproducible:
100%

Expected results:
The VM import should not be removed

Additional info:
This is also related to VM import from VMware to CNV via api (vmio).
For VMware, it is also not possible to release the Ceph-RBD resource,
and there is no suitable error that indicate the issue.
Comment 1 Fabien Dupont 2020-11-04 12:42:07 UTC 
https://bugzilla.redhat.com/show_bug.cgi?id=1858595 has been closed. I think we can't do more in VMIO if CDI doesn't report an error.

Ilanit what do you think?
Comment 2 Ilanit Stein 2020-11-04 13:28:51 UTC 
I agree. 

This bug is asking not to remove automatically the VM import resource, n case there's not enough space.
 
Bug 1858595 was closed since it was about an event generated based on an error from CDI, that is no longer generated.  

We have this other bug, on storage team:
Bug 1893526 - [v2v][VM import] No space left on the target Ceph-RBD/Block is not reported to the user.
Once resolved, vmio will be able to reflect the error to the user in the VM import status.
Comment 3 Fabien Dupont 2021-01-28 13:16:31 UTC 
Ilanit, can you please try to reproduce with 2.6.0.
Comment 4 Ilanit Stein 2021-02-22 07:51:18 UTC 
Tested on CNV-2.6.0 iib:42387.

In case there is not enough space on the Ceph-RBD/Block, this is the result:
1. VM import starts
2. VM is created
3. Importer pod fails
4. The PV/PVC is deleted. 
5. VM is removed
6. VM imports remains in the system (checked overnight that it stays there) 


This result is different than what we had on CNV-2.5.
On CNV-2.6.0 the Ceph-rbd block is cleared after the importer fails on not enough space. 
While on CNV-2.5, it was not cleared, there was no way to clear the space, and reuse that ceph-RBD/Block (unless more storage units are added).

Another difference is that on CNV-2.5 the VM import was eventually removed. and on CNV-2.6.0 the VM import remains.

After VM import failed, in order to verify that the space was indeed freed, 
I imported to Ceph-RBD/Block a second VM that it's disk size is also above the free space -
It resulted the same as the first VM import. That is the PVC/PV were created, and cleared at the end.  

Error displayed aside the VM import object in UI:
"Import error (RHV)
istein-test could not be imported.
DataVolumeCreationFailed: Error while importing disk image: istein-test-ef579c3f-14d8-41cf-aa03-2ee9e1102688. Unable to process data: read tcp 10.129.3.134:60974->10.1.37.103:54322: read: connection reset by peer (pod CrashLoopBackoff restart exceeded)"


Importer logs:

First log:
=========
I0221 17:24:52.875897       1 importer.go:52] Starting importer
I0221 17:24:52.877197       1 importer.go:132] begin import process
I0221 17:24:53.996176       1 http-datasource.go:214] Attempting to get certs from /certs/ca.pem
I0221 17:24:54.242183       1 data-processor.go:350] Calculating available size
I0221 17:24:54.243915       1 data-processor.go:358] Checking out block volume size.
I0221 17:24:54.243930       1 data-processor.go:370] Request image size not empty.
I0221 17:24:54.243944       1 data-processor.go:375] Target size 100Gi.
I0221 17:24:54.244106       1 data-processor.go:242] New phase: TransferDataFile
I0221 17:24:54.244951       1 util.go:161] Writing data...
I0221 17:24:55.244491       1 prometheus.go:69] 8.24
I0221 17:24:56.244622       1 prometheus.go:69] 17.40
I0221 17:24:57.244826       1 prometheus.go:69] 26.66
I0221 17:24:58.244998       1 prometheus.go:69] 35.61
I0221 17:24:59.245185       1 prometheus.go:69] 43.53
I0221 17:25:00.245398       1 prometheus.go:69] 51.62
I0221 17:25:01.245560       1 prometheus.go:69] 59.15
I0221 17:25:02.245698       1 prometheus.go:69] 66.68
I0221 17:25:03.245843       1 prometheus.go:69] 74.23
I0221 17:25:04.245984       1 prometheus.go:69] 81.04
I0221 17:25:05.246151       1 prometheus.go:69] 89.03
I0221 17:25:06.246294       1 prometheus.go:69] 96.11
I0221 17:25:07.246459       1 prometheus.go:69] 100.00
I0221 17:25:08.246631       1 prometheus.go:69] 100.00
I0221 17:25:09.246815       1 prometheus.go:69] 100.00
I0221 17:25:10.246993       1 prometheus.go:69] 100.00
I0221 17:25:11.247679       1 prometheus.go:69] 100.00
I0221 17:25:12.247824       1 prometheus.go:69] 100.00
...

Second log:
==========
I0221 17:45:56.052832       1 importer.go:52] Starting importer
I0221 17:45:56.054816       1 importer.go:132] begin import process
E0221 17:45:56.450184       1 importer.go:148] Fault reason is "Operation Failed". Fault detail is "[Cannot transfer Virtual Disk: The following disks are locked: VM_Disk. Please try again in a few minutes.]". HTTP response code is "409". HTTP response message is "409 Conflict".
Error sending transfer image request
kubevirt.io/containerized-data-importer/pkg/importer.getTransfer
	/remote-source/app/pkg/importer/imageio-datasource.go:272
kubevirt.io/containerized-data-importer/pkg/importer.createImageioReader
	/remote-source/app/pkg/importer/imageio-datasource.go:184
kubevirt.io/containerized-data-importer/pkg/importer.NewImageioDataSource
	/remote-source/app/pkg/importer/imageio-datasource.go:60
main.main
	/remote-source/app/cmd/cdi-importer/importer.go:146
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1373

Third log:
=========
I0221 17:47:35.389210       1 importer.go:52] Starting importer
I0221 17:47:35.390612       1 importer.go:132] begin import process
I0221 17:47:36.452324       1 http-datasource.go:214] Attempting to get certs from /certs/ca.pem
I0221 17:47:36.480945       1 data-processor.go:350] Calculating available size
I0221 17:47:36.482117       1 data-processor.go:358] Checking out block volume size.
I0221 17:47:36.482136       1 data-processor.go:370] Request image size not empty.
I0221 17:47:36.482155       1 data-processor.go:375] Target size 100Gi.
I0221 17:47:36.482403       1 data-processor.go:242] New phase: TransferDataFile
I0221 17:47:36.486322       1 util.go:161] Writing data...
I0221 17:47:37.482640       1 prometheus.go:69] 8.29
I0221 17:47:38.483047       1 prometheus.go:69] 15.05
I0221 17:47:39.483224       1 prometheus.go:69] 21.49
I0221 17:47:40.483423       1 prometheus.go:69] 27.67
I0221 17:47:41.483616       1 prometheus.go:69] 34.51
I0221 17:47:42.483800       1 prometheus.go:69] 40.30
I0221 17:47:43.483906       1 prometheus.go:69] 47.22
I0221 17:47:44.484092       1 prometheus.go:69] 54.43
I0221 17:47:45.484252       1 prometheus.go:69] 61.34
I0221 17:47:46.484534       1 prometheus.go:69] 68.04
I0221 17:47:47.484742       1 prometheus.go:69] 74.28
I0221 17:47:48.484853       1 prometheus.go:69] 81.08
I0221 17:47:49.484986       1 prometheus.go:69] 87.40
I0221 17:47:50.485127       1 prometheus.go:69] 94.66
I0221 17:47:51.485294       1 prometheus.go:69] 100.00
I0221 17:47:52.485551       1 prometheus.go:69] 100.00
I0221 17:47:53.485793       1 prometheus.go:69] 100.00
I0221 17:47:54.485954       1 prometheus.go:69] 100.00
I0221 17:47:55.486142       1 prometheus.go:69] 100.00
I0221 17:47:56.486296       1 prometheus.go:69] 100.00
I0221 17:47:57.486435       1 prometheus.go:69] 100.00
I0221 17:47:58.487229       1 prometheus.go:69] 100.00
I0221 17:47:59.487393       1 prometheus.go:69] 100.00
I0221 17:48:00.487494       1 prometheus.go:69] 100.00
I0221 17:48:01.487587       1 prometheus.go:69] 100.00
I0221 17:48:02.487738       1 prometheus.go:69] 100.00
I0221 17:48:03.487921       1 prometheus.go:69] 100.00
I0221 17:48:04.488080       1 prometheus.go:69] 100.00
I0221 17:48:05.488412       1 prometheus.go:69] 100.00
I0221 17:48:06.488564       1 prometheus.go:69] 100.00
I0221 17:48:07.489402       1 prometheus.go:69] 100.00
I0221 17:48:08.489505       1 prometheus.go:69] 100.00
I0221 17:48:09.490402       1 prometheus.go:69] 100.00
I0221 17:48:10.490590       1 prometheus.go:69] 100.00
I0221 17:48:11.491733       1 prometheus.go:69] 100.00
I0221 17:48:12.492807       1 prometheus.go:69] 100.00
I0221 17:48:13.492975       1 prometheus.go:69] 100.00
I0221 17:48:14.493203       1 prometheus.go:69] 100.00
I0221 17:48:15.493370       1 prometheus.go:69] 100.00
I0221 17:48:16.493463       1 prometheus.go:69] 100.00
I0221 17:48:17.494170       1 prometheus.go:69] 100.00
I0221 17:48:18.494515       1 prometheus.go:69] 100.00
I0221 17:48:19.494719       1 prometheus.go:69] 100.00
I0221 17:48:20.494997       1 prometheus.go:69] 100.00
I0221 17:48:21.495307       1 prometheus.go:69] 100.00
I0221 17:48:22.495438       1 prometheus.go:69] 100.00
I0221 17:48:23.495780       1 prometheus.go:69] 100.00
I0221 17:48:24.495987       1 prometheus.go:69] 100.00
I0221 17:48:25.496127       1 prometheus.go:69] 100.00
I0221 17:48:26.496335       1 prometheus.go:69] 100.00
I0221 17:48:27.496704       1 prometheus.go:69] 100.00
I0221 17:48:28.496941       1 prometheus.go:69] 100.00
I0221 17:48:29.497128       1 prometheus.go:69] 100.00
I0221 17:48:30.497345       1 prometheus.go:69] 100.00
I0221 17:48:31.497950       1 prometheus.go:69] 100.00
I0221 17:48:32.498067       1 prometheus.go:69] 100.00
I0221 17:48:33.498473       1 prometheus.go:69] 100.00
I0221 17:48:34.499054       1 prometheus.go:69] 100.00
I0221 17:48:35.500188       1 prometheus.go:69] 100.00
I0221 17:48:36.500602       1 prometheus.go:69] 100.00
I0221 17:48:37.501551       1 prometheus.go:69] 100.00
I0221 17:48:38.502094       1 prometheus.go:69] 100.00
I0221 17:48:39.502371       1 prometheus.go:69] 100.00
I0221 17:48:40.502449       1 prometheus.go:69] 100.00
I0221 17:48:41.502871       1 prometheus.go:69] 100.00
I0221 17:48:42.502990       1 prometheus.go:69] 100.00
I0221 17:48:43.503410       1 prometheus.go:69] 100.00
I0221 17:48:44.503664       1 prometheus.go:69] 100.00
I0221 17:48:45.504294       1 prometheus.go:69] 100.00
I0221 17:48:46.504404       1 prometheus.go:69] 100.00
I0221 17:48:47.504529       1 prometheus.go:69] 100.00
I0221 17:48:48.504726       1 prometheus.go:69] 100.00
I0221 17:48:49.505020       1 prometheus.go:69] 100.00
I0221 17:48:50.505986       1 prometheus.go:69] 100.00
I0221 17:48:51.506556       1 prometheus.go:69] 100.00
I0221 17:48:52.506700       1 prometheus.go:69] 100.00
I0221 17:48:53.506924       1 prometheus.go:69] 100.00
I0221 17:48:54.507449       1 prometheus.go:69] 100.00
I0221 17:48:55.507639       1 prometheus.go:69] 100.00
I0221 17:48:56.507811       1 prometheus.go:69] 100.00
I0221 17:48:57.507891       1 prometheus.go:69] 100.00
I0221 17:48:58.508022       1 prometheus.go:69] 100.00
E0221 17:48:59.040881       1 util.go:163] Unable to write file from dataReader: read tcp 10.129.3.143:59020->10.1.37.103:54322: read: connection reset by peer
E0221 17:48:59.040996       1 data-processor.go:239] read tcp 10.129.3.143:59020->10.1.37.103:54322: read: connection reset by peer
unable to write to file
kubevirt.io/containerized-data-importer/pkg/util.StreamDataToFile
	/remote-source/app/pkg/util/util.go:165
kubevirt.io/containerized-data-importer/pkg/importer.(*ImageioDataSource).TransferFile
	/remote-source/app/pkg/importer/imageio-datasource.go:115
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/remote-source/app/pkg/importer/data-processor.go:209
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/remote-source/app/pkg/importer/data-processor.go:171
main.main
	/remote-source/app/cmd/cdi-importer/importer.go:187
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1373
Unable to transfer source data to target file
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/remote-source/app/pkg/importer/data-processor.go:211
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/remote-source/app/pkg/importer/data-processor.go:171
main.main
	/remote-source/app/cmd/cdi-importer/importer.go:187
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1373
E0221 17:48:59.041081       1 importer.go:189] read tcp 10.129.3.143:59020->10.1.37.103:54322: read: connection reset by peer
unable to write to file
kubevirt.io/containerized-data-importer/pkg/util.StreamDataToFile
	/remote-source/app/pkg/util/util.go:165
kubevirt.io/containerized-data-importer/pkg/importer.(*ImageioDataSource).TransferFile
	/remote-source/app/pkg/importer/imageio-datasource.go:115
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/remote-source/app/pkg/importer/data-processor.go:209
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/remote-source/app/pkg/importer/data-processor.go:171
main.main
	/remote-source/app/cmd/cdi-importer/importer.go:187
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1373
Unable to transfer source data to target file
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/remote-source/app/pkg/importer/data-processor.go:211
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/remote-source/app/pkg/importer/data-processor.go:171
main.main
	/remote-source/app/cmd/cdi-importer/importer.go:187
runtime.main
	/usr/lib/golang/src/runtime/proc.go:203
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1373


Closing this bug, based on the above that the VM import remains in the system and not cleared on CNV-2.6.0.