Bug 1823342 - Invalid qcow2 image causes HTTP range error and difficult to read stack trace
Summary: Invalid qcow2 image causes HTTP range error and difficult to read stack trace
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Container Native Virtualization (CNV)
Classification: Red Hat
Component: Storage
Version: 2.4.0
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: 2.4.0
Assignee: Alexander Wels
QA Contact: Natalie Gavrielov
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-04-13 12:04 UTC by Natalie Gavrielov
Modified: 2020-07-28 19:09 UTC (History)
5 users (show)

Fixed In Version: hco-bundle-registry-container-v2.3.0-388 virt-cdi-importer-container-v2.4.0-24
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-07-28 19:09:47 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github kubevirt containerized-data-importer pull 1246 0 None closed [release-v1.18] Report better qemu failure messages. 2020-09-15 11:42:32 UTC
Red Hat Product Errata RHSA-2020:3194 0 None None None 2020-07-28 19:09:58 UTC

Description Natalie Gavrielov 2020-04-13 12:04:22 UTC 
Description of problem:
One of our tier2 automation tests imports a large json file. 
This causes an error message: 'Unable to process data: signal: segmentation fault (core dumped)' under containerStatuses.

Version-Release number of selected component:
2.3

How reproducible:
100%

Steps to Reproduce:
Try to import a json file.

Actual results:
Under containerStatuses it shows:
message: 'Unable to process data: signal: segmentation fault (core dumped)' 

Expected results:
Some other message explaining the file format is not supported.
No segmentation fault/core dump 

Additional info:

$ oc get dv -n cdi-import-test-import-htt -o yaml
apiVersion: v1
items:
- apiVersion: cdi.kubevirt.io/v1alpha1
  kind: DataVolume
  metadata:
    creationTimestamp: "2020-04-13T11:42:21Z"
    generation: 5
    name: large-json
    namespace: cdi-import-test-import-htt
    resourceVersion: "4991960"
    selfLink: /apis/cdi.kubevirt.io/v1alpha1/namespaces/cdi-import-test-import-htt/datavolumes/large-json
    uid: 4265fddc-5ace-4d56-86e0-a6d95f282aa1
  spec:
    contentType: kubevirt
    pvc:
      accessModes:
      - ReadWriteOnce
      resources:
        requests:
          storage: 5Gi
      storageClassName: hostpath-provisioner
      volumeMode: Filesystem
    source:
      http:
        url: http://internal-http.kube-system/invalid-qcow-large-json.img
  status:
    phase: ImportInProgress
kind: List
metadata:
  resourceVersion: ""
  selfLink: ""



$ oc get pod importer-large-json -n cdi-import-test-import-htt -o yaml
apiVersion: v1
kind: Pod
metadata:
  annotations:
    cdi.kubevirt.io/storage.createdByController: "yes"
    k8s.v1.cni.cncf.io/networks-status: |-
      [{
          "name": "openshift-sdn",
          "interface": "eth0",
          "ips": [
              "10.129.3.58"
          ],
          "dns": {},
          "default-route": [
              "10.129.2.1"
          ]
      }]
    openshift.io/scc: anyuid
  creationTimestamp: "2020-04-13T11:42:21Z"
  labels:
    app: containerized-data-importer
    cdi.kubevirt.io: importer
    cdi.kubevirt.io/storage.import.importPvcName: large-json
    prometheus.cdi.kubevirt.io: ""
  name: importer-large-json
  namespace: cdi-import-test-import-htt
  ownerReferences:
  - apiVersion: v1
    blockOwnerDeletion: true
    controller: true
    kind: PersistentVolumeClaim
    name: large-json
    uid: 53b86ba8-8f3c-469c-8502-52eaa53c0d36
  resourceVersion: "4992915"
  selfLink: /api/v1/namespaces/cdi-import-test-import-htt/pods/importer-large-json
  uid: d42593b7-5797-4a49-a12a-8e859168117a
