Repository: kubernetes/kubernetes (language: go)

Issue:
Kubelet serving CSR never created
### What happened?

We are seeing an issue occasionally where the kubelet never gets the server certificate (`serverTLSBootstrap: true`).
We have an auto-approver for the server certificates and detect this issue because we are waiting for the certificate to appear in `/var/lib/kubelet/pki/kubelet-server-current.pem`. When we hit it, not even the CSR is created.
It started happening after upgrading to v1.32 so we believe it could be from a change that was introduced in v1.32.
Restarting the kubelet does not help. It happily continues without the server certificate, even though it is configured to bootstrap it.

In healthy clusters, we see this:

```console
$ kubectl get csr
NAME        AGE   SIGNERNAME                                    REQUESTOR                           REQUESTEDDURATION   CONDITION
csr-8dql4   29s   kubernetes.io/kubelet-serving                 system:node:lennart-kubelet-debug   <none>              Pending
csr-r8ztr   17s   kubernetes.io/kubelet-serving                 system:node:lennart-kubelet-debug   <none>              Pending
csr-xtwpf   30s   kubernetes.io/kube-apiserver-client-kubelet   system:node:lennart-kubelet-debug   <none>              Approved,Issued
```

In faulty clusters, there is just the client CSR.
~~We are not sure why two CSRs are created for the server either, but it works when we approve the newer of them.~~

Edit: The two server CSRs happen because kubeadm restarts the kubelet as part of initializing. This is how it picks up the client certificate. After the restart, the kubelet does not "remember" its old server CSR so it creates a new. This is not an issue.

