Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

500 error during DV import on GCP env #2836

Closed
ksimon1 opened this issue Aug 8, 2023 · 5 comments
Closed

500 error during DV import on GCP env #2836

ksimon1 opened this issue Aug 8, 2023 · 5 comments
Labels
kind/bug

Comments

@ksimon1
Copy link
Member

ksimon1 commented Aug 8, 2023 •
edited
Loading

What happened:
500 error during DV import on GCP env
The e2e tests created DV with fedora image, then the test created VM from common-template which creates new datavolume, which clones original DV with fedora image. During the import of the VM disk, importer pod throws 500 error.

What you expected to happen:
DV is imported and VM runs

How to reproduce it (as minimally and precisely as possible):
run fedora e2e test in common templates (I can help with setting up env)

Environment:

  • CDI version (use kubectl get deployments cdi-deployment -o yaml): v1.56.1
  • Kubernetes version (use kubectl version):
[ksimon:10:43:52~/go/src/kubevirt.io/ssp-operator]$ oc version
Client Version: 4.13.4
Kustomize Version: v4.5.7
Server Version: 4.14.0-0.nightly-2023-08-08-005757
Kubernetes Version: v1.27.3+e123787

VM definition:

[ksimon:10:41:49~/go/src/kubevirt.io/ssp-operator]$ oc get vm -o yaml
apiVersion: v1
items:
- apiVersion: kubevirt.io/v1
  kind: VirtualMachine
  metadata:
    annotations:
      kubectl.kubernetes.io/last-applied-configuration: |
        {"apiVersion":"kubevirt.io/v1","kind":"VirtualMachine","metadata":{"annotations":{"vm.kubevirt.io/validations":"[\n  {\n    \"name\": \"minimal-required-memory\",\n    \"path\": \"jsonpath::.spec.domain.resources.requests.memory\",\n    \"rule\": \"integer\",\n    \"message\": \"This VM requires more memory.\",\n    \"min\": 1073741824\n  }\n]\n"},"labels":{"app":"fedora-desktop-tiny","vm.kubevirt.io/template":"fedora-desktop-tiny","vm.kubevirt.io/template.namespace":"kubevirt","vm.kubevirt.io/template.revision":"53","vm.kubevirt.io/template.version":"v0.25.0"},"name":"fedora-desktop-tiny","namespace":"kubevirt"},"spec":{"dataVolumeTemplates":[{"apiVersion":"cdi.kubevirt.io/v1beta1","kind":"DataVolume","metadata":{"name":"fedora-desktop-tiny"},"spec":{"sourceRef":{"kind":"DataSource","name":"fedora-datavolume-original","namespace":"kubevirt"},"storage":{"resources":{"requests":{"storage":"30Gi"}}}}}],"running":false,"template":{"metadata":{"annotations":{"vm.kubevirt.io/flavor":"tiny","vm.kubevirt.io/os":"fedora","vm.kubevirt.io/workload":"desktop"},"labels":{"kubevirt.io/domain":"fedora-desktop-tiny","kubevirt.io/size":"tiny"}},"spec":{"domain":{"cpu":{"cores":1,"sockets":1,"threads":1},"devices":{"disks":[{"disk":{"bus":"virtio"},"name":"rootdisk"},{"disk":{"bus":"virtio"},"name":"cloudinitdisk"}],"inputs":[{"bus":"virtio","name":"tablet","type":"tablet"}],"interfaces":[{"masquerade":{},"model":"virtio","name":"default"}],"networkInterfaceMultiqueue":true,"rng":{}},"features":{"smm":{"enabled":true}},"firmware":{"bootloader":{"efi":{}}},"resources":{"requests":{"memory":"1Gi"}}},"networks":[{"name":"default","pod":{}}],"terminationGracePeriodSeconds":0,"volumes":[{"dataVolume":{"name":"fedora-desktop-tiny"},"name":"rootdisk"},{"cloudInitNoCloud":{"userData":"#cloud-config\nuser: fedora\npassword: c311-wfo2-rwyd\nchpasswd: { expire: False }"},"name":"cloudinitdisk"}]}}}}
      kubevirt.io/latest-observed-api-version: v1
      kubevirt.io/storage-observed-api-version: v1alpha3
      vm.kubevirt.io/validations: |
        [
          {
            "name": "minimal-required-memory",
            "path": "jsonpath::.spec.domain.resources.requests.memory",
            "rule": "integer",
            "message": "This VM requires more memory.",
            "min": 1073741824
          }
        ]
    creationTimestamp: "2023-08-08T08:07:41Z"
    finalizers:
    - kubevirt.io/virtualMachineControllerFinalize
    generation: 2
    labels:
      app: fedora-desktop-tiny
      vm.kubevirt.io/template: fedora-desktop-tiny
      vm.kubevirt.io/template.namespace: kubevirt
      vm.kubevirt.io/template.revision: "53"
      vm.kubevirt.io/template.version: v0.25.0
    name: fedora-desktop-tiny
    namespace: kubevirt
    resourceVersion: "196533"
    uid: 80ee55d7-d868-459f-8914-2c079923c92d
  spec:
    dataVolumeTemplates:
    - apiVersion: cdi.kubevirt.io/v1beta1
      kind: DataVolume
      metadata:
        creationTimestamp: null
        name: fedora-desktop-tiny
      spec:
        sourceRef:
          kind: DataSource
          name: fedora-datavolume-original
          namespace: kubevirt
        storage:
          resources:
            requests:
              storage: 30Gi
    running: true
    template:
      metadata:
        annotations:
          vm.kubevirt.io/flavor: tiny
          vm.kubevirt.io/os: fedora
          vm.kubevirt.io/workload: desktop
        creationTimestamp: null
        labels:
          kubevirt.io/domain: fedora-desktop-tiny
          kubevirt.io/size: tiny
      spec:
        domain:
          cpu:
            cores: 1
            sockets: 1
            threads: 1
          devices:
            disks:
            - disk:
                bus: virtio
              name: rootdisk
            - disk:
                bus: virtio
              name: cloudinitdisk
            inputs:
            - bus: virtio
              name: tablet
              type: tablet
            interfaces:
            - masquerade: {}
              model: virtio
              name: default
            networkInterfaceMultiqueue: true
            rng: {}
          features:
            acpi: {}
            smm:
              enabled: true
          firmware:
            bootloader:
              efi: {}
          machine:
            type: q35
          resources:
            requests:
              memory: 1Gi
        networks:
        - name: default
          pod: {}
        terminationGracePeriodSeconds: 0
        volumes:
        - dataVolume:
            name: fedora-desktop-tiny
          name: rootdisk
        - cloudInitNoCloud:
            userData: |-
              #cloud-config
              user: fedora
              password: c311-wfo2-rwyd
              chpasswd: { expire: False }
          name: cloudinitdisk
  status:
    conditions:
    - lastProbeTime: "2023-08-08T08:07:42Z"
      lastTransitionTime: "2023-08-08T08:07:42Z"
      message: virt-launcher pod has not yet been scheduled
      reason: PodNotExists
      status: "False"
      type: Ready
    - lastProbeTime: null
      lastTransitionTime: null
      status: "True"
      type: Provisioning
    created: true
    printableStatus: Provisioning
    volumeSnapshotStatuses:
    - enabled: true
      name: rootdisk
    - enabled: false
      name: cloudinitdisk
      reason: Snapshot is not supported for this volumeSource type [cloudinitdisk]
