1893526 – [v2v][VM import] No space left on the target Ceph-RBD/Block is not reported to the user

Bug 1893526 - [v2v][VM import] No space left on the target Ceph-RBD/Block is not reported to the user

Summary: [v2v][VM import] No space left on the target Ceph-RBD/Block is not reported t...

Keywords:
Status:	CLOSED DUPLICATE of bug 1893528
Alias:	None
Product:	Container Native Virtualization (CNV)
Classification:	Red Hat
Component:	Storage
Sub Component:
Version:	2.5.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	high
Target Milestone:	---
Target Release:	4.9.0
Assignee:	Maya Rashish
QA Contact:	Kevin Alon Goldblatt
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2020-11-01 13:19 UTC by Ilanit Stein
Modified:	2021-07-25 08:56 UTC (History)
CC List:	7 users (show)
Fixed In Version:	CNV v4.9.0-32
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2021-07-25 08:56:22 UTC
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Github	kubevirt containerized-data-importer pull 1818	0	None	open	Add a datavolume condition for the image being too large	2021-06-03 10:16:06 UTC

Description Ilanit Stein 2020-11-01 13:19:54 UTC

Description of problem:
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 report that the target storage run out of space.

Additional info:
This but 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 Piotr Kliczewski 2020-11-02 08:33:52 UTC

First, let's make sure that CDI reports this properly and later we can propagate this info to the end user.

Comment 2 Natalie Gavrielov 2020-11-11 13:23:43 UTC

Ilanit, can you please run (right after the failure occurs): 
oc describe dv dv-name 
oc get events -n namespace

Comment 3 Fabien Dupont 2020-11-18 15:34:37 UTC

@alitke can you please triage this BZ?

Comment 4 Natalie Gavrielov 2020-12-02 13:25:14 UTC

We think that we are already reporting this information, should be seen when running:
oc describe dv dv-name 
oc get events -n namespace

Ilanit, can you please try running the scenario again, and supply this info?

Comment 5 Ilanit Stein 2020-12-22 10:54:43 UTC

@Natalie,
I provided the requested details below.
the behavior is still the same on CNV-2.5.1

I ran VM import from RHV for a VM with 100GB disk to CNV Ceph-RBD/Block twice on OCP-4.6/CNV-2.5.1, with Ceph of 65GB capacity.

On the first trial VM import failed very quickly with "DataVolumeCreationFailed" error displayed in VM import page.
events log) showed a communication error, and then that disk is locked. cdi importer pod terminated very quickly.
I filed a bug asking to propagate the error to the user in such a case - bug 1910019.

On the second trial VM import progressed well, till the point is got out of space.

oc describe at the beginning of the import:
$ oc describe dv v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c -n openshift-cnv
Name:         v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c
Namespace:    openshift-cnv
Labels:       <none>
Annotations:  <none>
API Version:  cdi.kubevirt.io/v1beta1
Kind:         DataVolume
Metadata:
  Creation Timestamp:  2020-12-22T09:36:52Z
  Generation:          104
  Managed Fields:
    API Version:  cdi.kubevirt.io/v1alpha1
    Fields Type:  FieldsV1
    fieldsV1:
      f:metadata:
        f:ownerReferences:
      f:spec:
        .:
        f:pvc:
          .:
          f:accessModes:
          f:resources:
            .:
            f:requests:
              .:
              f:storage:
          f:storageClassName:
          f:volumeMode:
        f:source:
          .:
          f:imageio:
            .:
            f:certConfigMap:
            f:diskId:
            f:secretRef:
            f:url:
      f:status:
    Manager:      vm-import-controller
    Operation:    Update
    Time:         2020-12-22T09:36:52Z
    API Version:  cdi.kubevirt.io/v1beta1
    Fields Type:  FieldsV1
    fieldsV1:
      f:status:
        f:conditions:
        f:phase:
        f:progress:
    Manager:    virt-cdi-controller
    Operation:  Update
    Time:       2020-12-22T09:40:35Z
  Owner References:
    API Version:           v2v.kubevirt.io/v1beta1
    Block Owner Deletion:  true
    Controller:            true
    Kind:                  VirtualMachineImport
    Name:                  vm-import-v2vmigrationvm0-gls9l
    UID:                   cb963e5b-d297-4147-85d8-36a21658baa5
    API Version:           kubevirt.io/v1alpha3
    Block Owner Deletion:  true
    Controller:            false
    Kind:                  VirtualMachine
    Name:                  v2vmigrationvm0
    UID:                   0b25fcba-73d1-4f86-8f25-a91942f8716a
  Resource Version:        4453917
  Self Link:               /apis/cdi.kubevirt.io/v1beta1/namespaces/openshift-cnv/datavolumes/v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c
  UID:                     d8f8ac1b-5fa0-496c-9323-7998d4c31c17