Here is the kubelet config from an affected node: [kubelet-config.txt](https://github.com/user-attachments/files/18688742/kubelet-config.txt)

### What did you expect to happen?

When configured, the kubelet should always create the server CSR.

### How can we reproduce it (as minimally and precisely as possible)?

Unfortunately we do not have any guaranteed reproduction steps.
In general, this is what is needed to trigger the issue:

1. Kubelet is configured to rotate certificates (default) and to use server certificate.
2. Node status is stable, i.e. there are no changes of any kind that would cause the kubelet to update the status.
3. Kubelet is restarted and the server certificate does not exist (e.g. because it was removed or it wasn't issued yet).

In this specific case you should be able to see that the CSR is not created:

```console
$ kubectl get csr
NAME        AGE   SIGNERNAME                                    REQUESTOR                           REQUESTEDDURATION   CONDITION
csr-2mq8h   22s   kubernetes.io/kube-apiserver-client-kubelet   system:node:lennart-kubelet-debug   <none>              Approved,Issued
$ kubectl get nodes
NAME                    STATUS   ROLES           AGE   VERSION
lennart-kubelet-debug   Ready    control-plane   28s   v1.32.1
```

### Anything else we need to know?

I believe the culprit is https://github.com/kubernetes/kubernetes/pull/128640. Not the randomization of the interval, but the change in how the [zero case for the lastStatusReportTime](https://github.com/kubernetes/kubernetes/pull/128640/files#diff-f39bb531745e5658a65143c9054c3fa92aa3ac9f41e9e627ac61b7ff08808153R607) is handled.
It used to be treated as expired and trigger an update. After the PR it is treated the opposite.
This means that `patchNodeStatus` is never called and consequently neither is `setLastObservedNodeAddresses`.
The latter is initializing the kubelets internal node address state (not node status).
This internal state is what the server certificate manager is relying on to create the CSR. As long as it is `nil`, i.e. as long as the node status hasn't been patched, it cannot progress.

### Kubernetes version

<details>

```console
$ kubectl version
Client Version: v1.32.1
Kustomize Version: v5.5.0
Server Version: v1.32.1
```

</details>


### Cloud provider

<details>
Happens both with and without external cloud provider
</details>


### OS version

<details>

```console
# On Linux:
$ cat /etc/os-release
# paste output here
$ uname -a
# paste output here
```

</details>


### Install tools

<details>

</details>


### Container runtime (CRI) and version (if applicable)

<details>

</details>


### Related plugins (CNI, CSI, ...) and versions (if applicable)

<details>

</details>



Discussion / hints:
@lentzi90 check if this is the problem https://github.com/kubernetes/kubernetes/pull/125813

naive question, what is the reason to have a node without valid IPs?
Thanks for the comment! I was looking at that PR already but it does not seem to be the issue we are hitting. We see this even when the node has a proper internal IP.
It does, however, explain why the attempt at reproducing it with the IPv6 loopback works.
looks like this https://github.com/kubernetes/kubernetes/pull/126441, you can try disabling the feature gate
Hmm that does indeed look interesting! I will check if there is something wrong with the node names
/sig auth
Alright, I managed to hit the scenario described in https://github.com/kubernetes/kubernetes/pull/126441, but unfortunately it does not behave the same as the issue we are seeing.
What I did to trigger it was the following:

1. Set `--hostname-override=not-correct-hostname` in `/etc/default/kubelet`
2. Do NOT set `nodeRegistration.name` in the `InitConfiguration` (that would cause kubeadm to try to set the hostname override)
3. kubeadm init now fails and indeed no CSRs are created.

```
[kubelet-start] Starting the kubelet
[wait-control-plane] Waiting for the kubelet to boot up the control plane as static Pods from directory "/etc/kubernetes/manifests"
[kubelet-check] Waiting for a healthy kubelet at http://127.0.0.1:10248/healthz. This can take up to 4m0s
[kubelet-check] The kubelet is healthy after 501.78975ms
[api-check] Waiting for a healthy API server. This can take up to 4m0s
[api-check] The API server is healthy after 3.001123109s
[upload-config] Storing the configuration used in ConfigMap "kubeadm-config" in the "kube-system" Namespace
[kubelet] Creating a ConfigMap "kubelet-config" in namespace kube-system with the configuration for the kubelets in the cluster
error execution phase upload-config/kubelet: error writing CRISocket for this node: nodes "lennart-kubelet-debug" not found
```

When we hit the issue described, kubeadm init is actually successful and the client CSR is created. So unfortunately it does not seem to be https://github.com/kubernetes/kubernetes/pull/126441 that is the cause. The hunt continues... 
This is reproducible maybe 5-10% of the cluster creations, so I don't think it is about wrong configuration or feature gates. 

Minimal test environments seem never produce this same issue, the only reproductions we've found are when something goes wrong 100% of the time (like using the link-local ipv6 address. That  breaking the node's addresses shouldn't happen either IMO, but maybe let's discuss that in another issue.)

Checking the changelog, most of the Kubelet and CSR related changes were done in 1.31 already, where no issues have been seen. That'd further exclude #126441 and #125813 IMO, but thanks @lentzi90 for verifying that with a test too.

Kubelet is not logging basically anything on any log level related to server certs is also making it hard to debug. The whole DynamicCertificateManager code is silent, and kubelet itself is also very silent on the very few lines it has related to certs. For client certs it at least says something, but server cert path is so silent.

One further finding related to CSRs are that in k8s 1.32, the second server CSR request comes 15 seconds later than the first. In 1.31 and older, they were only few seconds apart. This also happens on minimal kubeadm init based test env. I've also not found a reason why this is happening and if its somehow related or not.

It would also be interesting to understand why there is always 2 server CSRs and why the first one never means anything. The contents are basically the same, same requestor, same CSR input, ...
/triage accepted
We've now added some logging to the kubelet, and I managed to reproduce a VM that displays behavior. I did try this on few other VMs as well, where it does not reproduce it. So it is still elusive why it is this random. But this one node seems to reproduce it consistently. Why it started happening, it is also a open question. I've been doing this same test on this one node all week....

As minimal kubeadm config as possible.

```yaml
apiVersion: kubeadm.k8s.io/v1beta4
kind: InitConfiguration
nodeRegistration:
  kubeletExtraArgs:
  - name: cert-dir
    value: "/var/lib/kubelet/pki"
  - name: node-ip
    value: "10.1.0.109"
  - name: hostname-override
    value: "tuomo-ubuntu2"
---
apiVersion: kubeadm.k8s.io/v1beta4
kind: ClusterConfiguration
apiServer:
  certSANs:
  - "10.1.0.109"
---
kind: KubeletConfiguration
apiVersion: kubelet.config.k8s.io/v1beta1
serverTLSBootstrap: true
rotateCertificates: true
logging:
  verbosity: 2
```

and with additional logging added:

```text
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.071670 1844189 server.go:607] "[===DEBUG===] KubeletServer validated"
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.071860 1844189 server.go:647] "[===DEBUG===] Standalone Mode" standaloneMode=false
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.071880 1844189 server.go:673] "[===DEBUG===] Host and node names" hostName="tuomo-ubuntu2" nodeName="tuomo-ubuntu2"
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.071904 1844189 server.go:684] "[===DEBUG===] Setting up API clients"
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.075795 1844189 server.go:725] "[===DEBUG===] Setting up Auth"
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.076655 1844189 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] Generated CSR
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.077971 1844189 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] Got ClientSet for CSR, sending to API
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.081733 1844189 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] Got error from CSR: %!w(*errors.errorString=&{cannot create certificate signing request: Post "https://10.1.0.109:6443/apis/certificates.k8s.io/v1/certificatesigningrequests": dial tcp 10.1.0.109:6443: connect: connection refused})
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.087445 1844189 server.go:737] "[===DEBUG===] PreInitRuntimeService completed"
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.102987 1844189 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Dynamic template exists
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.103084 1844189 kubelet.go:1730] "[===DEBUG===] Modules initialized"
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.103129 1844189 kubelet.go:1769] "[===DEBUG===] Container runtime up"
Feb 13 09:38:03 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:03.103325 1844189 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 09:38:04 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:04.103543 1844189 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 09:38:05 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:05.103715 1844189 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 09:38:05 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:05.252548 1844189 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] Generated CSR
Feb 13 09:38:05 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:05.252938 1844189 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] Got ClientSet for CSR, sending to API
Feb 13 09:38:05 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:05.461340 1844189 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] CSR submitted successfully, now waiting for approval
Feb 13 09:38:06 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:06.104715 1844189 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] CSR template differs
Feb 13 09:38:06 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:06.105853 1844189 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Generated CSR
Feb 13 09:38:06 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:06.105875 1844189 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Got ClientSet for CSR, sending to API
Feb 13 09:38:06 tuomo-ubuntu2 kubelet[1844189]: I0213 09:38:06.120403 1844189 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] CSR submitted successfully, now waiting for approval
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.841937 1844606 server.go:607] "[===DEBUG===] KubeletServer validated"
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.842165 1844606 server.go:647] "[===DEBUG===] Standalone Mode" standaloneMode=false
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.842188 1844606 server.go:673] "[===DEBUG===] Host and node names" hostName="tuomo-ubuntu2" nodeName="tuomo-ubuntu2"
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.842213 1844606 server.go:684] "[===DEBUG===] Setting up API clients"
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.845377 1844606 server.go:725] "[===DEBUG===] Setting up Auth"
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.855724 1844606 server.go:737] "[===DEBUG===] PreInitRuntimeService completed"
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.879648 1844606 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Dynamic template exists
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.879683 1844606 kubelet.go:1730] "[===DEBUG===] Modules initialized"
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.879726 1844606 kubelet.go:1769] "[===DEBUG===] Container runtime up"
Feb 13 09:38:08 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:08.880821 1844606 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 09:38:09 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:09.882835 1844606 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 09:38:10 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:10.883548 1844606 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 09:38:11 tuomo-ubuntu2 kubelet[1844606]: I0213 09:38:11.884824 1844606 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
...snip....
```

and it is forever stuck in the `No certificate template available`.

Interestingly, this also shows the "double CSR needed" behavior: there is one CSR, but it did not result in serving certificate but it is trying to create another CSR.

```text
$ kubectl get csr -A
NAME        AGE   SIGNERNAME                                    REQUESTOR                   REQUESTEDDURATION   CONDITION
csr-9hshq   13m   kubernetes.io/kube-apiserver-client-kubelet   system:node:tuomo-ubuntu2   <none>              Approved,Issued
csr-xjzw5   13m   kubernetes.io/kubelet-serving                 system:node:tuomo-ubuntu2   <none>              Approved,Issued
```

Restarting kubelet does not help.

```text
Feb 13 10:16:17 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:17.987883 1867525 server.go:607] "[===DEBUG===] KubeletServer validated"
Feb 13 10:16:17 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:17.988164 1867525 server.go:647] "[===DEBUG===] Standalone Mode" standaloneMode=false
Feb 13 10:16:17 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:17.988203 1867525 server.go:673] "[===DEBUG===] Host and node names" hostName="tuomo-ubuntu2" nodeName="tuomo-ubuntu2"
Feb 13 10:16:17 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:17.988239 1867525 server.go:684] "[===DEBUG===] Setting up API clients"
Feb 13 10:16:17 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:17.991965 1867525 server.go:725] "[===DEBUG===] Setting up Auth"
Feb 13 10:16:18 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:18.007475 1867525 server.go:737] "[===DEBUG===] PreInitRuntimeService completed"
Feb 13 10:16:18 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:18.028994 1867525 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Dynamic template exists
Feb 13 10:16:18 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:18.029142 1867525 kubelet.go:1730] "[===DEBUG===] Modules initialized"
Feb 13 10:16:18 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:18.029458 1867525 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 10:16:18 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:18.030558 1867525 kubelet.go:1769] "[===DEBUG===] Container runtime up"
Feb 13 10:16:19 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:19.030267 1867525 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 10:16:20 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:20.030924 1867525 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
Feb 13 10:16:21 tuomo-ubuntu2 kubelet[1867525]: I0213 10:16:21.031193 1867525 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] No certificate template available
...snip...
```

It just immediately goes into waiting the template.

Question is, why is the certificate template not available, and why does it yet say: `Dynamic template exists` just couple lines above? Does it try to look up some information on the node for the template, which it cannot obtain, and is stuck?
To explain the extra logs, we have pushed the changes here: https://github.com/kubernetes/kubernetes/compare/release-1.32...Nordix:kubernetes:lentzi90/kubelet-logging-release-1.32?expand=1
I have been trying to figure out why there are two CSRs for the server certificate. This is what I have come up with. Does it make sense?

1. During bootstrap it creates one CSR for each.
2. When the client CSR is approved it proceeds to do a restart. I guess this is a normal part of the bootstrap process
3. After the restart, the kubelet no longer has knowledge of the server CSR and it does not seem to recognize it. In the code there is some check for already existing CSRs but that seems to rely on in-memory state, which would be lost on restart
4. A new CSR is created which the kubelet knows about...

I guess there could be situations when the server CSR is fast enough to be both created and approved before the restart also, but if there is any kind of delay we always "lose" the first
> * When the client CSR is approved it proceeds to do a restart. I guess this is a normal part of the bootstrap process

process restart? is kubelet exiting?
The systemd unit is restarted. Kubeadm I guess?

```console
$ grep -E "systemd\[1\]|===DEBUG===" kubelet-stopped-debug.log                                                                              
Feb 17 06:45:47 lennart-kubelet-debug systemd[1]: Started kubelet.service - kubelet: The Kubernetes Node Agent.
...
Feb 17 06:45:49 lennart-kubelet-debug kubelet[1879873]: I0217 06:45:49.574045 1879873 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] Generated 
CSR                                                                                                                                                                                    Feb 17 06:45:49 lennart-kubelet-debug kubelet[1879873]: I0217 06:45:49.574217 1879873 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] Got Client
Set for CSR, sending to API                                                                                                                                                            Feb 17 06:45:49 lennart-kubelet-debug kubelet[1879873]: I0217 06:45:49.909533 1879873 certificate_manager.go:356] kubernetes.io/kube-apiserver-client-kubelet: [===DEBUG===] CSR submit
ted successfully, now waiting for approval                                                                                                                                             
Feb 17 06:45:50 lennart-kubelet-debug kubelet[1879873]: I0217 06:45:50.450845 1879873 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] CSR template differs
Feb 17 06:45:50 lennart-kubelet-debug kubelet[1879873]: I0217 06:45:50.451119 1879873 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Generated CSR           Feb 17 06:45:50 lennart-kubelet-debug kubelet[1879873]: I0217 06:45:50.451129 1879873 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Got ClientSet for CSR, s
ending to API                                                                                                                                                                          Feb 17 06:45:50 lennart-kubelet-debug kubelet[1879873]: I0217 06:45:50.454899 1879873 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] CSR submitted successful
ly, now waiting for approval                                                                                                                                                           
Feb 17 06:45:52 lennart-kubelet-debug systemd[1]: Stopping kubelet.service - kubelet: The Kubernetes Node Agent...
Feb 17 06:45:52 lennart-kubelet-debug systemd[1]: kubelet.service: Deactivated successfully.
Feb 17 06:45:52 lennart-kubelet-debug systemd[1]: Stopped kubelet.service - kubelet: The Kubernetes Node Agent.
Feb 17 06:45:52 lennart-kubelet-debug systemd[1]: Started kubelet.service - kubelet: The Kubernetes Node Agent.
Feb 17 06:45:52 lennart-kubelet-debug kubelet[1880356]: I0217 06:45:52.089063 1880356 server.go:607] "[===DEBUG===] KubeletServer validated"
Feb 17 06:45:52 lennart-kubelet-debug kubelet[1880356]: I0217 06:45:52.089164 1880356 server.go:647] "[===DEBUG===] Standalone Mode" standaloneMode=false
Feb 17 06:45:52 lennart-kubelet-debug kubelet[1880356]: I0217 06:45:52.089184 1880356 server.go:673] "[===DEBUG===] Host and node names" hostName="lennart-kubelet-debug" nodeName="len
nart-kubelet-debug"
Feb 17 06:45:52 lennart-kubelet-debug kubelet[1880356]: I0217 06:45:52.089217 1880356 server.go:684] "[===DEBUG===] Setting up API clients"
Feb 17 06:45:52 lennart-kubelet-debug kubelet[1880356]: I0217 06:45:52.090839 1880356 server.go:725] "[===DEBUG===] Setting up Auth"
...
Feb 17 06:46:03 lennart-kubelet-debug kubelet[1880356]: I0217 06:46:03.115339 1880356 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Generated CSR
Feb 17 06:46:03 lennart-kubelet-debug kubelet[1880356]: I0217 06:46:03.115346 1880356 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Got ClientSet for CSR, sending to API
Feb 17 06:46:03 lennart-kubelet-debug kubelet[1880356]: I0217 06:46:03.118428 1880356 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] CSR submitted successfully, now waiting for approval
Feb 17 06:46:21 lennart-kubelet-debug kubelet[1880356]: I0217 06:46:21.378491 1880356 certificate_manager.go:356] kubernetes.io/kubelet-serving: [===DEBUG===] Updating cert on disk
Feb 17 06:46:29 lennart-kubelet-debug systemd[1]: Stopping kubelet.service - kubelet: The Kubernetes Node Agent...
Feb 17 06:46:29 lennart-kubelet-debug systemd[1]: kubelet.service: Deactivated successfully.
Feb 17 06:46:29 lennart-kubelet-debug systemd[1]: Stopped kubelet.service - kubelet: The Kubernetes Node Agent.
Feb 17 06:46:29 lennart-kubelet-debug systemd[1]: kubelet.service: Consumed 1.251s CPU time.
```

In this run I started with kubelet stopped and did the following:
1. kubeadm init and wait
2. approve the (second) kubelet serving CSR
3. kubeadm reset

The final `Stopping kubelet.service` comes from kubeadm reset.
So is a kubeadm process thing? 
Yes, I found the code in kubeadm now that does this: https://github.com/kubernetes/kubernetes/blob/2b3da7dfc846fec7c4044a320f8f38b4a45367a3/cmd/kubeadm/app/cmd/phases/init/kubeletfinalize.go#L146
I wonder if there could be some very particular order of events that could cause issues here. As far as I understand we have at least three things happening in parallel here:

1. kubeadm going through the init process, which ends with a kubelet restart during [kubelet-finalize] before the [addons] phase
2. kubelet client certificate rotation happening in the background
3. kubelet server certificate rotation happening in the background

The happy/normal case seems to be that the CSRs are created, kubelet registers the node and kubeadm restarts the kubelet. Then another CSR is created for the server certificate, because the first one was "forgotten" and most likely didn't get approved in time for the restart.
What I don't know is what would happen if the order is different, and is it even possible for them to be different? Perhaps kubeadm is waiting on something that always happens after the client CSR? Is it possible that kubeadm restarts the kubelet during a sensitive step that could somehow make it permanently stuck?

tagging kubeadm maintainers that are better positioned to answer these questions @neolit123 @fabriziopandini 
> When we hit it, not even the CSR is created.
> It started happening after upgrading to v1.32 so we believe it could be from a change that was introduced in v1.32.

kubeadm has no recent changes related to the kubelet-finalize phase (minus [this](https://github.com/kubernetes/kubernetes/commit/6e17cc7f0eaa4718951129e75d615abedebba65e)). that phase requires the kubelet restart to truly enable kubelet client cert rotation.

> What I don't know is what would happen if the order is different, and is it even possible for them to be different? Perhaps kubeadm is waiting on something that always happens after the client CSR? Is it possible that kubeadm restarts the kubelet during a sensitive step that could somehow make it permanently stuck?

kubeadm does the following on join:
- writes a bootstrap-kubelet.conf
- starts the kubelet with client cert rotation enabled (default from config)
- waits for the kubelet to write a kubelet.conf file (that means csr was sent and tls bootstrap completed)

on init:
- writes directly a kubelet.conf
- starts the kubelet with client cert rotation enabled by default (from config)
- waits for the control plane to start up
- mutates the kubelet.conf to point to the client certs on disk and restarts the kubelet (kubelet-finalize phase)

if the kubelet knows about the requirement for server cert rotation (from config) but it never creates the csr due to restarts, that seems like a kubelet bug.
 
I think I figured it out! In https://github.com/kubernetes/kubernetes/pull/128640, the [isUpdateStatusPeriodExperid](https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L605-L608C3) was introduced with these lines:

```go
	if kl.lastStatusReportTime.IsZero() {
		return false
	}
```

Doesn't that mean that the period is not expired ever, until we have the first status report? That makes [tryUpdateNodeStatus](https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L559) return early:
https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L584-L586

Why is that a problem if the Node status didn't change? Well, it means that we never call patchNodeStatus, so we never initialize the last observed node address:
https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L663-L670

This means that we can never create the CSR, because we do not know what addresses to use!

Usually this is not an issue, because there are many changes to the node when starting up the first time. However, when the kubelet is restarted later, e.g. as part of cert-rotation, there are no changes that makes it update the status.

To summarize, I think we should change `isUpdateStatusPeriodExperid` to return `true` always if `kl.lastStatusReportTime.IsZero()` to make sure that things are initialized.
> To summarize, I think we should change `isUpdateStatusPeriodExperid` to return `true` always if `kl.lastStatusReportTime.IsZero()` to make sure that things are initialized.

@lentzi90 before we didn't update the node if it didn't change

https://github.com/kubernetes/kubernetes/blame/3184eb3d1b2b07b3b68eff5240eb8a8e20bb0d07/pkg/kubelet/kubelet_node_status.go#L484-L488

```
	node, changed := kl.updateNode(ctx, originalNode)

	if !changed {
		// We don't do markVolumesFromNode(node) here and leave it to the regular syncNodeStatus().
		return false
	}
```

so that logic looks correct, if there was no update and the node didn't change, we don't update.

I think we need to understand what is the heuristic to detect the node change

EDIT

ups, wrong, place , there are two loops that update the node `fastNodeStatusUpdate` and `tryUpdateNodeStatus`, you are changing the later, taking a look now 👀 
Adding for reference how the server CSR is created:
1. [NewServerCertificateManager called from NewMainKubelet](https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet.go#L841) with [getLastObservedNodeAddresses](https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L752) as `getAddresses` func
2. [getTemplate](https://github.com/kubernetes/kubernetes/blob/931ad2a9fdedaf1e47126f5b3e5880eb3708bfb2/pkg/kubelet/certificate/kubelet.go#L123) function constructed from `getAddresses` and [returns nil](https://github.com/kubernetes/kubernetes/blob/931ad2a9fdedaf1e47126f5b3e5880eb3708bfb2/pkg/kubelet/certificate/kubelet.go#L60) when no addresses can be found.
3. The certificate manager [returns early](https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/staging/src/k8s.io/client-go/util/certificate/certificate_manager.go#L429-L430) if `getTemplate` returns `nil` and the CSR is never created.

All of this is based on the `getLastObservedNodeAddresses` returning `nil`, which it does until [setLastObservedNodeAddresses](https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L747-L750) has been called. It is only called from [patchNodeStatus](https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L670), which in turn only happens when the node changed or is considered expired:
https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L584-L598. 
I can see it is also called from [fastNodeStatusUpdate here](https://github.com/kubernetes/kubernetes/blob/ad4d9b2f5119f2bcf742239018a397d3794cb6e0/pkg/kubelet/kubelet_node_status.go#L503). Need to look through that code also.
Ok looks like the `fastNodeStatusUpdate` was always returning early if no change needed to be reported. I think that means we were relying on the `tryUpdateNodeStatus` previous behavior where it determined it like this:

```go
shouldPatchNodeStatus := changed || kl.clock.Since(kl.lastStatusReportTime) >= kl.nodeStatusReportFrequency
```
> were relying on the `tryUpdateNodeStatus` previous behavior where it determined it like this:

I see, and `kl.clock.Since(kl.lastStatusReportTime)` was `now - zero` , that is why it got triggered
@lentzi90 either way it seems odd that we rely on a blind update for this, I get a bit lost on the latest development, can you please clarify what is the node state that change and why we don't detect it, but once it updates the objects it is fixed?
That's the thing, there is no change.
We remove the old certificates, add a bootstrap config and restart the kubelet to force a certificate rotation. The Node did not change in any way, but due to the restart, `lastObservedNodeAddresses` will be `nil` until `setLastObservedNodeAddresses` is called. It seems that it is only ever called when we patch the node, and there is no reason to patch since there is no change.

There are probably other ways to make sure `lastObservedNodeAddresses` is set though. And strictly speaking we do not need to patch the Node, we just need to set the kubelet state.

One thing is still unclear to me. The client CSR somehow still gets created. I will try to figure out how that code path looks like. Maybe it is not relying on the same?
Ok the client CSR was simple. In that case we only [need the node name](https://github.com/kubernetes/kubernetes/blob/0b1ef24a9912d1cbbbfe5641bf9cd2cdc91f32bd/pkg/kubelet/certificate/kubelet.go#L231-L235) so there is no reason to get any addresses. 
**Summarizing my understanding**

Before https://github.com/kubernetes/kubernetes/pull/128640:
- `patchNodeStatus` was always called after `nodeStatusReportFrequency` even if there was no change

After https://github.com/kubernetes/kubernetes/pull/128640:
- `patchNodeStatus` will ONLY be called if `lastStatusReportTime` is != 0 and the period expired (or the node changed).
`lastStatusReportTime` is 0 initially, so as long as there is no update to the node it will never update its status.
That in itself is probably not an issue if the node didn't change. But it also means that `getLastObservedNodeAddresses` will return `nil` during all this time. That also means that during all this time the server CSR cannot be created.

What seems odd to me is that the zero time is handled separately. It was not before so why now? Shouldn't the kubelet update the status always with `nodeStatusReportFrequency`? After https://github.com/kubernetes/kubernetes/pull/128640, it does not do that until there is an actual change to it. Only after that does it respect the `nodeStatusReportFrequency`.
> After [#128640](https://github.com/kubernetes/kubernetes/pull/128640), it does not do that until there is an actual change to it. Only after that does it respect the `nodeStatusReportFrequency`.

yep, I think you are right, that looks wrong, it should start reporting periodically 

Fix patch:
diff --git a/pkg/kubelet/kubelet.go b/pkg/kubelet/kubelet.go
index 617b636d44bcd..2a1a3e4aa2ec7 100644
--- a/pkg/kubelet/kubelet.go
+++ b/pkg/kubelet/kubelet.go
@@ -1096,9 +1096,6 @@ type Kubelet struct {
 	rootDirectory    string
 	podLogsDirectory string
 
-	lastObservedNodeAddressesMux sync.RWMutex
-	lastObservedNodeAddresses    []v1.NodeAddress
-
 	// onRepeatedHeartbeatFailure is called when a heartbeat operation fails more than once. optional.
 	onRepeatedHeartbeatFailure func()
 
diff --git a/pkg/kubelet/kubelet_getters.go b/pkg/kubelet/kubelet_getters.go
index 491ce594dd329..2928673b6c36b 100644
--- a/pkg/kubelet/kubelet_getters.go
+++ b/pkg/kubelet/kubelet_getters.go
@@ -480,3 +480,13 @@ func (kl *Kubelet) setCachedMachineInfo(info *cadvisorapiv1.MachineInfo) {
 	defer kl.machineInfoLock.Unlock()
 	kl.machineInfo = info
 }
+
+// getLastStableNodeAddresses returns the last observed node addresses.
+func (kl *Kubelet) getLastObservedNodeAddresses() []v1.NodeAddress {
+	node, err := kl.GetNode()
+	if err != nil || node == nil {
+		klog.V(4).InfoS("fail to obtain node from local cache", "node", kl.nodeName, "error", err)
+		return nil
+	}
+	return node.Status.Addresses
+}
diff --git a/pkg/kubelet/kubelet_node_status.go b/pkg/kubelet/kubelet_node_status.go
index ebe36617f05b9..b712220c78bb6 100644
--- a/pkg/kubelet/kubelet_node_status.go
+++ b/pkg/kubelet/kubelet_node_status.go
@@ -644,7 +644,6 @@ func (kl *Kubelet) patchNodeStatus(originalNode, node *v1.Node) (*v1.Node, error
 		return nil, err
 	}
 	kl.lastStatusReportTime = kl.clock.Now()
-	kl.setLastObservedNodeAddresses(updatedNode.Status.Addresses)
 
 	readyIdx, readyCondition := nodeutil.GetNodeCondition(&updatedNode.Status, v1.NodeReady)
 	if readyIdx >= 0 && readyCondition.Status == v1.ConditionTrue {
@@ -721,17 +720,6 @@ func (kl *Kubelet) setNodeStatus(ctx context.Context, node *v1.Node) {
 	}
 }
 
-func (kl *Kubelet) setLastObservedNodeAddresses(addresses []v1.NodeAddress) {
-	kl.lastObservedNodeAddressesMux.Lock()
-	defer kl.lastObservedNodeAddressesMux.Unlock()
-	kl.lastObservedNodeAddresses = addresses
-}
-func (kl *Kubelet) getLastObservedNodeAddresses() []v1.NodeAddress {
-	kl.lastObservedNodeAddressesMux.RLock()
-	defer kl.lastObservedNodeAddressesMux.RUnlock()
-	return kl.lastObservedNodeAddresses
-}
-
 // defaultNodeStatusFuncs is a factory that generates the default set of
 // setNodeStatus funcs
 func (kl *Kubelet) defaultNodeStatusFuncs() []func(context.Context, *v1.Node) error {


Test patch:
diff --git a/pkg/kubelet/kubelet_getters_test.go b/pkg/kubelet/kubelet_getters_test.go
index b66bc23d2c673..dca460fadd6dc 100644
--- a/pkg/kubelet/kubelet_getters_test.go
+++ b/pkg/kubelet/kubelet_getters_test.go
@@ -21,6 +21,10 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	v1 "k8s.io/api/core/v1"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/types"
+	cloudproviderapi "k8s.io/cloud-provider/api"
 	kubecontainer "k8s.io/kubernetes/pkg/kubelet/container"
 )
 
@@ -132,3 +136,180 @@ func TestHandlerSupportsUserNamespaces(t *testing.T) {
 	assert.False(t, got)
 	assert.Error(t, err)
 }
+
+func Test_getLastObservedNodeAddresses(t *testing.T) {
+	testCases := []struct {
+		name                  string
+		nodeName              types.NodeName
+		node                  *v1.Node
+		externalCloudProvider bool
+		expectedAddrs         []v1.NodeAddress
+	}{
+		{
+			name:          "node not found",
+			nodeName:      "test-node",
+			node:          nil,
+			expectedAddrs: nil,
+		},
+		{
+			name:     "empty addresses",
+			nodeName: "test-node",
+			node: &v1.Node{
+				ObjectMeta: metav1.ObjectMeta{Name: "test-node"},
+				Status:     v1.NodeStatus{Addresses: []v1.NodeAddress{}},
+			},
+			expectedAddrs: nil,
+		},
+		{
+			name:     "no taints",
+			nodeName: "test-node",
+			node: &v1.Node{
+				ObjectMeta: metav1.ObjectMeta{Name: "test-node"},
+				Status: v1.NodeStatus{
+					Addresses: []v1.NodeAddress{
+						{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+						{Type: v1.NodeHostName, Address: "test-node"},
+					},
+				},
+			},
+			expectedAddrs: []v1.NodeAddress{
+				{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+				{Type: v1.NodeHostName, Address: "test-node"},
+			},
+		},
+		{
+			name:     "other taints",
+			nodeName: "test-node",
+			node: &v1.Node{
+				ObjectMeta: metav1.ObjectMeta{Name: "test-node"},
+				Spec: v1.NodeSpec{
+					Taints: []v1.Taint{
+						{Key: "other-taint", Effect: v1.TaintEffectNoSchedule},
+					},
+				},
+				Status: v1.NodeStatus{
+					Addresses: []v1.NodeAddress{
+						{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+						{Type: v1.NodeHostName, Address: "test-node"},
+					},
+				},
+			},
+			expectedAddrs: []v1.NodeAddress{
+				{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+				{Type: v1.NodeHostName, Address: "test-node"},
+			},
+		},
+		{
+			name:                  "external cloud provider no taints",
+			nodeName:              "test-node",
+			externalCloudProvider: true,
+			node: &v1.Node{
+				ObjectMeta: metav1.ObjectMeta{Name: "test-node"},
+				Status: v1.NodeStatus{
+					Addresses: []v1.NodeAddress{
+						{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+						{Type: v1.NodeHostName, Address: "test-node"},
+					},
+				},
+			},
+			expectedAddrs: []v1.NodeAddress{
+				{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+				{Type: v1.NodeHostName, Address: "test-node"},
+			},
+		},
+		{
+			name:                  "no external cloud provider with external cloud provider taint",
+			nodeName:              "test-node",
+			externalCloudProvider: false,
+			node: &v1.Node{
+				ObjectMeta: metav1.ObjectMeta{Name: "test-node"},
+				Spec: v1.NodeSpec{
+					Taints: []v1.Taint{
+						{Key: cloudproviderapi.TaintExternalCloudProvider, Effect: v1.TaintEffectNoSchedule},
+					},
+				},
+				Status: v1.NodeStatus{
+					Addresses: []v1.NodeAddress{
+						{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+						{Type: v1.NodeHostName, Address: "test-node"},
+					},
+				},
+			},
+			expectedAddrs: []v1.NodeAddress{
+				{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+				{Type: v1.NodeHostName, Address: "test-node"},
+			},
+		},
+		{
+			name:                  "external cloud provider taint",
+			nodeName:              "test-node",
+			externalCloudProvider: true,
+			node: &v1.Node{
+				ObjectMeta: metav1.ObjectMeta{Name: "test-node"},
+				Spec: v1.NodeSpec{
+					Taints: []v1.Taint{
+						{Key: cloudproviderapi.TaintExternalCloudProvider, Effect: v1.TaintEffectNoSchedule},
+					},
+				},
+				Status: v1.NodeStatus{
+					Addresses: []v1.NodeAddress{
+						{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+						{Type: v1.NodeHostName, Address: "test-node"},
+					},
+				},
+			},
+			expectedAddrs: []v1.NodeAddress{
+				{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+				{Type: v1.NodeHostName, Address: "test-node"},
+			}},
+		{
+			name:                  "external cloud provider other taint",
+			nodeName:              "test-node",
+			externalCloudProvider: true,
+			node: &v1.Node{
+				ObjectMeta: metav1.ObjectMeta{Name: "test-node"},
+				Spec: v1.NodeSpec{
+					Taints: []v1.Taint{
+						{Key: "other-taint", Effect: v1.TaintEffectNoSchedule},
+					},
+				},
+				Status: v1.NodeStatus{
+					Addresses: []v1.NodeAddress{
+						{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+						{Type: v1.NodeHostName, Address: "test-node"},
+					},
+				},
+			},
+			expectedAddrs: []v1.NodeAddress{
+				{Type: v1.NodeInternalIP, Address: "10.0.0.1"},
+				{Type: v1.NodeHostName, Address: "test-node"},
+			},
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			testKubelet := newTestKubelet(t, false /* controllerAttachDetachEnabled */)
+			defer testKubelet.Cleanup()
+			kl := testKubelet.kubelet
+			kl.nodeName = types.NodeName(tc.nodeName)
+			kl.externalCloudProvider = tc.externalCloudProvider
+			nodeLister := testNodeLister{}
+			if tc.node != nil {
+				nodeLister.nodes = append(nodeLister.nodes, tc.node)
+			}
+			kl.nodeLister = nodeLister
+			addrs := kl.getLastObservedNodeAddresses()
+
+			if len(addrs) != len(tc.expectedAddrs) {
+				t.Errorf("expected %d addresses, got %d", len(tc.expectedAddrs), len(addrs))
+			} else {
+				for i := range addrs {
+					if addrs[i] != tc.expectedAddrs[i] {
+						t.Errorf("expected address %v, got %v", tc.expectedAddrs[i], addrs[i])
+					}
+				}
+			}
+		})
+	}
+}