kind: List
metadata:
  resourceVersion: ""

StorageClass

[ksimon:10:43:41~/go/src/kubevirt.io/ssp-operator]$ oc get storageclass -o yaml standard-csi
allowVolumeExpansion: true
apiVersion: storage.k8s.io/v1
kind: StorageClass
metadata:
  annotations:
    storageclass.kubernetes.io/is-default-class: "true"
  creationTimestamp: "2023-08-08T05:46:49Z"
  name: standard-csi
  resourceVersion: "5823"
  uid: aba3e263-e55c-4b0b-991d-6c038876a88e
parameters:
  replication-type: none
  type: pd-standard
provisioner: pd.csi.storage.gke.io
reclaimPolicy: Delete
volumeBindingMode: WaitForFirstConsumer
@ksimon1
Copy link
Member Author

ksimon1 commented Aug 8, 2023

Logs from importer pod:

[ksimon:10:40:08~/go/src/kubevirt.io/ssp-operator]$ oc logs -f f9fd8027-8671-4ce7-a7d9-1a758307ac30-source-pod
VOLUME_MODE=filesystem
MOUNT_POINT=/var/run/cdi/clone/source
/var/run/cdi/clone/source /
UPLOAD_BYTES=29776416768
I0808 08:39:29.938774      10 clone-source.go:220] content-type is "filesystem-clone"
I0808 08:39:29.938821      10 clone-source.go:221] mount is "/var/run/cdi/clone/source"
I0808 08:39:29.938824      10 clone-source.go:222] upload-bytes is 29776416768
I0808 08:39:29.938832      10 clone-source.go:239] Starting cloner target
I0808 08:39:29.938878      10 clone-source.go:177] Executing [/usr/bin/tar cv -S disk.img]
I0808 08:39:30.663865      10 clone-source.go:251] Set header to filesystem-clone
F0808 08:39:30.681207      10 clone-source.go:260] Unexpected status code 500
goroutine 1 [running]:
kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.stacks(0x1)
	vendor/k8s.io/klog/v2/klog.go:1038 +0x8a
kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.(*loggingT).output(0x14c47e0, 0x3, 0x0, 0xc0002ac460, 0x0, {0x10aeba0?, 0x1?}, 0xc000584330?, 0x0)
	vendor/k8s.io/klog/v2/klog.go:987 +0x5fd
kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.(*loggingT).printf(0x12?, 0x4605b?, 0x0, {0x0, 0x0}, {0xd3ecd6, 0x19}, {0xc000584330, 0x1, 0x1})
	vendor/k8s.io/klog/v2/klog.go:753 +0x1c5
kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.Fatalf(...)
	vendor/k8s.io/klog/v2/klog.go:1532
main.main()
	cmd/cdi-cloner/clone-source.go:260 +0xbfa

goroutine 7 [chan receive]:
kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.(*loggingT).flushDaemon(0xc000142480?)
	vendor/k8s.io/klog/v2/klog.go:1181 +0x6a
created by kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.init.0
	vendor/k8s.io/klog/v2/klog.go:420 +0xf6

goroutine 8 [IO wait]:
internal/poll.runtime_pollWait(0x7f68c4c5adb8, 0x72)
	GOROOT/src/runtime/netpoll.go:302 +0x89
internal/poll.(*pollDesc).wait(0xc00007ea80?, 0xc000400009?, 0x1)
	GOROOT/src/internal/poll/fd_poll_runtime.go:83 +0x32
internal/poll.(*pollDesc).waitRead(...)
	GOROOT/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Read(0xc00007ea80, {0xc000400009, 0x5f7, 0x5f7})
	GOROOT/src/internal/poll/fd_unix.go:167 +0x25a
os.(*File).read(...)
	GOROOT/src/os/file_posix.go:31
os.(*File).Read(0xc000010640, {0xc000400009?, 0x7f68c4c16fe8?, 0xc00005eea0?})
	GOROOT/src/os/file.go:119 +0x5e
bytes.(*Buffer).ReadFrom(0xc000300270, {0xe8f020, 0xc000010640})
	GOROOT/src/bytes/buffer.go:204 +0x98
io.copyBuffer({0xe8da00, 0xc000300270}, {0xe8f020, 0xc000010640}, {0x0, 0x0, 0x0})
	GOROOT/src/io/io.go:412 +0x14b
io.Copy(...)
	GOROOT/src/io/io.go:385
os/exec.(*Cmd).writerDescriptor.func1()
	GOROOT/src/os/exec/exec.go:311 +0x3a