Spec:
  Pvc:
    Access Modes:
      ReadWriteMany
    Resources:
      Requests:
        Storage:         100Gi
    Storage Class Name:  ocs-storagecluster-ceph-rbd
    Volume Mode:         Block
  Source:
    Imageio:
      Cert Config Map:  vmimport.v2v.kubevirt.ioz8smj
      Disk Id:          03072434-e45b-430c-8860-ff50b0c71a2c
      Secret Ref:       vmimport.v2v.kubevirt.iolkqlw
      URL:              https://rhev-blue-01.rdu2.scalelab.redhat.com/ovirt-engine/api
Status:
  Conditions:
    Last Heartbeat Time:   2020-12-22T09:37:04Z
    Last Transition Time:  2020-12-22T09:37:04Z
    Message:               PVC v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c Bound
    Reason:                Bound
    Status:                True
    Type:                  Bound
    Last Heartbeat Time:   2020-12-22T09:40:35Z
    Last Transition Time:  2020-12-22T09:36:53Z
    Reason:                TransferRunning
    Status:                False
    Type:                  Ready
    Last Heartbeat Time:   2020-12-22T09:37:27Z
    Last Transition Time:  2020-12-22T09:37:27Z
    Reason:                Pod is running
    Status:                True
    Type:                  Running
  Phase:                   ImportInProgress
  Progress:                13.15%
Events:
  Type    Reason            Age    From                   Message
  ----    ------            ----   ----                   -------
  Normal  Pending           3m44s  datavolume-controller  PVC v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c Pending
  Normal  ImportScheduled   3m33s  datavolume-controller  Import into v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c scheduled
  Normal  Bound             3m33s  datavolume-controller  PVC v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c Bound
  Normal  ImportInProgress  3m10s  datavolume-controller  Import into v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c in progress


First Log of the cdi importer till it reached the point of out of space:
$ oc logs importer-v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c -n openshift-cnv -f
I1222 09:37:27.424895       1 importer.go:52] Starting importer
I1222 09:37:27.431641       1 importer.go:116] begin import process
I1222 09:37:29.032316       1 http-datasource.go:219] Attempting to get certs from /certs/ca.pem
I1222 09:37:29.526977       1 data-processor.go:302] Calculating available size
I1222 09:37:29.529169       1 data-processor.go:310] Checking out block volume size.
I1222 09:37:29.529188       1 data-processor.go:322] Request image size not empty.
I1222 09:37:29.529211       1 data-processor.go:327] Target size 100Gi.
I1222 09:37:29.529376       1 data-processor.go:224] New phase: TransferDataFile
I1222 09:37:29.530520       1 util.go:161] Writing data...
I1222 09:37:30.529705       1 prometheus.go:69] 0.10
I1222 09:37:31.530301       1 prometheus.go:69] 0.21
I1222 09:37:32.530547       1 prometheus.go:69] 0.32
...
I1222 10:00:42.169484       1 prometheus.go:69] 57.37
I1222 10:00:43.169648       1 prometheus.go:69] 57.37
I1222 10:00:44.169825       1 prometheus.go:69] 57.37
I1222 10:00:45.170001       1 prometheus.go:69] 57.37
I1222 10:00:46.170198       1 prometheus.go:69] 57.37
E1222 10:00:46.544570       1 util.go:163] Unable to write file from dataReader: unexpected EOF
E1222 10:00:46.544761       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
E1222 10:00:46.548995       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


