microk8s kubelet cannot connect to secret-operator node registrar

[sheng-kenbun]

Affected version

zk-op 0.12.0

Current and expected behavior

This happened in microk8s. After apply -f zookeeper.yml the operator created PVC, configmap and pods but no PV is created. The PVC and pods are in pending because they can not find PV to bind. The k8s local-path-provisioner is installed.

created PVC by the zookeeper operator:

data-kenbun-zk-server-default-0               Pending                       microk8s-hostpath        16m
kenbun-zk-server-default-0-client-tls-mount   Pending                       secrets.stackable.tech   16m
kenbun-zk-server-default-0-quorum-tls-mount   Pending                       secrets.stackable.tech   16m

but no created PV in the same namespace:
´´´
&> microk8s kubectl -n stackable get pv
No resources found
´´´

Expected:
Zookeeper pods are correctly started and running in microk8s, like in kind or minikube.

Is there already a known issue about this unexpected behaviour in microk8s? How can I get some further information about that why the operator failed to create pv? (operator logs, ect.)

Possible solution

No response

Additional context

commons=0.4.0, secret=0.6.0 and zookeeper=0.12.0 are installed by stackablectl operator install

NAME                                            READY   STATUS    RESTARTS   AGE
commons-operator-deployment-7bdd9fd6b7-2pt55    1/1     Running   0          10h
zookeeper-operator-deployment-bcdc889db-7wjqh   1/1     Running   0          10h
secret-operator-daemonset-njf5c                 3/3     Running   0          10h

Environment

microk8s kubectl version --short:

Client Version: v1.25.4
Kustomize Version: v4.5.7
Server Version: v1.25.4

OS: ubuntu 22.04 x86_64

Would you like to work on fixing this bug?

None

[sbernauer]

Hi @sheng-kenbun, thanks for your report!
I personally have never used microk8s but do use kind with local-path-provisioner.
Could you please do me a favor and provide us with the output of kubectl describe pvc? The zookeeper.yml would be great as well.

[sheng-kenbun]

@sbernauer thank you for the rapid response!
describe pvc:

Name:          data-kenbun-zk-server-default-0
Namespace:     stackable-poc
StorageClass:  microk8s-hostpath
Status:        Pending
Volume:
Labels:        app.kubernetes.io/component=server
               app.kubernetes.io/instance=kenbun-zk
               app.kubernetes.io/name=zookeeper
               app.kubernetes.io/role-group=default
Annotations:   <none>
Finalizers:    [kubernetes.io/pvc-protection]
Capacity:
Access Modes:
VolumeMode:    Filesystem
Used By:       kenbun-zk-server-default-0
Events:
  Type    Reason                Age               From                         Message
  ----    ------                ----              ----                         -------
  Normal  WaitForFirstConsumer  47s               persistentvolume-controller  waiting for first consumer to be created before binding
  Normal  WaitForPodScheduled   2s (x3 over 32s)  persistentvolume-controller  waiting for pod kenbun-zk-server-default-0 to be scheduled

and the zookeeper.yml:

apiVersion: zookeeper.stackable.tech/v1alpha1
kind: ZookeeperCluster
metadata:
  name: kenbun-zk
spec:
  version: 3.8.0-stackable0.8.0
  servers:
    roleGroups:
      default:
        replicas: 1

[sbernauer]

Thanks!
I just installed microk8s and will try to reproduce the problem

[sbernauer]

If you execute kubectl describe pvc kenbun-zk-server-default-0-quorum-tls-mount you can see the following error
Warning ProvisioningFailed 2m31s (x12 over 16m) secrets.stackable.tech_secret-operator-daemonset-7dhxg_a3ee55fc-9d45-416e-8f84-ee25bd8497f3 failed to provision volume with StorageClass "secrets.stackable.tech": error generating accessibility requirements: no available topology found
I will look further into this

[sbernauer]

We have been debugging so far and found out, that the problem should be somewhere with the microk8s setup.
The error originates in the external-provisioner container (which uses the k8s.gcr.io/sig-storage/csi-provisioner:v3.1.0 image).