os/exec.(*Cmd).Start.func1(0x0?)
	GOROOT/src/os/exec/exec.go:448 +0x25
created by os/exec.(*Cmd).Start
	GOROOT/src/os/exec/exec.go:447 +0x776

goroutine 10 [sleep]:
time.Sleep(0x3b9aca00)
	GOROOT/src/runtime/time.go:194 +0x12e
kubevirt.io/containerized-data-importer/pkg/util/prometheus.(*ProgressReader).timedUpdateProgress(0xc00007eba0?)
	pkg/util/prometheus/prometheus.go:55 +0x2c
created by kubevirt.io/containerized-data-importer/pkg/util/prometheus.(*ProgressReader).StartTimedUpdate
	pkg/util/prometheus/prometheus.go:48 +0x56

goroutine 11 [semacquire]:
sync.runtime_SemacquireMutex(0x1e?, 0x27?, 0x6?)
	GOROOT/src/runtime/sema.go:71 +0x25
sync.(*Mutex).lockSlow(0x14c47f8)
	GOROOT/src/sync/mutex.go:162 +0x165
sync.(*Mutex).Lock(...)
	GOROOT/src/sync/mutex.go:81
kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.(*loggingT).output(0x14c47e0, 0x3, 0x0, 0xc00013f8f0, 0x0, {0x10aeba0?, 0xf?}, 0xc000070f00?, 0x0)
	vendor/k8s.io/klog/v2/klog.go:920 +0xa5
kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.(*loggingT).printf(0xc000091360?, 0x0?, 0x0, {0x0, 0x0}, {0xd3d1c6, 0x17}, {0xc000070f00, 0x1, 0x1})
	vendor/k8s.io/klog/v2/klog.go:753 +0x1c5
kubevirt.io/containerized-data-importer/vendor/k8s.io/klog/v2.Fatalf(...)
	vendor/k8s.io/klog/v2/klog.go:1532
main.pipeToSnappy.func1()
	cmd/cdi-cloner/clone-source.go:119 +0x12e
created by main.pipeToSnappy
	cmd/cdi-cloner/clone-source.go:116 +0x285

goroutine 16 [IO wait]:
internal/poll.runtime_pollWait(0x7f68c4c5acc8, 0x72)
	GOROOT/src/runtime/netpoll.go:302 +0x89
internal/poll.(*pollDesc).wait(0xc0000f2000?, 0x4e399e?, 0x0)
	GOROOT/src/internal/poll/fd_poll_runtime.go:83 +0x32
internal/poll.(*pollDesc).waitRead(...)
	GOROOT/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Accept(0xc0000f2000)
	GOROOT/src/internal/poll/fd_unix.go:614 +0x22c
net.(*netFD).accept(0xc0000f2000)
	GOROOT/src/net/fd_unix.go:172 +0x35
net.(*TCPListener).accept(0xc000418000)
	GOROOT/src/net/tcpsock_posix.go:139 +0x28
net.(*TCPListener).Accept(0xc000418000)
	GOROOT/src/net/tcpsock.go:288 +0x3d
crypto/tls.(*listener).Accept(0xc000418018)
	GOROOT/src/crypto/tls/tls.go:66 +0x2d
net/http.(*Server).Serve(0xc00021a000, {0xe93648, 0xc000418018})
	GOROOT/src/net/http/server.go:3039 +0x385
net/http.(*Server).ServeTLS(0xc00021a000, {0xe96e88?, 0xc000418000}, {0xc00003a880, 0x1f}, {0xc00003a8e0, 0x1f})
	GOROOT/src/net/http/server.go:3111 +0x3fe
net/http.(*Server).ListenAndServeTLS(0xc00021a000, {0xc00003a880, 0x1f}, {0xc00003a8e0, 0x1f})
	GOROOT/src/net/http/server.go:3266 +0x12f
net/http.ListenAndServeTLS(...)
	GOROOT/src/net/http/server.go:3232
kubevirt.io/containerized-data-importer/pkg/util/prometheus.StartPrometheusEndpoint.func1()
	pkg/util/prometheus/prometheus.go:113 +0xa5