spec:
  containers:
  - args:
    - -v=1
    env:
    - name: IMPORTER_SOURCE
      value: http
    - name: IMPORTER_ENDPOINT
      value: http://internal-http.kube-system/invalid-qcow-large-json.img
    - name: IMPORTER_CONTENTTYPE
      value: kubevirt
    - name: IMPORTER_IMAGE_SIZE
      value: 5Gi
    - name: OWNER_UID
      value: 4265fddc-5ace-4d56-86e0-a6d95f282aa1
    - name: INSECURE_TLS
      value: "false"
    image: registry-proxy.engineering.redhat.com/rh-osbs/container-native-virtualization-virt-cdi-importer@sha256:dec1d1299427341c3a0e9cba17c1316806718f3a3cdc9d1e2ba0949657ece59d
    imagePullPolicy: IfNotPresent
    name: importer
    ports:
    - containerPort: 8443
      name: metrics
      protocol: TCP
    resources:
      limits:
        cpu: "0"
        memory: "0"
      requests:
        cpu: "0"
        memory: "0"
    securityContext:
      capabilities:
        drop:
        - MKNOD
    terminationMessagePath: /dev/termination-log
    terminationMessagePolicy: File
    volumeMounts:
    - mountPath: /data
      name: cdi-data-vol
    - mountPath: /var/run/secrets/kubernetes.io/serviceaccount
      name: default-token-6l8bx
      readOnly: true
  dnsPolicy: ClusterFirst
  enableServiceLinks: true
  imagePullSecrets:
  - name: default-dockercfg-zdvzg
  nodeName: natalie-ipi-jszq8-worker-bfz7z
  priority: 0
  restartPolicy: OnFailure
  schedulerName: default-scheduler
  securityContext:
    seLinuxOptions:
      level: s0:c39,c9
  serviceAccount: default
  serviceAccountName: default
  terminationGracePeriodSeconds: 30
  tolerations:
  - effect: NoExecute
    key: node.kubernetes.io/not-ready
    operator: Exists
    tolerationSeconds: 300
  - effect: NoExecute
    key: node.kubernetes.io/unreachable
    operator: Exists
    tolerationSeconds: 300
  volumes:
  - name: cdi-data-vol
    persistentVolumeClaim:
      claimName: large-json
  - name: default-token-6l8bx
    secret:
      defaultMode: 420
      secretName: default-token-6l8bx
status:
  conditions:
  - lastProbeTime: null
    lastTransitionTime: "2020-04-13T11:42:22Z"
    status: "True"
    type: Initialized
  - lastProbeTime: null
    lastTransitionTime: "2020-04-13T11:43:55Z"
    message: 'containers with unready status: [importer]'
    reason: ContainersNotReady
    status: "False"
    type: Ready
  - lastProbeTime: null
    lastTransitionTime: "2020-04-13T11:43:55Z"
    message: 'containers with unready status: [importer]'
    reason: ContainersNotReady
    status: "False"
    type: ContainersReady
  - lastProbeTime: null
    lastTransitionTime: "2020-04-13T11:42:22Z"
    status: "True"
    type: PodScheduled
  containerStatuses:
  - containerID: cri-o://371e2e257973f28754d806024a1be03ec7a73614b070f0a35e06673f81a72386
    image: registry-proxy.engineering.redhat.com/rh-osbs/container-native-virtualization-virt-cdi-importer@sha256:dec1d1299427341c3a0e9cba17c1316806718f3a3cdc9d1e2ba0949657ece59d
    imageID: registry-proxy.engineering.redhat.com/rh-osbs/container-native-virtualization-virt-cdi-importer@sha256:1a1614ffaef617faf2911b8524d23882b075bb72ec0c209cc29d03bfa77fad38
    lastState:
      terminated:
        containerID: cri-o://371e2e257973f28754d806024a1be03ec7a73614b070f0a35e06673f81a72386
        exitCode: 1
        finishedAt: "2020-04-13T11:43:54Z"
        message: 'Unable to process data: signal: segmentation fault (core dumped)'
        reason: Error
        startedAt: "2020-04-13T11:43:53Z"
    name: importer
    ready: false
    restartCount: 4
    started: false
    state:
      waiting:
        message: back-off 1m20s restarting failed container=importer pod=importer-large-json_cdi-import-test-import-htt(d42593b7-5797-4a49-a12a-8e859168117a)
        reason: CrashLoopBackOff
  hostIP: 192.168.0.41
  phase: Running
  podIP: 10.129.3.58
  podIPs:
  - ip: 10.129.3.58
  qosClass: BestEffort
  startTime: "2020-04-13T11:42:22Z"


$ oc get dv -n cdi-import-test-import-htt
NAME         PHASE              PROGRESS   AGE
large-json   ImportInProgress              18s

$ oc get pods -n cdi-import-test-import-htt
NAME                  READY   STATUS   RESTARTS   AGE
importer-large-json   0/1     Error    2          28s

$ oc logs -f importer-large-json -n cdi-import-test-import-htt
I0413 11:42:42.922914       1 importer.go:51] Starting importer
I0413 11:42:42.923039       1 importer.go:107] begin import process
I0413 11:42:42.931239       1 data-processor.go:275] Calculating available size
I0413 11:42:42.932423       1 data-processor.go:283] Checking out file system volume size.
I0413 11:42:42.932464       1 data-processor.go:287] Request image size not empty.
I0413 11:42:42.932493       1 data-processor.go:292] Target size 5Gi.
I0413 11:42:42.932709       1 data-processor.go:205] New phase: Convert
I0413 11:42:42.932728       1 data-processor.go:211] Validating image
E0413 11:42:43.004211       1 prlimit.go:164] qemu-img failed output is:
E0413 11:42:43.004234       1 prlimit.go:165] qemu-img: curl: The requested URL returned error: 416 Requested Range Not Satisfiable
qemu-img: Could not open 'json: {"file.driver": "http", "file.url": "http://internal-http.kube-system/invalid-qcow-large-json.img", "file.timeout": 3600}': Could not read snapshots: Input/output error

