Disk mounted in wrong VM (Atomic Host/Openshift 3.11)

[danragnar]

Description Disk is created fine, but when creating the pod where the disk/volume should be attached, it gets mounted in the wrong VM (master instead of node). FlexVolume is installed on all nodes and seems to propagate to the containerized kubelet, and the vm id in the flexvolume config is consistent with the vm id in ovirt.

Steps To Reproduce

1. Install openshift/okd 3.11 on rhel atomic host
2. Modify paths to flexvolume driver on atomic host (/etc/origin/kubelet-plugins/...) in repo and build containers locally. Push the flexvolume driver to the openshift registry and deploy with locally modified apb docker image that fixes docker image location and paths for flex volume driver
3. Create Storage Class according to example
4. Create PVC according to example (disk is created fine)
5. Create Pod according to example. disk is mounted on the elected master (i think) instead of the node where pod is running.

Expected behavior Disk should be mounted on correct VM.

Versions:

• OS: Red Hat Enterprise Linux Atomic Host 7.6.1.1

• Openshift|kubernetes version oc version or kubectl version: openshift v3.11.0+cbab8ee-94, kubernetes v1.11.0+d4cacc0

• oVirt version rpm -ql ovirt-engine: 4.2.6.4

Logs: Master

• Openshift master and node: journalctrl --since "-2h"

  Feb 07 15:48:56 ocp-master-01.domain.name dockerd-current[4753]: W0207 14:48:56.317657       1 plugin-defaults.go:32] flexVolume driver ovirt/ovirt-flexvolume-driver: using default GetVolumeName for volume pvc-d1676c0e-2ad1-11e9-93d9-001a4a160194
  Feb 07 15:48:56 ocp-master-01.domain.name dockerd-current[4753]: W0207 14:48:56.418019       1 plugin-defaults.go:32] flexVolume driver ovirt/ovirt-flexvolume-driver: using default GetVolumeName for volume pvc-d1676c0e-2ad1-11e9-93d9-001a4a160194
  Feb 07 15:48:56 ocp-master-01.domain.name dockerd-current[4753]: E0207 14:48:56.506312       1 driver-call.go:253] Failed to unmarshal output for command: isattached, output: "panic: runtime error: index out of range\n\ngoroutine 1 [running]:\nmain.IsAttached(0x7ffc102e1dcc, 0x88, 0x7ffc102e1e55, 0x14, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)\n\t/root/g
  o/src/github.com/ovirt/ovirt-openshift-extensions/cmd/ovirt-flexvolume-driver/ovirt-flexdriver.go:258 +0x7e8\nmain.app(0xc00008a010, 0x3, 0x3, 0x0, 0x8e7a40, 0xc00006f220, 0
  x818580)\n\t/root/go/src/github.com/ovirt/ovirt-openshift-extensions/cmd/ovirt-flexvolume-driver/ovirt-flexdriver.go:94 +0xa77\nmain.main()\n\t/root/go/src/github.com/ovirt/ovirt-openshift-extensions/cmd/ovirt-flexvolume-driver/ovirt-flexdriver.go:59 +0xbd\n", error: invalid character 'p' looking for beginning of value
  Feb 07 15:48:56 ocp-master-01.domain.name dockerd-current[4753]: W0207 14:48:56.506438       1 driver-call.go:144] FlexVolume: driver call failed: executable: /etc/origin/kubelet-plugins/volume/exec/ovirt~ovirt-flexvolume-driver/ovirt-flexvolume-driver, args: [isattached {"kubernetes.io/fsType":"ext4","kubernetes.io/pvOrVolumeName":"pvc-d1676c0e-2
  ad1-11e9-93d9-001a4a160194","kubernetes.io/readwrite":"rw"} ocp-node-01.domain.name], error: exit status 2, output: "panic: runtime error: index out of range\n\ngoroutine 1 [running]:\nmain.IsAttached(0x7ffc102e1dcc, 0x88, 0x7ffc102e1e55, 0x14, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)\n\t/root/go/src/github.com/ovirt/ovirt-openshift-extensions/cmd/ovirt
  -flexvolume-driver/ovirt-flexdriver.go:258 +0x7e8\nmain.app(0xc00008a010, 0x3, 0x3, 0x0, 0x8e7a40, 0xc00006f220, 0x818580)\n\t/root/go/src/github.com/ovirt/ovirt-openshift-extensions/cmd/ovirt-flexvolume-driver/ovirt-flexdriver.go:94 +0xa77\nmain.main()\n\t/root/go/src/github.com/ovirt/ovirt-openshift-extensions/cmd/ovirt-flexvolume-driver/ovirt-flexdriver.go:59 +0xbd\n"
  Feb 07 15:48:56 ocp-master-01.domain.name dockerd-current[4753]: E0207 14:48:56.506481       1 operation_generator.go:186] VolumesAreAttached failed for checking on node "ocp-node-01.domain.name" with: invalid character 'p' looking for beginning of value

• volume-provisioner pod: oc logs pods/ovirt-volume-provisioner-XYZ

  I0207 14:45:57.750727       1 leaderelection.go:156] attempting to acquire leader lease...
  I0207 14:45:57.762517       1 leaderelection.go:178] successfully acquired lease to provision for pvc default/mediawiki
  I0207 14:45:57.766148       1 provision.go:75] About to provision a disk name: pvc-143c07fb-2ae7-11e9-93d9-001a4a160194 domain: vm_disk size: 1073741824 thin provisioned:  file system: ext4
  I0207 14:45:57.767432       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"mediawiki", UID:"143c07fb-2ae7-11e9-93d9-001a4a160194", APIVersion:"v1", ResourceVersion:"487888", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "default/mediawiki"
  E0207 14:45:57.827569       1 controller.go:1074] Failed to provision volume for claim "default/mediawiki" with StorageClass "ovirt": 401 Unauthorized
  I0207 14:45:57.827749       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"mediawiki", UID:"143c07fb-2ae7-11e9-93d9-001a4a160194", APIVersion:"v1", ResourceVersion:"487888", FieldPath:""}): type: 'Warning' reason: 'ProvisioningFailed' Failed to provision volume with StorageClass "ovirt": 401 Unauthorized
  I0207 14:45:59.785944       1 leaderelection.go:198] stopped trying to renew lease to provision for pvc default/mediawiki, task failed
  W0207 14:45:59.786012       1 controller.go:686] retrying syncing claim "default/mediawiki" because failures 0 < threshold 15
  E0207 14:45:59.786065       1 controller.go:701] error syncing claim "default/mediawiki": 401 Unauthorized
  I0207 14:45:59.904712       1 leaderelection.go:156] attempting to acquire leader lease...
  I0207 14:45:59.910473       1 leaderelection.go:178] successfully acquired lease to provision for pvc default/mediawiki
  I0207 14:45:59.919567       1 provision.go:75] About to provision a disk name: pvc-143c07fb-2ae7-11e9-93d9-001a4a160194 domain: vm_disk size: 1073741824 thin provisioned:  file system: ext4
  I0207 14:45:59.919694       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"mediawiki", UID:"143c07fb-2ae7-11e9-93d9-001a4a160194", APIVersion:"v1", ResourceVersion:"487890", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "default/mediawiki"
  I0207 14:46:00.332997       1 controller.go:1079] volume "pvc-143c07fb-2ae7-11e9-93d9-001a4a160194" for claim "default/mediawiki" created
  I0207 14:46:00.343494       1 controller.go:1096] volume "pvc-143c07fb-2ae7-11e9-93d9-001a4a160194" for claim "default/mediawiki" saved
  I0207 14:46:00.343519       1 controller.go:1132] volume "pvc-143c07fb-2ae7-11e9-93d9-001a4a160194" provisioned for claim "default/mediawiki"
  I0207 14:46:00.343852       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"mediawiki", UID:"143c07fb-2ae7-11e9-93d9-001a4a160194", APIVersion:"v1", ResourceVersion:"487890", FieldPath:""}): type: 'Normal' reason: 'ProvisioningSucceeded' Successfully provisioned volume pvc-143c07fb-2ae7-11e9-93d9-001a4a160194
  I0207 14:46:01.952810       1 leaderelection.go:198] stopped trying to renew lease to provision for pvc default/mediawiki, task succeeded