created by kubevirt.io/containerized-data-importer/pkg/util/prometheus.StartPrometheusEndpoint
	pkg/util/prometheus/prometheus.go:111 +0x23b
F0808 08:39:30.681226      10 clone-source.go:119] Error io: read/write on closed pipe piping to gzip

Datavolume definition:

[ksimon:10:41:18~/go/src/kubevirt.io/ssp-operator]$ oc get datavolume
NAME                         PHASE             PROGRESS   RESTARTS   AGE
fedora-datavolume-original   Succeeded         100.0%                45m
fedora-desktop-tiny          CloneInProgress   N/A        11         33m
[ksimon:10:41:23~/go/src/kubevirt.io/ssp-operator]$ oc get datavolume -o yaml
apiVersion: v1
items:
- apiVersion: cdi.kubevirt.io/v1beta1
  kind: DataVolume
  metadata:
    annotations:
      cdi.kubevirt.io/storage.bind.immediate.requested: "true"
      kubectl.kubernetes.io/last-applied-configuration: |
        {"apiVersion":"cdi.kubevirt.io/v1beta1","kind":"DataVolume","metadata":{"annotations":{"cdi.kubevirt.io/storage.bind.immediate.requested":"true"},"name":"fedora-datavolume-original","namespace":"kubevirt"},"spec":{"pvc":{"accessModes":["ReadWriteOnce"],"resources":{"requests":{"storage":"30Gi"}}},"source":{"registry":{"url":"docker://quay.io/kubevirt/common-templates:fedora"}}}}
    creationTimestamp: "2023-08-08T07:56:21Z"
    generation: 1
    name: fedora-datavolume-original
    namespace: kubevirt
    resourceVersion: "167551"
    uid: e0fee454-c252-4802-a3e6-1654bbac84ba
  spec:
    pvc:
      accessModes:
      - ReadWriteOnce
      resources:
        requests:
          storage: 30Gi
    source:
      registry:
        url: docker://quay.io/kubevirt/common-templates:fedora
  status:
    claimName: fedora-datavolume-original
    conditions:
    - lastHeartbeatTime: "2023-08-08T07:56:27Z"
      lastTransitionTime: "2023-08-08T07:56:27Z"
      message: PVC fedora-datavolume-original Bound
      reason: Bound
      status: "True"
      type: Bound
    - lastHeartbeatTime: "2023-08-08T07:57:31Z"
      lastTransitionTime: "2023-08-08T07:57:31Z"
      status: "True"
      type: Ready
    - lastHeartbeatTime: "2023-08-08T07:57:00Z"
      lastTransitionTime: "2023-08-08T07:57:00Z"
      message: Import Complete
      reason: Completed
      status: "False"
      type: Running
    phase: Succeeded
    progress: 100.0%
