Bug 2028484

Summary: AWS EBS CSI driver's livenessprobe does not respect operator's loglevel
Product: OpenShift Container Platform Reporter: Jan Safranek <jsafrane>
Component: StorageAssignee: Roman Bednář <rbednar>
Storage sub component: Operators QA Contact: Wei Duan <wduan>
Status: CLOSED ERRATA Docs Contact:
Severity: low    
Priority: unspecified CC: aos-bugs, chaoyang, jdobson, pewang, ropatil
Version: 4.10   
Target Milestone: ---   
Target Release: 4.10.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-03-10 16:31:35 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Jan Safranek 2021-12-02 13:34:15 UTC 
Description of problem:
Log level of liveness probe container of Cinder CSI driver is not changed when ClusterCSIDriver.Spec.LogLevel is changed.

Version-Release number of selected component (if applicable):
4.9.0-0.nightly-2021-11-30-041848

How reproducible:
Always

Steps to Reproduce:
1. oc edit clustercsidriver ebs.csi.aws.com
 - change "logLevel: Normal" to "Trace"
2. Wait for the operator to re-deploy everything.
3. Check log level of liveness probe containers

oc -n openshift-cluster-csi-drivers get deployment aws-ebs-csi-driver-controller -o yaml

Actual results:
Log level is not specified in csi-livenessprobe container:

      - args:
        - --csi-address=/csi/csi.sock
        - --probe-timeout=3s
        - --health-port=10301
        image: quay.io/openshift-release-dev/ocp-v4.0-art-dev@sha256:27bf62619a6463e7f7c175800c0507e0e7427b45db1b33429962709aad35aee7
        imagePullPolicy: IfNotPresent
        name: csi-liveness-probe

Expected results:
      - args:
        - --v=6

Note that it's probably the same with *all* CSI drivers we ship in OCP.
Comment 1 Roman Bednář 2021-12-06 14:15:08 UTC 
Liveness probe container should now react to operator's log level changes. 

I verified the fix using the following steps, posting it for reference and later verification by QE.

=======

1) Get logs from liveness probe container:

$ oc -n openshift-cluster-csi-drivers logs aws-ebs-csi-driver-controller-f486cf7ff-s8p76 csi-liveness-probe
I1206 11:51:01.840062       1 main.go:149] calling CSI driver to discover driver name
I1206 11:51:01.842260       1 main.go:155] CSI driver name: "ebs.csi.aws.com"
I1206 11:51:01.842358       1 main.go:183] ServeMux listening at "0.0.0.0:10301"

2) Change log level in cluster csi driver object:
(change "logLevel: Normal" to "logLevel: Trace")

$ oc edit clustercsidriver ebs.csi.aws.com

3) Verify pods are recreated:

oc -n openshift-cluster-csi-drivers get pod  | grep controller
aws-ebs-csi-driver-controller-f486cf7ff-jnlbv   11/11   Running             0          8s
aws-ebs-csi-driver-controller-f486cf7ff-xq59m   0/11    ContainerCreating   0          3s

$ oc -n openshift-cluster-csi-drivers get pod  | grep controller
aws-ebs-csi-driver-controller-f486cf7ff-jnlbv   11/11   Running   0          27s
aws-ebs-csi-driver-controller-f486cf7ff-xq59m   11/11   Running   0          22

4) Check the logs again:

BEFORE FIX:

Log level change was not respected:

$ oc -n openshift-cluster-csi-drivers logs aws-ebs-csi-driver-controller-f486cf7ff-jnlbv csi-liveness-probe
I1206 12:08:23.077359       1 main.go:149] calling CSI driver to discover driver name
I1206 12:08:23.080035       1 main.go:155] CSI driver name: "ebs.csi.aws.com"
I1206 12:08:23.080314       1 main.go:183] ServeMux listening at "0.0.0.0:10301"


AFTER FIX:

Log level was changed and is now more verbose:

$ oc -n openshift-cluster-csi-drivers logs pod/aws-ebs-csi-driver-controller-79bc77f685-rfpmc csi-liveness-probe
I1206 13:44:10.326609       1 connection.go:154] Connecting to unix:///csi/csi.sock
I1206 13:44:10.327485       1 main.go:149] calling CSI driver to discover driver name
I1206 13:44:10.327510       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo
I1206 13:44:10.327519       1 connection.go:184] GRPC request: {}
I1206 13:44:10.330998       1 connection.go:186] GRPC response: {"name":"ebs.csi.aws.com","vendor_version":"v1.2.0"}
I1206 13:44:10.331087       1 connection.go:187] GRPC error: <nil>
I1206 13:44:10.331118       1 main.go:155] CSI driver name: "ebs.csi.aws.com"
I1206 13:44:10.331129       1 main.go:183] ServeMux listening at "0.0.0.0:10301"
I1206 13:44:26.628356       1 connection.go:154] Connecting to unix:///csi/csi.sock
I1206 13:44:26.628861       1 main.go:69] Sending probe request to CSI driver "ebs.csi.aws.com"
I1206 13:44:26.628884       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I1206 13:44:26.628894       1 connection.go:184] GRPC request: {}
I1206 13:44:26.629624       1 connection.go:186] GRPC response: {}
I1206 13:44:26.629721       1 connection.go:187] GRPC error: <nil>
...
Comment 2 Jan Safranek 2021-12-06 16:04:44 UTC 
We need to fix this in all other CSI driver operators:
https://github.com/openshift/ibm-vpc-block-csi-driver-operator
https://github.com/openshift/aws-efs-csi-driver-operator
https://github.com/openshift/vmware-vsphere-csi-driver-operator
https://github.com/openshift/csi-driver-manila-operator
https://github.com/openshift/openstack-cinder-csi-driver-operator
https://github.com/openshift/alibaba-disk-csi-driver-operator
https://github.com/openshift/ovirt-csi-driver-operator
https://github.com/openshift/gcp-pd-csi-driver-operator
https://github.com/openshift/azure-file-csi-driver-operator
https://github.com/openshift/azure-disk-csi-driver-operator

(not all may use the liveness probe sidecar)
Comment 4 Jonathan Dobson 2021-12-06 20:35:55 UTC 
Moving back to POST to address the other drivers before it goes to QA:
https://bugzilla.redhat.com/show_bug.cgi?id=2028484#c2
Comment 13 Wei Duan 2021-12-15 10:35:19 UTC 
Azure-Disk and Azure-File CSI Driver Operator verified pass on 4.10.0-0.nightly-2021-12-14-083101

Azure-Disk-CSI-Driver:
$ oc get deployment.apps/azure-disk-csi-driver-controller -o json | jq -r '.spec.template.spec.containers[] | select(.name=="csi-liveness-probe").args'
[
  "--csi-address=$(ADDRESS)",
  "--probe-timeout=3s",
  "--health-port=10301",
  "--v=6"
]

$ oc logs deployment.apps/azure-disk-csi-driver-controller csi-liveness-probe
Found 2 pods, using pod/azure-disk-csi-driver-controller-6f7fd84cc5-x7tx6
I1215 09:03:26.542980       1 connection.go:154] Connecting to unix:///var/lib/csi/sockets/pluginproxy/csi.sock
I1215 09:03:26.543671       1 main.go:149] calling CSI driver to discover driver name
I1215 09:03:26.543743       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo
I1215 09:03:26.543776       1 connection.go:184] GRPC request: {}
I1215 09:03:26.549213       1 connection.go:186] GRPC response: {"name":"disk.csi.azure.com","vendor_version":"v1.5.0"}
I1215 09:03:26.549286       1 connection.go:187] GRPC error: <nil>
I1215 09:03:26.549315       1 main.go:155] CSI driver name: "disk.csi.azure.com"
I1215 09:03:26.549325       1 main.go:183] ServeMux listening at "0.0.0.0:10301"
I1215 09:03:28.015696       1 connection.go:154] Connecting to unix:///var/lib/csi/sockets/pluginproxy/csi.sock
I1215 09:03:28.016386       1 main.go:69] Sending probe request to CSI driver "disk.csi.azure.com"
I1215 09:03:28.016407       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I1215 09:03:28.016413       1 connection.go:184] GRPC request: {}
I1215 09:03:28.017457       1 connection.go:186] GRPC response: {"ready":{"value":true}}
I1215 09:03:28.017712       1 connection.go:187] GRPC error: <nil>
I1215 09:03:28.017789       1 main.go:87] Health check succeeded
...

Azure-file:
$ oc get deployment.apps/azure-file-csi-driver-controller  -o json | jq -r '.spec.template.spec.containers[] | select(.name=="csi-liveness-probe").args'
[
  "--csi-address=$(ADDRESS)",
  "--probe-timeout=3s",
  "--health-port=10303",
  "--v=6"
]