• ovirt-engine: /var/log/ovirt-engine/engine.log

  
  2019-02-07 15:46:00,051+01 INFO  [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] Running command: AddDiskCom
  mand internal: false. Entities affected :  ID: d144b561-9092-493a-9a9f-63de51807b01 Type: StorageAction group CREATE_DISK with role type USER
  2019-02-07 15:46:00,080+01 INFO  [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] Running c
  ommand: AddImageFromScratchCommand internal: true. Entities affected :  ID: d144b561-9092-493a-9a9f-63de51807b01 Type: Storage
  2019-02-07 15:46:00,118+01 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] START, CreateImageVDSCommand( CreateImageVDSCommandParameters:{storagePoolId='5adf3acb-034d-0291-0258-0000000003bd', ignoreFailoverLimit='false', storageDomainId='d144b561-9092-493a-9a9f-63de51807b01', imageGroupId='059fd7e3-721e-4a17-8294-81844e09b412', imageSizeInBytes='1073741824', volumeFormat='RAW', newImageId='18e61e96-33fb-44a0-9725-38a8e63d6fe8', imageType='Sparse', newImageDescription='{"DiskAlias":"pvc-143c07fb-2ae7-11e9-93d9-001a4a160194","DiskDescription":""}', imageInitialSizeInBytes='0'}), log id: 45d1caaa
  2019-02-07 15:46:00,118+01 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] -- executeIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
  2019-02-07 15:46:00,230+01 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] FINISH, CreateImageVDSCommand, return: 18e61e96-33fb-44a0-9725-38a8e63d6fe8, log id: 45d1caaa
  2019-02-07 15:46:00,237+01 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command '6acde297-737f-458e-a8ce-6f31fd87a9f8'
  2019-02-07 15:46:00,237+01 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] CommandMultiAsyncTasks::attachTask: Attaching task '2ea7349e-0bd7-4964-ba16-19b7fc020817' to command '6acde297-737f-458e-a8ce-6f31fd87a9f8'.
  2019-02-07 15:46:00,262+01 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] Adding task '2ea7349e-0bd7-4964-ba16-19b7fc020817' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet..
  2019-02-07 15:46:00,281+01 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] BaseAsyncTask::startPollingTask: Starting to poll task '2ea7349e-0bd7-4964-ba16-19b7fc020817'.
  2019-02-07 15:46:00,306+01 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-27) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] EVENT_ID: USER_ADD_DISK(2,020), Add-Disk operation of 'pvc-143c07fb-2ae7-11e9-93d9-001a4a160194' was initiated by admin@internal-authz.
  2019-02-07 15:46:00,433+01 INFO  [org.ovirt.engine.core.bll.AddDeprecatedApiEventCommand] (default task-24) [38db92b4] Running command: AddDeprecatedApiEventCommand internal: false.
  2019-02-07 15:46:00,505+01 INFO  [org.ovirt.engine.core.bll.AddDeprecatedApiEventCommand] (default task-57) [5034cd9] Running command: AddDeprecatedApiEventCommand internal: false.
  2019-02-07 15:46:00,709+01 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-96) [052d9132-a8b5-45cd-813a-b7aaea9aa2a7] Command 'AddDisk' (id: 'ee0c5d02-2105-42e9-b073-81450271c3ab') waiting on child command id: '6acde297-737f-458e-a8ce-6f31fd87a9f8' type:'AddImageFromScratch' to complete
  ...
  2019-02-07 15:47:31,577+01 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-62) [4f1f424b] EVENT_ID: USER_VDC_LOGIN(30), User admin
  @internal-authz connecting from '10.X.X.56' using session 'gl/9KTXcx/ZmJAeViotl1hldGQDojWEUYiihLQGuQC7KzVvOfxFeZY7Kx5oFI0ftF+tGinwI+HdyDPSDU97O5Q==' logged in.
  2019-02-07 15:47:31,741+01 INFO  [org.ovirt.engine.core.bll.storage.disk.AttachDiskToVmCommand] (default task-51) [25276cec-04fc-4c94-b00a-77a8fdb52140] Lock Acquired to obj
  ect 'EngineLock:{exclusiveLocks='[059fd7e3-721e-4a17-8294-81844e09b412=DISK]', sharedLocks=''}'
  2019-02-07 15:47:31,763+01 INFO  [org.ovirt.engine.core.bll.storage.disk.AttachDiskToVmCommand] (default task-51) [25276cec-04fc-4c94-b00a-77a8fdb52140] Running command: Att
  achDiskToVmCommand internal: false. Entities affected :  ID: 31e89a6f-da55-46ad-b91f-8775699f121b Type: VMAction group CONFIGURE_VM_STORAGE with role type USER,  ID: 059fd7e
  3-721e-4a17-8294-81844e09b412 Type: DiskAction group ATTACH_DISK with role type USER
  2019-02-07 15:47:31,771+01 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotPlugDiskVDSCommand] (default task-51) [25276cec-04fc-4c94-b00a-77a8fdb52140] START, HotPlugDis
  kVDSCommand(HostName = rhev2.domain.name, HotPlugDiskVDSParameters:{hostId='457e19bb-cd5b-4c59-ab91-473152433920', vmId='31e89a6f-da55-46ad-b91f-8775699f121b', diskId='059fd7e3
  -721e-4a17-8294-81844e09b412', addressMap='[bus=0, controller=0, unit=2, type=drive, target=0]'}), log id: 2743ef58
  2019-02-07 15:47:31,777+01 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotPlugDiskVDSCommand] (default task-51) [25276cec-04fc-4c94-b00a-77a8fdb52140] Disk hot-plug: <?
  xml version="1.0" encoding="UTF-8"?><hotplug>
  <devices>
  <disk snapshot="no" type="file" device="disk">
    <target dev="sda" bus="scsi"/>
    <source file="/rhev/data-center/5adf3acb-034d-0291-0258-0000000003bd/d144b561-9092-493a-9a9f-63de51807b01/images/059fd7e3-721e-4a17-8294-81844e09b412/18e61e96-33fb-44a
  0-9725-38a8e63d6fe8"/>
    <driver name="qemu" io="threads" type="raw" error_policy="stop" cache="none"/>
    <alias name="ua-059fd7e3-721e-4a17-8294-81844e09b412"/>
    <address bus="0" controller="0" unit="2" type="drive" target="0"/>
    <serial>059fd7e3-721e-4a17-8294-81844e09b412</serial>
  </disk>
  </devices>
  <metadata xmlns:ovirt-vm="http://ovirt.org/vm/1.0">
  <ovirt-vm:vm>
    <ovirt-vm:device devtype="disk" name="sda">
      <ovirt-vm:poolID>5adf3acb-034d-0291-0258-0000000003bd</ovirt-vm:poolID>
      <ovirt-vm:volumeID>18e61e96-33fb-44a0-9725-38a8e63d6fe8</ovirt-vm:volumeID>
      <ovirt-vm:imageID>059fd7e3-721e-4a17-8294-81844e09b412</ovirt-vm:imageID>
      <ovirt-vm:domainID>d144b561-9092-493a-9a9f-63de51807b01</ovirt-vm:domainID>
    </ovirt-vm:device>
  </ovirt-vm:vm>
  </metadata>
  </hotplug>

2019-02-07 15:47:32,183+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotPlugDiskVDSCommand] (default task-51) [25276cec-04fc-4c94-b00a-77a8fdb52140] FINISH, HotPlugDi skVDSCommand, log id: 2743ef58 2019-02-07 15:47:32,203+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-51) [25276cec-04fc-4c94-b00a-77a8fdb52140] EVENT_ID: USER_ATTACH_DISK_TO_VM(2,016), Disk pvc-143c07fb-2ae7-11e9-93d9-001a4a160194 was successfully attached to VM ocp-master-01.domain.name by admin@internal-authz.