- apiVersion: cdi.kubevirt.io/v1beta1
  kind: DataVolume
  metadata:
    annotations:
      cdi.kubevirt.io/cloneType: network
      cdi.kubevirt.io/storage.clone.token: eyJhbGciOiJQUzI1NiJ9.eyJleHAiOjE2OTE0ODIzNjEsImlhdCI6MTY5MTQ4MjA2MSwiaXNzIjoiY2RpLWFwaXNlcnZlciIsIm5hbWUiOiJmZWRvcmEtZGF0YXZvbHVtZS1vcmlnaW5hbCIsIm5hbWVzcGFjZSI6Imt1YmV2aXJ0IiwibmJmIjoxNjkxNDgyMDYxLCJvcGVydGF0aW9uIjoiQ2xvbmUiLCJwYXJhbXMiOnsidGFyZ2V0TmFtZSI6ImZlZG9yYS1kZXNrdG9wLXRpbnkiLCJ0YXJnZXROYW1lc3BhY2UiOiJrdWJldmlydCJ9LCJyZXNvdXJjZSI6eyJncm91cCI6IiIsInJlc291cmNlIjoicGVyc2lzdGVudHZvbHVtZWNsYWltcyIsInZlcnNpb24iOiJ2MSJ9fQ.jc8MIIqHn694PqZuvQqlsC2uasdBZ2Zvt951ySdlxzF3DCN5cRmtXSuuPie7lji3yiqJp_KE4AHljeN-dNyg9za7M6Ezg90r0-A7AriXI6KmDP8mGl_zFZhgzmNQDRabjpdZyphKuEqm6N_uvQbLicTdc0wiXmab_6dW18WZQyemsQ3xOJYpUpYvM7Y0FJ9jIsTk9d6geLnPrQkaPV3yxoxXTY0TauG6mmBQ2OVwQiwb0S6ZQw3KVMq23l1AlsaHrU8O6sgLNOf4zRi76LM1bMSPPEWMBO7BDPd1SokIpMANz8B0bdSLn8dVrDRzpNrmNNpodhj1d6pkHFw0FkT4EA
    creationTimestamp: "2023-08-08T08:07:41Z"
    generation: 1
    labels:
      kubevirt.io/created-by: 80ee55d7-d868-459f-8914-2c079923c92d
    name: fedora-desktop-tiny
    namespace: kubevirt
    ownerReferences:
    - apiVersion: kubevirt.io/v1
      blockOwnerDeletion: true
      controller: true
      kind: VirtualMachine
      name: fedora-desktop-tiny
      uid: 80ee55d7-d868-459f-8914-2c079923c92d
    resourceVersion: "289799"
    uid: 02d977c0-9be6-4a7d-9c01-bac4a6a42fa5
  spec:
    source:
      pvc:
        name: fedora-datavolume-original
        namespace: kubevirt
    storage:
      resources:
        requests:
          storage: 30Gi
  status:
    claimName: fedora-desktop-tiny
    conditions:
    - lastHeartbeatTime: "2023-08-08T08:07:46Z"
      lastTransitionTime: "2023-08-08T08:07:46Z"
      message: PVC fedora-desktop-tiny Bound
      reason: Bound
      status: "True"
      type: Bound
    - lastHeartbeatTime: "2023-08-08T08:41:27Z"
      lastTransitionTime: "2023-08-08T08:07:41Z"
      reason: TransferRunning
      status: "False"
      type: Ready
    - lastHeartbeatTime: "2023-08-08T08:41:27Z"
      lastTransitionTime: "2023-08-08T08:41:27Z"
      reason: Pod is running
      status: "True"
      type: Running
    phase: CloneInProgress
    progress: N/A
    restartCount: 11
kind: List
metadata:
  resourceVersion: ""

Logs from cdi-upload pod:

[ksimon:10:52:31~/go/src/kubevirt.io/ssp-operator]$ oc logs -f cdi-upload-fedora-desktop-tiny
I0808 08:08:18.568246       1 uploadserver.go:74] Running server on 0.0.0.0:8443
I0808 08:08:27.003771       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:08:27.032361       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:08:27.032422       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:08:27.779990       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:08:27.786792       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:08:27.786841       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:08:43.725399       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:08:43.730871       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:08:43.730922       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:09:08.630250       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:09:08.635999       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:09:08.636045       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:09:49.297528       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:09:49.303551       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:09:49.303603       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:11:15.559983       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:11:15.564695       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:11:15.564856       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:14:01.461394       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:14:01.466824       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:14:01.466901       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:19:09.632895       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:19:09.639067       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:19:09.639115       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:24:22.459579       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:24:22.465149       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:24:22.465201       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:29:23.285982       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:29:23.291964       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:29:23.292005       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:34:27.489593       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:34:27.496102       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:34:27.496163       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:39:30.675551       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:39:30.680325       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:39:30.680371       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:44:33.569164       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:44:33.574866       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:44:33.574908       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied
I0808 08:49:35.319089       1 uploadserver.go:378] Content type header is "filesystem-clone"
I0808 08:49:35.323952       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:49:35.324002       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied

@ksimon1
Copy link
Member Author

ksimon1 commented Aug 8, 2023

cdi-deployment logs (it keeps iterating this block for every 0,5 seconds):