$ oc logs deployment.apps/azure-file-csi-driver-controller csi-liveness-probe
Found 2 pods, using pod/azure-file-csi-driver-controller-86479945f9-lsjds
I1215 10:33:45.765144       1 connection.go:154] Connecting to unix:///var/lib/csi/sockets/pluginproxy/csi.sock
I1215 10:33:45.766651       1 main.go:149] calling CSI driver to discover driver name
I1215 10:33:45.766701       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo
I1215 10:33:45.766708       1 connection.go:184] GRPC request: {}
I1215 10:33:45.773450       1 connection.go:186] GRPC response: {"name":"file.csi.azure.com","vendor_version":"v1.7.0"}
I1215 10:33:45.773513       1 connection.go:187] GRPC error: <nil>
I1215 10:33:45.773539       1 main.go:155] CSI driver name: "file.csi.azure.com"
I1215 10:33:45.773548       1 main.go:183] ServeMux listening at "0.0.0.0:10303"
Comment 14 Chao Yang 2022-01-05 09:04:51 UTC 
oc logs pod/ibm-vpc-block-csi-controller-5dc949cf6-9rt6c -c liveness-probe
I0105 08:56:37.233425       1 main.go:149] calling CSI driver to discover driver name
I0105 08:56:37.234944       1 main.go:155] CSI driver name: "vpc.block.csi.ibm.io"
I0105 08:56:37.234959       1 main.go:183] ServeMux listening at "0.0.0.0:9808"