$ oc describe dv v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c -n openshift-cnv     
Name:         v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c
Namespace:    openshift-cnv
Labels:       <none>
Annotations:  <none>
API Version:  cdi.kubevirt.io/v1beta1
Kind:         DataVolume
Metadata:
  Creation Timestamp:  2020-12-22T09:36:52Z
  Generation:          1097
  Managed Fields:
    API Version:  cdi.kubevirt.io/v1alpha1
    Fields Type:  FieldsV1
    fieldsV1:
      f:metadata:
        f:ownerReferences:
      f:spec:
        .:
        f:pvc:
          .:
          f:accessModes:
          f:resources:
            .:
            f:requests:
              .:
              f:storage:
          f:storageClassName:
          f:volumeMode:
        f:source:
          .:
          f:imageio:
            .:
            f:certConfigMap:
            f:diskId:
            f:secretRef:
            f:url:
      f:status:
    Manager:      vm-import-controller
    Operation:    Update
    Time:         2020-12-22T09:36:52Z
    API Version:  cdi.kubevirt.io/v1beta1
    Fields Type:  FieldsV1
    fieldsV1:
      f:status:
        f:conditions:
        f:phase:
        f:progress:
        f:restartCount:
    Manager:    virt-cdi-controller
    Operation:  Update
    Time:       2020-12-22T10:13:25Z
  Owner References:
    API Version:           v2v.kubevirt.io/v1beta1
    Block Owner Deletion:  true
    Controller:            true
    Kind:                  VirtualMachineImport
    Name:                  vm-import-v2vmigrationvm0-gls9l
    UID:                   cb963e5b-d297-4147-85d8-36a21658baa5
    API Version:           kubevirt.io/v1alpha3
    Block Owner Deletion:  true
    Controller:            false
    Kind:                  VirtualMachine
    Name:                  v2vmigrationvm0
    UID:                   0b25fcba-73d1-4f86-8f25-a91942f8716a
  Resource Version:        4482693
  Self Link:               /apis/cdi.kubevirt.io/v1beta1/namespaces/openshift-cnv/datavolumes/v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c
  UID:                     d8f8ac1b-5fa0-496c-9323-7998d4c31c17
Spec:
  Pvc:
    Access Modes:
      ReadWriteMany
    Resources:
      Requests:
        Storage:         100Gi
    Storage Class Name:  ocs-storagecluster-ceph-rbd
    Volume Mode:         Block
  Source:
    Imageio:
      Cert Config Map:  vmimport.v2v.kubevirt.ioz8smj
      Disk Id:          03072434-e45b-430c-8860-ff50b0c71a2c
      Secret Ref:       vmimport.v2v.kubevirt.iolkqlw
      URL:              https://rhev-blue-01.rdu2.scalelab.redhat.com/ovirt-engine/api
Status:
  Conditions:
    Last Heartbeat Time:   2020-12-22T09:37:04Z
    Last Transition Time:  2020-12-22T09:37:04Z
    Message:               PVC v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c Bound
    Reason:                Bound
    Status:                True
    Type:                  Bound
    Last Heartbeat Time:   2020-12-22T10:13:25Z
    Last Transition Time:  2020-12-22T09:36:53Z
    Reason:                TransferRunning
    Status:                False
    Type:                  Ready
    Last Heartbeat Time:   2020-12-22T10:09:37Z
    Last Transition Time:  2020-12-22T10:09:37Z
    Reason:                Pod is running
    Status:                True
    Type:                  Running
  Phase:                   ImportInProgress
  Progress:                0.01%
  Restart Count:           3