[rgolangh]

First, I see that I didn't check the disk result to return empty ovirt-flexdriver.go:258 - and that explains why the isAttach call panics.

• what is the version of ovirt-flexvolume-driver you are using?
• The pvc which is attached to master is pvc-143c07fb-2ae7-11e9-93d9-001a4a160194 . It is not the one which you reported error on. Can you double check the pods list?

[danragnar]

Hmm, yea, sorry about the pvc inconsistency. I have debugged a lot, so there might be different deployment attempts in the logs, it's consistent however.

I have tried multiple different versions of the driver, from older versions where the name of the VM is used instead of the ID to the latest build. Same problem. I have now reinstalled my cluster on regular RHEL 7.6 VM:s, and now it works. I specifically installed OpenShift to give this project a try and thought I would give Atomic a shot since the openshift install seemed a lot easier.

If you want to continue to troubleshoot, I can bring up a new cluster based on Atomic if you want. Otherwise you can close this issue if you want to. It works as expected on regular RHEL.

[rgolangh]

Can you verify that openshift made the call to flexvolume on the node and not on master? its openshift responsibility to call out, or execute the 'attach' command. Also, you did make sure that whatever ovirtVmId you had in ovirt-flexvolume-driver.conf was matching the VM it was deployed on, right? I assume the fact that you used atomic was the reason you had to deploy the driver on /etc?

