NodeStageVolume is called again even after the successful response about ibm-powervs-block-csi-driver

[Madhan-SWE]

The first Node stage volume call is made at 10:21

I1214 10:21:57.940053       1 node.go:91] NodeStageVolume: called with args {VolumeId:4ee2661e-adf7-4172-a168-59d562ef9791 PublishContext:map[wwn:6005076810830198a0000000000015d1] StagingTargetPath:/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1639477051560-8081-powervs.csi.ibm.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I1214 10:21:57.940174       1 node.go:135] NodeStageVolume: wwnkey: wwn, req.PublishContext: map[wwn:6005076810830198a0000000000015d1]
I1214 10:21:57.940196       1 node.go:142] NodeStageVolume: Get device path for wwn: 6005076810830198a0000000000015d1
I1214 10:21:57.940206       1 mount.go:72] GetDevicePath: c.WWIDs : [36005076810830198a0000000000015d1]
ERROR: logging before flag.Parse: I1214 10:21:57.940217       1 fibrechannel.go:246] Attaching fibre channel volume
ERROR: logging before flag.Parse: I1214 10:21:57.941656       1 fibrechannel.go:231]  = = = = = = = = = =  = = = = Disk : /dev/dm-11 dm:

.....
.....
ERROR: logging before flag.Parse: I1214 10:23:08.922284       1 fibrechannel.go:231]  = = = = = = = = = =  = = = = Disk : /dev/dm-11 dm:
I1214 10:23:08.922316       1 node.go:148] NodeStageVolume: find device path for wwn 6005076810830198a0000000000015d1 -> /dev/dm-11
I1214 10:23:08.923079       1 node.go:184] NodeStageVolume: formatting /dev/dm-11 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount with fstype xfs
I1214 10:23:08.923094       1 mount_linux.go:405] Attempting to determine if disk "/dev/dm-11" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/dm-11])
I1214 10:23:08.930690       1 mount_linux.go:408] Output: "", err: exit status 2
I1214 10:23:08.930720       1 mount_linux.go:366] Disk "/dev/dm-11" appears to be unformatted, attempting to format as type: "xfs" with options: [/dev/dm-11]

Since the previous volume staging is not completed, another call is made for NodeStageVolume.

I1214 10:23:58.538418       1 node.go:91] NodeStageVolume: called with args {VolumeId:4ee2661e-adf7-4172-a168-59d562ef9791 PublishContext:map[wwn:6005076810830198a0000000000015d1] StagingTargetPath:/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_WRITER >  Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1639477051560-8081-powervs.csi.ibm.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I1214 10:23:58.538523       1 node.go:135] NodeStageVolume: wwnkey: wwn, req.PublishContext: map[wwn:6005076810830198a0000000000015d1]
I1214 10:23:58.538545       1 node.go:142] NodeStageVolume: Get device path for wwn: 6005076810830198a0000000000015d1
I1214 10:23:58.538558       1 mount.go:72] GetDevicePath: c.WWIDs : [36005076810830198a0000000000015d1]
ERROR: logging before flag.Parse: I1214 10:23:58.538572       1 fibrechannel.go:246] Attaching fibre channel volume
ERROR: logging before flag.Parse: I1214 10:23:58.540199       1 fibrechannel.go:231]  = = = = = = = = = =  = = = = Disk : /dev/dm-11 dm:
I1214 10:24:00.366208       1 mount_linux.go:376] Disk successfully formatted (mkfs): xfs - /dev/dm-11 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount
I1214 10:24:00.366228       1 mount_linux.go:394] Attempting to mount disk /dev/dm-11 in xfs format at /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount
I1214 10:24:00.366247       1 mount_linux.go:146] Mounting cmd (mount) with arguments (-t xfs -o defaults /dev/dm-11 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount)

At the same time previous Node stage volume is finished. That causes the current call to fail with error Volume already mounted

I1214 10:24:00.366247       1 mount_linux.go:146] Mounting cmd (mount) with arguments (-t xfs -o defaults /dev/dm-11 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount)
I1214 10:24:01.026631       1 node.go:190] Node stage volume finished ++++++++++++++++++++ source /dev/dm-11 target /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount wwn 6005076810830198a0000000000015d1
I1214 10:24:04.241553       1 node.go:356] NodeGetCapabilities: called with args {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I1214 10:24:16.506235       1 node.go:356] NodeGetCapabilities: called with args {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
ERROR: logging before flag.Parse: I1214 10:24:32.977824       1 fibrechannel.go:231]  = = = = = = = = = =  = = = = Disk : /dev/dm-11 dm:
I1214 10:24:32.977847       1 node.go:148] NodeStageVolume: find device path for wwn 6005076810830198a0000000000015d1 -> /dev/dm-11
I1214 10:24:32.978728       1 node.go:184] NodeStageVolume: formatting /dev/dm-11 and mounting at /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount with fstype xfs
I1214 10:24:32.978751       1 mount_linux.go:405] Attempting to determine if disk "/dev/dm-11" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/dm-11])
I1214 10:24:32.980885       1 mount_linux.go:408] Output: "DEVNAME=/dev/dm-11\nTYPE=xfs\n", err: <nil>
I1214 10:24:32.980902       1 mount_linux.go:298] Checking for issues with fsck on disk: /dev/dm-11
I1214 10:24:32.985722       1 mount_linux.go:394] Attempting to mount disk /dev/dm-11 in xfs format at /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount
I1214 10:24:32.985745       1 mount_linux.go:146] Mounting cmd (mount) with arguments (-t xfs -o defaults /dev/dm-11 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount)
E1214 10:24:32.988904       1 mount_linux.go:150] Mount failed: exit status 32
Mounting command: mount
Mounting arguments: -t xfs -o defaults /dev/dm-11 /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount
Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount: /dev/mapper/mpathu already mounted on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount.

E1214 10:24:32.989378       1 driver.go:116] GRPC error: rpc error: code = Internal desc = could not format "/dev/dm-11" and mnt it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-6d954fa8-d913-410e-ba8e-a23accdd1b53/globalmount"

[Madhan-SWE]

Expected fixes could be:

• Need to find a way to increase the timeout for kublet calling the node plugin methods
• Need to handle Volume already mounted error and if the volume is already mounted on the expected target path then return success response