Events:
  Type     Reason            Age                  From                   Message
  ----     ------            ----                 ----                   -------
  Normal   Pending           36m                  datavolume-controller  PVC v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c Pending
  Normal   ImportScheduled   36m                  datavolume-controller  Import into v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c scheduled
  Normal   Bound             36m                  datavolume-controller  PVC v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c Bound
  Normal   ImportInProgress  35m                  datavolume-controller  Import into v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c in progress
  Warning  CrashLoopBackOff  7m24s                datavolume-controller  back-off 10s restarting failed container=importer pod=importer-v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c_openshift-cnv(8bd74447-d6ab-46b1-aacd-1eeec448840d)
  Warning  Error             4m13s (x3 over 12m)  datavolume-controller  Unable to process data: unexpected EOF
  Warning  CrashLoopBackOff  4m1s                 datavolume-controller  back-off 20s restarting failed container=importer pod=importer-v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c_openshift-cnv(8bd74447-d6ab-46b1-aacd-1eeec448840d)



Then the same importer pod seem to start again and show constantly 0% progress, and this "restart" repeats itself. In CNV UI VM import it remained at 47%, till eventually it failed with error:

Import error (RHV)
v2vmigrationvm0 could not be imported.
DataVolumeCreationFailed: Error while importing disk image: v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c. pod CrashLoopBackoff restart exceeded

The later cdi importer pod logs had this content:
$ oc logs importer-v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c -n openshift-cnv -f
I1222 10:00:48.026224       1 importer.go:52] Starting importer
I1222 10:00:48.030022       1 importer.go:116] begin import process
I1222 10:00:49.000772       1 http-datasource.go:219] Attempting to get certs from /certs/ca.pem
I1222 10:00:49.046945       1 data-processor.go:302] Calculating available size
I1222 10:00:49.048284       1 data-processor.go:310] Checking out block volume size.
I1222 10:00:49.048300       1 data-processor.go:322] Request image size not empty.
I1222 10:00:49.048327       1 data-processor.go:327] Target size 100Gi.
I1222 10:00:49.048470       1 data-processor.go:224] New phase: TransferDataFile
I1222 10:00:49.050167       1 util.go:161] Writing data...
I1222 10:00:50.048728       1 prometheus.go:69] 0.00
I1222 10:00:51.049358       1 prometheus.go:69] 0.00
I1222 10:00:52.049703       1 prometheus.go:69] 0.00
I1222 10:00:53.049845       1 prometheus.go:69] 0.00
...
I1222 10:09:11.233254       1 prometheus.go:69] 0.01
I1222 10:09:12.233434       1 prometheus.go:69] 0.01
E1222 10:09:12.474672       1 util.go:163] Unable to write file from dataReader: unexpected EOF
E1222 10:09:12.474820       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
E1222 10:09:12.474994       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

The events related to this VM import:
$ oc get events -n openshift-cnv
33m         Normal    ImportScheduled          virtualmachineimport/vm-import-v2vmigrationvm0-gls9l                         Import of Virtual Machine openshift-cnv/v2vmigrationvm0 started
33m         Normal    ImportInProgress         virtualmachineimport/vm-import-v2vmigrationvm0-gls9l                         Import of Virtual Machine openshift-cnv/v2vmigrationvm0 disk v2vmigrationvm0-03072434-e45b-430c-8860-ff50b0c71a2c in progress
4m21s       Warning   EventPVCImportFailed     virtualmachineimport/vm-import-v2vmigrationvm0-gls9l                         Unable to process data: unexpected EOF

Comment 6 Maya Rashish 2020-12-22 11:41:03 UTC

So there's two ways I can interpret the discussion here:
"there's no event being reported that the UI can utilize"
but there is one (note: reported by vm-import-operator, not CDI):
4m21s       Warning   EventPVCImportFailed     virtualmachineimport/vm-import-v2vmigrationvm0-gls9l                         Unable to process data: unexpected EOF