kubectl logs secret-operator-daemonset-nf8l5 -c external-provisioner
W0111 11:49:07.416619       1 feature_gate.go:237] Setting GA feature gate Topology=true. It will be removed in a future release.
I0111 11:49:07.416668       1 csi-provisioner.go:139] Version: v3.1.0
I0111 11:49:07.416672       1 csi-provisioner.go:162] Building kube configs for running in cluster...
I0111 11:49:07.417316       1 common.go:111] Probing CSI driver for readiness
I0111 11:49:07.419659       1 csi-provisioner.go:278] CSI driver does not support PUBLISH_UNPUBLISH_VOLUME, not watching VolumeAttachments
I0111 11:49:07.520847       1 controller.go:811] Starting provisioner controller secrets.stackable.tech_secret-operator-daemonset-nf8l5_9e705c8f-b965-4d4c-8001-fea6a49650e0!
I0111 11:49:07.520912       1 volume_store.go:97] Starting save volume queue
I0111 11:49:07.622484       1 controller.go:860] Started provisioner controller secrets.stackable.tech_secret-operator-daemonset-nf8l5_9e705c8f-b965-4d4c-8001-fea6a49650e0!
I0111 11:49:25.064153       1 controller.go:1337] provision "default/kenbun-zk-server-default-0-client-tls-mount" class "secrets.stackable.tech": started
W0111 11:49:25.064203       1 topology.go:320] No topology keys found on any node
W0111 11:49:25.064222       1 controller.go:934] Retrying syncing claim "d7e5f4f1-562d-4450-b6ca-80ef9f4dfbb4", failure 0
E0111 11:49:25.064242       1 controller.go:957] error syncing claim "d7e5f4f1-562d-4450-b6ca-80ef9f4dfbb4": failed to provision volume with StorageClass "secrets.stackable.tech": error generating accessibility requirements: no available topology found
I0111 11:49:25.064619       1 event.go:285] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"kenbun-zk-server-default-0-client-tls-mount", UID:"d7e5f4f1-562d-4450-b6ca-80ef9f4dfbb4", APIVersion:"v1", ResourceVersion:"11311", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "default/kenbun-zk-server-default-0-client-tls-mount"
I0111 11:49:25.064634       1 event.go:285] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"kenbun-zk-server-default-0-client-tls-mount", UID:"d7e5f4f1-562d-4450-b6ca-80ef9f4dfbb4", APIVersion:"v1", ResourceVersion:"11311", FieldPath:""}): type: 'Warning' reason: 'ProvisioningFailed' failed to provision volume with StorageClass "secrets.stackable.tech": error generating accessibility requirements: no available topology found
I0111 11:49:25.066979       1 controller.go:1337] provision "default/kenbun-zk-server-default-0-quorum-tls-mount" class "secrets.stackable.tech": started
W0111 11:49:25.067009       1 topology.go:320] No topology keys found on any node

[sbernauer]

The code throwing the error also indicates

We may reach here if the driver has not registered on any nodes.
We should wait for at least one driver to start so that we can
provision in a supported topology.

If we inspect the cluster using

kubectl get csinodes.storage.k8s.io 
NAME        DRIVERS   AGE
sbernauer   0         57m

we can see no node loaded the csidriver secrets.stackable.tech.

Having a look at e.g. my local kind cluster it looks as follows

kubectl get csinodes.storage.k8s.io 
NAME                                    DRIVERS   AGE
stackable-data-platform-control-plane   0         3m5s
stackable-data-platform-worker          1         2m41s
stackable-data-platform-worker2         1         2m41s
stackable-data-platform-worker3         1         2m41s

So i think the root cause is that the csidriver was not loaded on the sbernauer node

[sbernauer]

Looking further there is a container called node-driver-registrar which is responsible to register the driver on the node.
On a kind cluster it looks like