oc logs pod/ibm-vpc-block-csi-controller-56bcb4b544-bgj9k -c liveness-probe
I0105 09:00:11.245474       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:00:12.247027       1 main.go:149] calling CSI driver to discover driver name
I0105 09:00:12.247048       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo
I0105 09:00:12.247053       1 connection.go:184] GRPC request: {}
I0105 09:00:12.249924       1 connection.go:186] GRPC response: {"name":"vpc.block.csi.ibm.io","vendor_version":"vpcBlockDriver-279a88c2795e0ff8ee88784c0140cf7f0492a176"}
I0105 09:00:12.249979       1 connection.go:187] GRPC error: <nil>
I0105 09:00:12.250001       1 main.go:155] CSI driver name: "vpc.block.csi.ibm.io"
I0105 09:00:12.250009       1 main.go:183] ServeMux listening at "0.0.0.0:9808"
I0105 09:00:24.452228       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:00:24.544548       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:00:24.544570       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:00:24.544573       1 connection.go:184] GRPC request: {}
I0105 09:00:24.545287       1 connection.go:186] GRPC response: {}
I0105 09:00:24.545344       1 connection.go:187] GRPC error: <nil>
I0105 09:00:24.545351       1 main.go:87] Health check succeeded
I0105 09:00:34.451823       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:00:34.453343       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:00:34.453377       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:00:34.453382       1 connection.go:184] GRPC request: {}
I0105 09:00:34.453934       1 connection.go:186] GRPC response: {}
I0105 09:00:34.453966       1 connection.go:187] GRPC error: <nil>
I0105 09:00:34.453975       1 main.go:87] Health check succeeded
I0105 09:00:44.451224       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:00:44.451883       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:00:44.452011       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:00:44.452020       1 connection.go:184] GRPC request: {}
I0105 09:00:44.452554       1 connection.go:186] GRPC response: {}
I0105 09:00:44.452584       1 connection.go:187] GRPC error: <nil>
I0105 09:00:44.452591       1 main.go:87] Health check succeeded
I0105 09:00:54.450858       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:00:54.451272       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:00:54.451300       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:00:54.451304       1 connection.go:184] GRPC request: {}
I0105 09:00:54.451779       1 connection.go:186] GRPC response: {}
I0105 09:00:54.451817       1 connection.go:187] GRPC error: <nil>
I0105 09:00:54.451825       1 main.go:87] Health check succeeded
I0105 09:01:04.451802       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:01:04.452320       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:01:04.452352       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:01:04.452357       1 connection.go:184] GRPC request: {}
I0105 09:01:04.452895       1 connection.go:186] GRPC response: {}
I0105 09:01:04.452925       1 connection.go:187] GRPC error: <nil>
I0105 09:01:04.452933       1 main.go:87] Health check succeeded
I0105 09:01:14.453262       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:01:14.453758       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:01:14.453791       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:01:14.453795       1 connection.go:184] GRPC request: {}
I0105 09:01:14.454289       1 connection.go:186] GRPC response: {}
I0105 09:01:14.454342       1 connection.go:187] GRPC error: <nil>
I0105 09:01:14.454349       1 main.go:87] Health check succeeded
I0105 09:01:24.451366       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:01:24.451828       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:01:24.451863       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:01:24.451867       1 connection.go:184] GRPC request: {}
I0105 09:01:24.452305       1 connection.go:186] GRPC response: {}
I0105 09:01:24.452348       1 connection.go:187] GRPC error: <nil>
I0105 09:01:24.452356       1 main.go:87] Health check succeeded
I0105 09:01:34.451908       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:01:34.452343       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:01:34.452372       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:01:34.452377       1 connection.go:184] GRPC request: {}
I0105 09:01:34.452886       1 connection.go:186] GRPC response: {}
I0105 09:01:34.452915       1 connection.go:187] GRPC error: <nil>
I0105 09:01:34.452923       1 main.go:87] Health check succeeded
I0105 09:01:44.451317       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:01:44.451753       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:01:44.451785       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:01:44.451790       1 connection.go:184] GRPC request: {}
I0105 09:01:44.452250       1 connection.go:186] GRPC response: {}
I0105 09:01:44.452277       1 connection.go:187] GRPC error: <nil>
I0105 09:01:44.452284       1 main.go:87] Health check succeeded
I0105 09:01:54.451356       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:01:54.451825       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:01:54.451856       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:01:54.451861       1 connection.go:184] GRPC request: {}
I0105 09:01:54.452382       1 connection.go:186] GRPC response: {}
I0105 09:01:54.452412       1 connection.go:187] GRPC error: <nil>
I0105 09:01:54.452420       1 main.go:87] Health check succeeded
I0105 09:02:04.450841       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:02:04.451328       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:02:04.451359       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:02:04.451363       1 connection.go:184] GRPC request: {}
I0105 09:02:04.451858       1 connection.go:186] GRPC response: {}
I0105 09:02:04.451890       1 connection.go:187] GRPC error: <nil>
I0105 09:02:04.451900       1 main.go:87] Health check succeeded
I0105 09:02:14.451839       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:02:14.452665       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:02:14.452696       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:02:14.452712       1 connection.go:184] GRPC request: {}
I0105 09:02:14.453212       1 connection.go:186] GRPC response: {}
I0105 09:02:14.453246       1 connection.go:187] GRPC error: <nil>
I0105 09:02:14.453253       1 main.go:87] Health check succeeded
I0105 09:02:24.451227       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:02:24.451750       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:02:24.451780       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:02:24.451785       1 connection.go:184] GRPC request: {}
I0105 09:02:24.452236       1 connection.go:186] GRPC response: {}
I0105 09:02:24.452269       1 connection.go:187] GRPC error: <nil>
I0105 09:02:24.452276       1 main.go:87] Health check succeeded
I0105 09:02:34.451095       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:02:34.451544       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:02:34.451607       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:02:34.451612       1 connection.go:184] GRPC request: {}
I0105 09:02:34.452186       1 connection.go:186] GRPC response: {}
I0105 09:02:34.452213       1 connection.go:187] GRPC error: <nil>
I0105 09:02:34.452221       1 main.go:87] Health check succeeded
I0105 09:02:44.451110       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:02:44.451525       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:02:44.451608       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:02:44.451619       1 connection.go:184] GRPC request: {}
I0105 09:02:44.452099       1 connection.go:186] GRPC response: {}
I0105 09:02:44.452146       1 connection.go:187] GRPC error: <nil>
I0105 09:02:44.452153       1 main.go:87] Health check succeeded
I0105 09:02:54.451003       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:02:54.451422       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:02:54.451454       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:02:54.451459       1 connection.go:184] GRPC request: {}
I0105 09:02:54.451943       1 connection.go:186] GRPC response: {}
I0105 09:02:54.451982       1 connection.go:187] GRPC error: <nil>
I0105 09:02:54.451990       1 main.go:87] Health check succeeded
I0105 09:03:04.451293       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:03:04.451720       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:03:04.451796       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:03:04.451808       1 connection.go:184] GRPC request: {}
I0105 09:03:04.452303       1 connection.go:186] GRPC response: {}
I0105 09:03:04.452331       1 connection.go:187] GRPC error: <nil>
I0105 09:03:04.452339       1 main.go:87] Health check succeeded
I0105 09:03:14.451850       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:03:14.452335       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:03:14.452362       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:03:14.452366       1 connection.go:184] GRPC request: {}
I0105 09:03:14.452807       1 connection.go:186] GRPC response: {}
I0105 09:03:14.452839       1 connection.go:187] GRPC error: <nil>
I0105 09:03:14.452846       1 main.go:87] Health check succeeded
I0105 09:03:24.451235       1 connection.go:154] Connecting to unix:///csi/csi.sock
I0105 09:03:24.451714       1 main.go:69] Sending probe request to CSI driver "vpc.block.csi.ibm.io"
I0105 09:03:24.451741       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0105 09:03:24.451746       1 connection.go:184] GRPC request: {}
I0105 09:03:24.452223       1 connection.go:186] GRPC response: {}
I0105 09:03:24.452252       1 connection.go:187] GRPC error: <nil>
I0105 09:03:24.452261       1 main.go:87] Health check succeeded


passed with 4.10.0-0.nightly-2021-12-23-153012
Comment 16 Wei Duan 2022-01-06 11:52:02 UTC 
Verified pass on Ali CSI Driver.
Comment 17 Wei Duan 2022-01-06 11:52:30 UTC 
Mark it as Verified.
Comment 20 errata-xmlrpc 2022-03-10 16:31:35 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 (Moderate: OpenShift Container Platform 4.10.3 security update), 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-2022:0056