E0413 11:42:43.004271       1 data-processor.go:202] exit status 1
qemu-img execution failed
kubevirt.io/containerized-data-importer/pkg/system.ExecWithLimits
	/go/src/kubevirt.io/containerized-data-importer/pkg/system/prlimit.go:166
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Info
	/go/src/kubevirt.io/containerized-data-importer/pkg/image/qemu.go:153
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/image/qemu.go:179
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:212
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).convert
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:221
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:189
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:141
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:142
runtime.main
	/usr/lib/golang/src/runtime/proc.go:200
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1337
Error getting info on image http://internal-http.kube-system/invalid-qcow-large-json.img
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Info
	/go/src/kubevirt.io/containerized-data-importer/pkg/image/qemu.go:158
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/image/qemu.go:179
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:212
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).convert
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:221
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:189
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:141
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:142
runtime.main
	/usr/lib/golang/src/runtime/proc.go:200
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1337
Image validation failed
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:214
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).convert
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:221
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:189
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:141
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:142
runtime.main
	/usr/lib/golang/src/runtime/proc.go:200
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1337
Unable to convert source data to target format
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:141
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:142
runtime.main
	/usr/lib/golang/src/runtime/proc.go:200
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1337
E0413 11:42:43.004405       1 importer.go:144] exit status 1
qemu-img execution failed
kubevirt.io/containerized-data-importer/pkg/system.ExecWithLimits
	/go/src/kubevirt.io/containerized-data-importer/pkg/system/prlimit.go:166
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Info
	/go/src/kubevirt.io/containerized-data-importer/pkg/image/qemu.go:153
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/image/qemu.go:179
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:212
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).convert
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:221
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:189
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:141
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:142
runtime.main
	/usr/lib/golang/src/runtime/proc.go:200
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1337
Error getting info on image http://internal-http.kube-system/invalid-qcow-large-json.img
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Info
	/go/src/kubevirt.io/containerized-data-importer/pkg/image/qemu.go:158
kubevirt.io/containerized-data-importer/pkg/image.(*qemuOperations).Validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/image/qemu.go:179
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:212
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).convert
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:221
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:189
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:141
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:142
runtime.main
	/usr/lib/golang/src/runtime/proc.go:200
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1337
Image validation failed
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).validate
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:214
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).convert
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:221
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessDataWithPause
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:189
kubevirt.io/containerized-data-importer/pkg/importer.(*DataProcessor).ProcessData
	/go/src/kubevirt.io/containerized-data-importer/pkg/importer/data-processor.go:141
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:142
runtime.main
	/usr/lib/golang/src/runtime/proc.go:200
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1337
Unable to convert source data to target format
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:141
main.main
	/go/src/kubevirt.io/containerized-data-importer/cmd/cdi-importer/importer.go:142
runtime.main
	/usr/lib/golang/src/runtime/proc.go:200
runtime.goexit
	/usr/lib/golang/src/runtime/asm_amd64.s:1337

$ oc get pods -n cdi-import-test-import-htt
NAME                  READY   STATUS             RESTARTS   AGE
importer-large-json   0/1     CrashLoopBackOff   4          2m13s
Comment 1 Alexander Wels 2020-04-21 12:53:47 UTC 
So this is actually expected behavior, here is what happens. The size of the virtual disk in the bad image is huge, qemu tries to do a range operation on the http endpoint. Because the value is so large, this will generate the 'The requested URL returned error: 416 Requested Range Not Satisfiable' error message. This will cause the unable to process data message that you are seeing. I originally thought this was a prlimit issue, but the http endpoint is returning the 416 which generates the error. I am not sure why its saying a core dump, because the import process exists with an exit(1) as shown in the stack trace.
Comment 2 Adam Litke 2020-05-14 20:59:37 UTC 
Alexander, I think we should show stack traces only when there is a core dump in golang code.  When there is a handled error we should exit with an informative message and not print the stack trace.  All of that verbosity merely obfuscates the helpful information we are providing.
Comment 3 Adam Litke 2020-06-03 20:58:16 UTC 
Alexander, would you agree?  Can this be handled for most cases with a change to how we catch and print errors generally?
Comment 4 Adam Litke 2020-06-10 13:41:31 UTC 
We don't want to suppress information that can help us diagnose and fix the bug.  Now that we have conditions on DataVolumes, we should surface a better message there but leave the logs as-is.
Comment 5 Ying Cui 2020-06-17 12:25:47 UTC 
Could you confirm that the condition on DataVolumes surfaces the error.
Comment 6 Alexander Wels 2020-06-17 12:38:55 UTC 
I cannot confirm this, I don't think so.
Comment 7 Alexander Wels 2020-06-19 12:13:41 UTC 
Created PR to better report errors.
Comment 8 Natalie Gavrielov 2020-07-02 13:36:51 UTC 
Verified CNV 2.4, getting the following message now:
 'message': 'Unable to process data: qemu-img: curl: The requested URL '
            'returned error: 416 Requested Range Not Satisfiable',
Comment 11 errata-xmlrpc 2020-07-28 19:09:47 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, 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-2020:3194
Note You need to log in before you can comment on or make changes to this bug.