k logs secret-operator-daemonset-vrwpr -c node-driver-registrar
I0111 11:57:03.265890       1 main.go:166] Version: v2.4.0
I0111 11:57:03.265915       1 main.go:167] Running node-driver-registrar in mode=registration
I0111 11:57:03.267166       1 node_register.go:53] Starting Registration Server at: /registration/secrets.stackable.tech-reg.sock
I0111 11:57:03.267241       1 node_register.go:62] Registration Server started at: /registration/secrets.stackable.tech-reg.sock
I0111 11:57:03.267337       1 node_register.go:92] Skipping HTTP server because endpoint is set to: ""
I0111 11:57:03.850660       1 main.go:102] Received GetInfo call: &InfoRequest{}
I0111 11:57:03.851082       1 main.go:109] "Kubelet registration probe created" path="/var/lib/kubelet/plugins/secrets.stackable.tech/registration"
I0111 11:57:03.858456       1 main.go:120] Received NotifyRegistrationStatus call: &RegistrationStatus{PluginRegistered:true,Error:,}

On microk8s however it stops after

k logs secret-operator-daemonset-nf8l5 -c node-driver-registrar
I0111 11:49:07.445397       1 main.go:166] Version: v2.4.0
I0111 11:49:07.445416       1 main.go:167] Running node-driver-registrar in mode=registration
I0111 11:49:07.446581       1 node_register.go:53] Starting Registration Server at: /registration/secrets.stackable.tech-reg.sock
I0111 11:49:07.446682       1 node_register.go:62] Registration Server started at: /registration/secrets.stackable.tech-reg.sock
I0111 11:49:07.446724       1 node_register.go:92] Skipping HTTP server because endpoint is set to: ""

So somehow the registration was not successful.

[sbernauer]

Somehow the node-driver-registrar was not called by the kubelet, hence the Received GetInfo call: &InfoRequest{} is missing. Looking at the kubelet logs we see

Jan 11 13:37:08 sbernauer microk8s.daemon-kubelite[91652]: W0111 13:37:08.102403   91652 logging.go:59] [core] [Channel #711 SubChannel #712] grpc: addrConn.createTransport failed to connect to {
Jan 11 13:37:08 sbernauer microk8s.daemon-kubelite[91652]:   "Addr": "/var/snap/microk8s/common/var/lib/kubelet/plugins_registry/secrets.stackable.tech-reg.sock/secrets.stackable.tech-reg.sock",
Jan 11 13:37:08 sbernauer microk8s.daemon-kubelite[91652]:   "ServerName": "/var/snap/microk8s/common/var/lib/kubelet/plugins_registry/secrets.stackable.tech-reg.sock/secrets.stackable.tech-reg.sock",
Jan 11 13:37:08 sbernauer microk8s.daemon-kubelite[91652]:   "Attributes": null,
Jan 11 13:37:08 sbernauer microk8s.daemon-kubelite[91652]:   "BalancerAttributes": null,
Jan 11 13:37:08 sbernauer microk8s.daemon-kubelite[91652]:   "Type": 0,
Jan 11 13:37:08 sbernauer microk8s.daemon-kubelite[91652]:   "Metadata": null
Jan 11 13:37:08 sbernauer microk8s.daemon-kubelite[91652]: }. Err: connection error: desc = "transport: Error while dialing dial unix /var/snap/microk8s/common/var/lib/kubelet/plugins_registry/secrets.stackable.tech-reg.sock/secrets.stackable.tech-reg.sock: connect: invalid argument"
Jan 11 13:37:09 sbernauer microk8s.daemon-kubelite[91652]: W0111 13:37:09.102915   91652 logging.go:59] [core] [Channel #711 SubChannel #712] grpc: addrConn.createTransport failed to connect to {

ls -la /var/snap/microk8s/common/var/lib/kubelet/plugins_registry/secrets.stackable.tech-reg.sock/secrets.stackable.tech-reg.sock
srwx------ 1 root root 0 Jan 11 13:15 /var/snap/microk8s/common/var/lib/kubelet/plugins_registry/secrets.stackable.tech-reg.sock/secrets.stackable.tech-reg.sock

[lfrancke]

Hi @sheng-kenbun,
thanks for the report, as you can see, we were able to replicate this locally.
Our Secret Operator expert is out until February so it'll take a bit before we will take a look at this

[sheng-kenbun]

Hello @lfrancke, thank you for the response! There is no hurry for us. Take your time!
Happy weekend.

[nightkr]

Looks like this is indeed a secret-operator bug, so I'm moving it to there.