{"level":"debug","ts":1691485092.4025793,"logger":"controller.clone-controller","msg":"reconciling Clone PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.4027576,"logger":"controller.clone-controller","msg":"Updating PVC from pod","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.4025977,"logger":"controller.import-controller","msg":"reconciling Import PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.4030507,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.4030907,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.4031498,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.403177,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.4053724,"logger":"controller.upload-controller","msg":"reconciling Upload PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"info","ts":1691485092.4054167,"logger":"controller.upload-controller","msg":"Calling Upload reconcile PVC","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.4537373,"logger":"controller.upload-controller","msg":"reconciling Upload PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"info","ts":1691485092.4542925,"logger":"controller.upload-controller","msg":"Calling Upload reconcile PVC","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.454649,"logger":"controller.upload-controller","msg":"Phase is now","pvc.anno.Phase":"Running"}
{"level":"debug","ts":1691485092.4539897,"logger":"controller.clone-controller","msg":"reconciling Clone PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.4541728,"logger":"controller.import-controller","msg":"reconciling Import PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.4549265,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.4549437,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.4549484,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.4549525,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.455004,"logger":"controller.clone-controller","msg":"Updating PVC from pod","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.5065174,"logger":"controller.upload-controller","msg":"reconciling Upload PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"info","ts":1691485092.5066519,"logger":"controller.upload-controller","msg":"Calling Upload reconcile PVC","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.5065467,"logger":"controller.clone-controller","msg":"reconciling Clone PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.5065765,"logger":"controller.import-controller","msg":"reconciling Import PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.5069675,"logger":"controller.clone-controller","msg":"Updating PVC from pod","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.5069823,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.5070214,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.507026,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.5070312,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.5506127,"logger":"controller.upload-controller","msg":"reconciling Upload PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"info","ts":1691485092.5506606,"logger":"controller.upload-controller","msg":"Calling Upload reconcile PVC","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.5506985,"logger":"controller.import-controller","msg":"reconciling Import PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.5507267,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.5507321,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.550736,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.5507398,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.550658,"logger":"controller.clone-controller","msg":"reconciling Clone PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.5507836,"logger":"controller.upload-controller","msg":"Phase is now","pvc.anno.Phase":"Running"}
{"level":"debug","ts":1691485092.5509844,"logger":"controller.clone-controller","msg":"Updating PVC from pod","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.6146708,"logger":"controller.import-controller","msg":"reconciling Import PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.6155543,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.6155665,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.6155717,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.6156003,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.6147428,"logger":"controller.clone-controller","msg":"reconciling Clone PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.6157384,"logger":"controller.clone-controller","msg":"Updating PVC from pod","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.6175401,"logger":"controller.upload-controller","msg":"reconciling Upload PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"info","ts":1691485092.6175833,"logger":"controller.upload-controller","msg":"Calling Upload reconcile PVC","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.6833313,"logger":"controller.upload-controller","msg":"reconciling Upload PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"info","ts":1691485092.6837146,"logger":"controller.upload-controller","msg":"Calling Upload reconcile PVC","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.6839483,"logger":"controller.upload-controller","msg":"Phase is now","pvc.anno.Phase":"Running"}
{"level":"debug","ts":1691485092.6835885,"logger":"controller.import-controller","msg":"reconciling Import PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.684163,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.684199,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.6842258,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.6842525,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.6846628,"logger":"controller.clone-controller","msg":"reconciling Clone PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.6848586,"logger":"controller.clone-controller","msg":"Updating PVC from pod","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.7361336,"logger":"controller.clone-controller","msg":"reconciling Clone PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.7362843,"logger":"controller.import-controller","msg":"reconciling Import PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.7365773,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.7366426,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.7366698,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.endpoint"}
{"level":"debug","ts":1691485092.7366943,"logger":"controller.import-controller","msg":"PVC annotation not found, skipping pvc","PVC":"kubevirt/fedora-desktop-tiny","annotation":"cdi.kubevirt.io/storage.import.source"}
{"level":"debug","ts":1691485092.7364628,"logger":"controller.clone-controller","msg":"Updating PVC from pod","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"debug","ts":1691485092.7385097,"logger":"controller.upload-controller","msg":"reconciling Upload PVCs","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"info","ts":1691485092.738555,"logger":"controller.upload-controller","msg":"Calling Upload reconcile PVC","PVC":"kubevirt/fedora-desktop-tiny"}
{"level":"error","ts":1691485092.7687426,"logger":"controller.datavolume-pvc-clone-controller","msg":"unable to update datavolume status","name":"fedora-desktop-tiny","error":"Operation cannot be fulfilled on datavolumes.cdi.kubevirt.io \"fedora-desktop-tiny\": the object has been modified; please apply your changes to the latest version and try again","stacktrace":"kubevirt.io/containerized-data-importer/pkg/controller/datavolume.ReconcilerBase.updateStatus\n\tpkg/controller/datavolume/controller-base.go:784\nkubevirt.io/containerized-data-importer/pkg/controller/datavolume.(*ReconcilerBase).reconcile\n\tpkg/controller/datavolume/controller-base.go:344\nkubevirt.io/containerized-data-importer/pkg/controller/datavolume.(*PvcCloneReconciler).Reconcile\n\tpkg/controller/datavolume/pvc-clone-controller.go:226\nkubevirt.io/containerized-data-importer/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile\n\tvendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:114\nkubevirt.io/containerized-data-importer/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\tvendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:311\nkubevirt.io/containerized-data-importer/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\tvendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:266\nkubevirt.io/containerized-data-importer/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\tvendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:227"}
{"level":"error","ts":1691485092.7689426,"logger":"controller.datavolume-pvc-clone-controller","msg":"Reconciler error","name":"fedora-desktop-tiny","namespace":"kubevirt","error":"Operation cannot be fulfilled on datavolumes.cdi.kubevirt.io \"fedora-desktop-tiny\": the object has been modified; please apply your changes to the latest version and try again","stacktrace":"kubevirt.io/containerized-data-importer/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\tvendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:266\nkubevirt.io/containerized-data-importer/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\tvendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:227"}

@akalenyu
Copy link
Collaborator

akalenyu commented Aug 8, 2023 

I0808 08:49:35.323952       1 uploadserver.go:481] Untaring 29776412672 bytes to /dev/cdi-block-volume
E0808 08:49:35.324002       1 uploadserver.go:391] Saving stream failed: error unarchiving to /dev/cdi-block-volume: open /dev/cdi-block-volume: permission denied