p.s thanks a lot for reporting that.

[danragnar]

Well both the master and node receives the call, but when the node tries to mount the device on the system it isn't there, as it is mounted on the master. The ID's and virtual machine names were consistent with oVirt. Yes exactly, I deployed it with a modifed APB that mounts /etc/origin/kubelet-plugins/volume/exec/ in the "regular" path inside the driver container. So the driver ends up in the correct directory for the kubelet.

As I said, I took down the environment and got it working on regular RHEL, which I'll be happy to continue with. I saw that there was some issue previously reporting very similar problems (however not on OKD/origin 3.11). Do you have the possibility to try to reproduce the fault on Atomic on your end?

[rgolangh]

Well both the master and node receives the call, but when the node tries to mount the device on the system it isn't there, as it is mounted on the master.

If the master got the attach call-out then this is not a good thing and probably is an openshift bug. I'd check the pod logs of master-controllers-XYZ on the kube-system namespace. As far as I remember the attach should be called on the node that runs the pod. If that's not the case, then that's my bug because I extract the VM id from the underlying system at the time of the call.

[danragnar]

I'm not 100% sure that both get the attach call. I can't check anymore since I don't have the environment anymore. I'll close the issue. If I give atomic another shot and experience the same issues, I'll open a new one and reference this one. Thanks for the help!