(Should we improve on this?)


Another way to interpret it is:
"The behaviour where CDI restarts the import even though it failed seems strange/wrong"
I agree it's somewhat weird, but it's a behaviour that is typical for kubernetes ("eventual consistency"), and we strive to behave in a "kubernetes native way" as much as possible.
And heck, some disk write errors might not happen a second time (bad connectivity to network storage?).

After enough times (failure threshold) of restarting the pod that is CrashLoopBackoff-ing, it will go into Failed state, and CDI should set the datavolume to failed as well.

Comment 7 Adam Litke 2021-01-04 19:45:12 UTC

I think we could provide a more useful error message by catching this write error and checking the free space on the filesystem.  If we determine there is no (or almost none) space available we could suggest that the PVC is out of space.

I think we should audit the CDI code and utilize this check in any place where we might run out of space.

I am not sure how we could handle it for block devices but we should check if that is possible too.

Comment 8 Ying Cui 2021-03-03 13:25:55 UTC

Maya, could you please update on the bug progress? It is targeted to 2.6.1.

Comment 9 Maya Rashish 2021-03-15 05:56:07 UTC

Haven't made progress.

Comment 10 Maya Rashish 2021-03-24 17:59:10 UTC

describe dv now says (in 4.8.0, and 2.6.z will soon do the same):
  Warning  Error             61s (x5 over 3m54s)  datavolume-controller  Unable to process data: Virtual image size 2147483648 is larger than available size 209715200 (PVC size 2147483648, reserved overhead 0.000000%). A larger PVC is required.

Which is considerably more obvious.

Are we looking for more clarity than this?

Comment 11 Maya Rashish 2021-03-25 07:21:38 UTC

Actually, there are a couple of things it could say (it could fail at multiple points), let me verify the message for this particular scenario.

Comment 12 Adam Litke 2021-04-14 12:36:05 UTC

The fix is already in 4.8 and this isn't high priority enough to warrant a backport so I'm moving this to 4.8.

Comment 13 Adam Litke 2021-04-14 12:37:44 UTC

Maya, can you link the PR that provided this change and then move the bug to MODIFIED?

Comment 14 Maya Rashish 2021-04-26 07:36:19 UTC

there isn't a commit I'd like to mark as fixing this PR

Comment 15 Adam Litke 2021-04-28 20:37:51 UTC

Maya, then what is left to do here?

Comment 16 Maya Rashish 2021-05-03 07:11:20 UTC

it wasn't entirely clear what v2v is doing with this information and how easy to check it needs to be.
a single event that can be programmatically and easily checked? that doesn't exist yet.
any event that makes it obvious there's a problem? the warning referenced might be enough.

Comment 17 Adam Litke 2021-05-03 16:45:50 UTC

Maya, I believe we discussed that if the Pod exits with a more detailed/specific error message that would be sufficient.  In this case, the termination message will be propagated to the DV conditions and can be read progmatically.

Comment 18 Kevin Alon Goldblatt 2021-05-19 08:37:32 UTC

Hey @mrashish is this fix still targeted for 4.8?

Comment 19 Maya Rashish 2021-05-31 10:26:20 UTC

nbdkit changes make it unusually difficult to tell from the pod termination status that it failed due to space issues, I don't think it is appropriate to make these changes in 4.8 though

Comment 20 Maya Rashish 2021-07-14 16:05:07 UTC

The change to add a condition to the DV for this too-small scenario is now downstream.
(If this is not the desired result of the bug, feel free to change it).

Comment 24 Maya Rashish 2021-07-25 08:56:22 UTC

On a closer look I think that this bug is an instance of bz#1897351:
the import did not progress after the first failed import (ceph probably went into read-only mode)
There's not much we can do about that in CDI.

It might make sense to close this bug as a duplicate of this bug.

*** This bug has been marked as a duplicate of bug 1893528 ***

Note You need to log in before you can comment on or make changes to this bug.