Sounds like a recent issue we heard about from hypershift folks,
as a result it was decided to revert the triggering change:
cri-o/cri-o#7192

You could also enable a cri-o configurable:
https://github.com/kubevirt/containerized-data-importer/blob/main/doc/block_cri_ownership_config.md

@ksimon1 ksimon1 mentioned this issue Aug 8, 2023
Closed
ksimon1 added a commit to ksimon1/common-templates that referenced this issue Aug 9, 2023
@ksimon1
fix: hardcode cdi version to v1.56.0
ad8c933 
newest cdi contains bug which is causing problems
for our tests. kubevirt/containerized-data-importer#2836

Signed-off-by: Karel Simon <ksimon@redhat.com>
ksimon1 added a commit to ksimon1/common-templates that referenced this issue Aug 9, 2023
@ksimon1
fix: hardcode cdi version to v1.56.0
da0381f 
newest cdi contains bug which is causing problems
for our tests. kubevirt/containerized-data-importer#2836

Signed-off-by: Karel Simon <ksimon@redhat.com>
@codingben codingben mentioned this issue Aug 10, 2023
Closed
@aglitke
Copy link
Member

aglitke commented Aug 14, 2023

This issue should now be resolved by the linked cri-o change. @ksimon1 Are you okay if we close this issue now?

@ksimon1
Copy link
Member Author

ksimon1 commented Aug 14, 2023

yes, thanks

@ksimon1 ksimon1 closed this as completed Aug 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@aglitke @ksimon1 @akalenyu