[levindecaro]

Hi, I got exact the same issues, but on CentOS Linux, okd3.11, everything is fresh installed, vdisks was created by provisioner, however, the pvc will attach to origin master node when the pod is launching. As a result, the actual assigned pod node will pending on the volume and ultimately mount fail. Noticed that ovirt logs got few attach/detach vdisk operation with that pvc to master node 1.

Checked every node ovirtVmId is correct in /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ovirt~ovirt-flexvolume-driver/ovirt-flexvolume-driver.conf

[rgolangh]

@levindecaro can you get the logs of the master-controller-xyz pod under kube-system namespace?

something like:

oc logs -n kube-system pods/master-controllers-$(hostname)

[levindecaro]

Here you are, thanks

oc1.log oc2.log oc3.log

[rgolangh]

@danragnar @levindecaro a fix is pushed, not merged yet. The CI will build a test container and you can use it to test the fix at your env(I'll paste the link as soon as its ready)

[levindecaro]

@rgolangh brilliant, will test it asap.

[rgolangh]

I made another iteration so it will work for default kubernets and default openshift configurations. Checkout quay.io[1] for the latest tag - you should have one in ~30 minutes from now.

You can also follow the pull request conversation for updates.

[1] https://quay.io/repository/rgolangh/ovirt-flexvolume-driver?tab=tags

[levindecaro]

problem resolved. thank you.