Windows-Containers icon indicating copy to clipboard operation
Windows-Containers copied to clipboard
verified publisher icon microsoft

Requesting any debugging handler stopped working in Kubernetes 1.27 and containerd 1.7.14 (error: You must be logged in to the server (the server has asked for the client to provide credentials ( pods/log some pod))

Open doctorpangloss opened this issue 1 year ago • 11 comments

Describe the bug kubectl logs some-pod on pods created after an upgrade from 1.26 to 1.27.14 and from containerd 1.7.0 to 1.7.17 fail with

error: You must be logged in to the server (the server has asked for the client to provide credentials ( pods/log some pod)

I have permission to do this:

$ kubectl -v 8 auth can-i get pods/comfyui-backend-0 --subresource=logs --namespace=appmana
I0618 22:24:57.794173   25188 loader.go:395] Config loaded from file:  C:/.../kubeconfig.yaml
I0618 22:24:57.812177   25188 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1
I0618 22:24:57.812177   25188 round_trippers.go:469] Request Headers:
I0618 22:24:57.813174   25188 round_trippers.go:473]     Accept: application/json, */*
I0618 22:24:57.813174   25188 round_trippers.go:473]     User-Agent: kubectl.exe/v1.28.2 (windows/amd64) kubernetes/89a4ea3
I0618 22:24:57.825175   25188 round_trippers.go:574] Response Status: 200 OK in 12 milliseconds
I0618 22:24:57.825175   25188 round_trippers.go:577] Response Headers:
I0618 22:24:57.825175   25188 round_trippers.go:580]     Date: Wed, 19 Jun 2024 05:24:57 GMT
I0618 22:24:57.825175   25188 round_trippers.go:580]     Audit-Id: e310da1c-2ec7-4ae8-9299-522062632321
I0618 22:24:57.825175   25188 round_trippers.go:580]     Cache-Control: no-cache, private
I0618 22:24:57.825175   25188 round_trippers.go:580]     Content-Type: application/json
I0618 22:24:57.826176   25188 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 545e31b4-1e93-452e-b5ff-9f8e0e7d5d0e
I0618 22:24:57.826176   25188 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: eb6e015d-344b-4b22-863f-3e5868c6662b
I0618 22:24:57.826176   25188 request.go:1212] Response Body: {"kind":"APIResourceList","groupVersion":"v1","resources":[{"name":"bindings","singularName":"binding","namespaced":true,"kind":"Binding","verbs":["create"]},{"name":"componentstatuses","singularName":"componentstatus","namespaced":false,"kind":"ComponentStatus","verbs":["get","list"],"shortNames":["cs"]},{"name":"configmaps","singularName":"configmap","namespaced":true,"kind":"ConfigMap","verbs":["create","delete","deletecollection","get","list","patch","update","watch"],"shortNames":["cm"],"storageVersionHash":"qFsyl6wFWjQ="},{"name":"endpoints","singularName":"endpoints","namespaced":true,"kind":"Endpoints","verbs":["create","delete","deletecollection","get","list","patch","update","watch"],"shortNames":["ep"],"storageVersionHash":"fWeeMqaN/OA="},{"name":"events","singularName":"event","namespaced":true,"kind":"Event","verbs":["create","delete","deletecollection","get","list","patch","update","watch"],"shortNames":["ev"],"storageVersionHash":"r2yiGXH7wu8="},{"name":"limitranges","singularName":"limitrange" [truncated 5359 chars]
I0618 22:24:57.826176   25188 request.go:1212] Request Body: {"kind":"SelfSubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null},"spec":{"resourceAttributes":{"namespace":"appmana","verb":"get","resource":"pods","subresource":"logs","name":"comfyui-backend-0"}},"status":{"allowed":false}}
I0618 22:24:57.827175   25188 round_trippers.go:463] POST https://10.2.0.19:6443/apis/authorization.k8s.io/v1/selfsubjectaccessreviews
I0618 22:24:57.827175   25188 round_trippers.go:469] Request Headers:
I0618 22:24:57.827175   25188 round_trippers.go:473]     User-Agent: kubectl.exe/v1.28.2 (windows/amd64) kubernetes/89a4ea3
I0618 22:24:57.827175   25188 round_trippers.go:473]     Content-Type: application/json
I0618 22:24:57.827175   25188 round_trippers.go:473]     Accept: application/json, */*
I0618 22:24:57.828176   25188 round_trippers.go:574] Response Status: 201 Created in 1 milliseconds
I0618 22:24:57.828176   25188 round_trippers.go:577] Response Headers:
I0618 22:24:57.828176   25188 round_trippers.go:580]     Content-Length: 561
I0618 22:24:57.828176   25188 round_trippers.go:580]     Date: Wed, 19 Jun 2024 05:24:57 GMT
I0618 22:24:57.828176   25188 round_trippers.go:580]     Audit-Id: 36a03371-92b2-480f-8131-a638f5d90f1a
I0618 22:24:57.828176   25188 round_trippers.go:580]     Cache-Control: no-cache, private
I0618 22:24:57.828176   25188 round_trippers.go:580]     Content-Type: application/json
I0618 22:24:57.828176   25188 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 545e31b4-1e93-452e-b5ff-9f8e0e7d5d0e
I0618 22:24:57.828176   25188 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: eb6e015d-344b-4b22-863f-3e5868c6662b
I0618 22:24:57.828176   25188 request.go:1212] Response Body: {"kind":"SelfSubjectAccessReview","apiVersion":"authorization.k8s.io/v1","metadata":{"creationTimestamp":null,"managedFields":[{"manager":"kubectl.exe","operation":"Update","apiVersion":"authorization.k8s.io/v1","time":"2024-06-19T05:24:57Z","fieldsType":"FieldsV1","fieldsV1":{"f:spec":{"f:resourceAttributes":{".":{},"f:name":{},"f:namespace":{},"f:resource":{},"f:subresource":{},"f:verb":{}}}}}]},"spec":{"resourceAttributes":{"namespace":"appmana","verb":"get","resource":"pods","subresource":"logs","name":"comfyui-backend-0"}},"status":{"allowed":true}}

$ kubectl -v 8 logs comfyui-backend-0
I0618 22:17:19.298593   22640 loader.go:395] Config loaded from file:  C:/.../kubeconfig.yaml
I0618 22:17:19.315590   22640 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-0
I0618 22:17:19.315590   22640 round_trippers.go:469] Request Headers:
I0618 22:17:19.315590   22640 round_trippers.go:473]     Accept: application/json, */*
I0618 22:17:19.315590   22640 round_trippers.go:473]     User-Agent: kubectl.exe/v1.28.2 (windows/amd64) kubernetes/89a4ea3
I0618 22:17:19.323588   22640 round_trippers.go:574] Response Status: 200 OK in 7 milliseconds
I0618 22:17:19.323588   22640 round_trippers.go:577] Response Headers:
I0618 22:17:19.323588   22640 round_trippers.go:580]     Audit-Id: 329d2007-e17b-4756-a570-ab078077133f
I0618 22:17:19.323588   22640 round_trippers.go:580]     Cache-Control: no-cache, private
I0618 22:17:19.323588   22640 round_trippers.go:580]     Content-Type: application/json
I0618 22:17:19.323588   22640 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 545e31b4-1e93-452e-b5ff-9f8e0e7d5d0e
I0618 22:17:19.323588   22640 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: eb6e015d-344b-4b22-863f-3e5868c6662b
I0618 22:17:19.323588   22640 round_trippers.go:580]     Date: Wed, 19 Jun 2024 05:17:19 GMT
I0618 22:17:19.324241   22640 request.go:1212] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"comfyui-backend-0","generateName":"comfyui-backend-","namespace":"appmana","uid":"b1f04544-a4a8-484b-8c76-35bbaff0f52b","resourceVersion":"1137858590","creationTimestamp":"2024-05-30T01:51:32Z","labels":{"app":"comfyui-backend-statefulset","controller-revision-hash":"comfyui-backend-75b567789c","statefulset.kubernetes.io/pod-name":"comfyui-backend-0"},"annotations":{"cni.projectcalico.org/containerID":"d9b79796a3c84308d2d3c59f34320928c32656d90dc1e768bfa6c48a912f617e","cni.projectcalico.org/podIP":"10.3.16.14/32","cni.projectcalico.org/podIPs":"10.3.16.14/32"},"ownerReferences":[{"apiVersion":"apps/v1","kind":"StatefulSet","name":"comfyui-backend","uid":"cb7340a5-f27d-4916-ba09-1095b9b3090b","controller":true,"blockOwnerDeletion":true}],"managedFields":[{"manager":"kube-controller-manager","operation":"Update","apiVersion":"v1","time":"2024-05-30T01:51:32Z","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:generateName":{},"f:labels":{".":{},"f:app":{},"f: [truncated 12176 chars]
Defaulted container "comfyui" out of: comfyui, robocopy-periodic, robocopy-first (init)
I0618 22:17:19.326225   22640 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-0/log?container=comfyui
I0618 22:17:19.326225   22640 round_trippers.go:469] Request Headers:
I0618 22:17:19.326225   22640 round_trippers.go:473]     Accept: application/json, */*
I0618 22:17:19.326225   22640 round_trippers.go:473]     User-Agent: kubectl.exe/v1.28.2 (windows/amd64) kubernetes/89a4ea3
I0618 22:17:19.331224   22640 round_trippers.go:574] Response Status: 401 Unauthorized in 4 milliseconds
I0618 22:17:19.331224   22640 round_trippers.go:577] Response Headers:
I0618 22:17:19.332225   22640 round_trippers.go:580]     Audit-Id: b2597ebf-e451-4a68-a794-c97654a06332
I0618 22:17:19.332225   22640 round_trippers.go:580]     Cache-Control: no-cache, private
I0618 22:17:19.332225   22640 round_trippers.go:580]     Content-Type: application/json
I0618 22:17:19.332225   22640 round_trippers.go:580]     Content-Length: 262
I0618 22:17:19.332225   22640 round_trippers.go:580]     Date: Wed, 19 Jun 2024 05:17:19 GMT
I0618 22:17:19.332225   22640 request.go:1212] Response Body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"the server has asked for the client to provide credentials ( pods/log comfyui-backend-0)","reason":"Unauthorized","details":{"name":"comfyui-backend-0","kind":"pods/log"},"code":401}
I0618 22:17:19.333224   22640 helpers.go:246] server response object: [{
  "metadata": {},
  "status": "Failure",
  "message": "the server has asked for the client to provide credentials ( pods/log comfyui-backend-0)",
  "reason": "Unauthorized",
  "details": {
    "name": "comfyui-backend-0",
    "kind": "pods/log"
  },
  "code": 401
}]
error: You must be logged in to the server (the server has asked for the client to provide credentials ( pods/log comfyui-backend-0))

Compare to a healthy request:

$ kubectl -v 8 get pods comfyui-backend-0
I0618 22:19:23.887144   29636 loader.go:395] Config loaded from file:  C:/.../kubeconfig.yaml
I0618 22:19:23.914118   29636 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-0
I0618 22:19:23.914118   29636 round_trippers.go:469] Request Headers:
I0618 22:19:23.914118   29636 round_trippers.go:473]     Accept: application/json;as=Table;v=v1;g=meta.k8s.io,application/json;as=Table;v=v1beta1;g=meta.k8s.io,application/json
I0618 22:19:23.914118   29636 round_trippers.go:473]     User-Agent: kubectl.exe/v1.28.2 (windows/amd64) kubernetes/89a4ea3
I0618 22:19:23.922228   29636 round_trippers.go:574] Response Status: 200 OK in 7 milliseconds
I0618 22:19:23.922228   29636 round_trippers.go:577] Response Headers:
I0618 22:19:23.922228   29636 round_trippers.go:580]     Audit-Id: 40bc9bd7-1fff-4777-86ca-a3842d375bdc
I0618 22:19:23.922228   29636 round_trippers.go:580]     Cache-Control: no-cache, private
I0618 22:19:23.922228   29636 round_trippers.go:580]     Content-Type: application/json
I0618 22:19:23.922228   29636 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 545e31b4-1e93-452e-b5ff-9f8e0e7d5d0e
I0618 22:19:23.922228   29636 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: eb6e015d-344b-4b22-863f-3e5868c6662b
I0618 22:19:23.922228   29636 round_trippers.go:580]     Date: Wed, 19 Jun 2024 05:19:23 GMT
I0618 22:19:23.922228   29636 request.go:1212] Response Body: {"kind":"Table","apiVersion":"meta.k8s.io/v1","metadata":{"resourceVersion":"1137858590"},"columnDefinitions":[{"name":"Name","type":"string","format":"name","description":"Name must be unique within a namespace. Is required when creating resources, although some resources may allow a client to request the generation of an appropriate name automatically. Name is primarily intended for creation idempotence and configuration definition. Cannot be updated. More info: https://kubernetes.io/docs/concepts/overview/working-with-objects/names#names","priority":0},{"name":"Ready","type":"string","format":"","description":"The aggregate readiness state of this pod for accepting traffic.","priority":0},{"name":"Status","type":"string","format":"","description":"The aggregate status of the containers in this pod.","priority":0},{"name":"Restarts","type":"string","format":"","description":"The number of times the containers in this pod have been restarted and when the last container in this pod has restarted.","priority": [truncated 7812 chars]

Sometimes this error occurs on Windows pods that are healthy and running. It always occurs on non-Running Windows pods.

To Reproduce (Investigating)

Expected behavior I should be able to access pod logs on 1.27 like I was able to do on 1.26.

Configuration:

System Info:
  Machine ID:                                AppMana-009
  System UUID:                               Dxxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxA
  Boot ID:                                   55
  Kernel Version:                            10.0.20348.1726
  OS Image:                                  Windows Server 2022 Datacenter
  Operating System:                          windows
  Architecture:                              amd64
  Container Runtime Version:                 containerd://1.7.17
  Kubelet Version:                           v1.27.14
  Kube-Proxy Version:                        v1.27.14

Additional context 1.26 worked fine. Your help in diagnosing the issue could reveal an important regression.

doctorpangloss avatar Jun 19 '24 05:06 doctorpangloss

exec is broken too. What happened with subresources?

doctorpangloss avatar Jun 19 '24 18:06 doctorpangloss

It might be helpful to isolate if something in kubernetes or containerd broke, does kubernets 1.26 with containerd 1.7.17? Does 1.27 work with containerd 1.7.0?

jsturtevant avatar Jun 20 '24 17:06 jsturtevant

We collect logs during e2e tests (not with kubectl but with the api directly) and that seems to be working: https://gcsweb.k8s.io/gcs/kubernetes-jenkins/logs/ci-kubernetes-e2e-capz-windows-1-27/1803517549418123264/artifacts/container-lifecycle-hook-8282/pod-handle-http-request/container-handle-https-request/.

We have containerd containerd://1.7.10 on that kuberetes 1.27 e2e test runs

jsturtevant avatar Jun 20 '24 17:06 jsturtevant

This looks like the containerd version isn't really at play:

I0618 22:17:19.326225   22640 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-0/log?container=comfyui
I0618 22:17:19.326225   22640 round_trippers.go:469] Request Headers:
I0618 22:17:19.326225   22640 round_trippers.go:473]     Accept: application/json, */*
I0618 22:17:19.326225   22640 round_trippers.go:473]     User-Agent: kubectl.exe/v1.28.2 (windows/amd64) kubernetes/89a4ea3
I0618 22:17:19.331224   22640 round_trippers.go:574] Response Status: 401 Unauthorized in 4 milliseconds

jsturtevant avatar Jun 20 '24 17:06 jsturtevant

could you look up the API server logs at that same time?

jsturtevant avatar Jun 20 '24 17:06 jsturtevant

I've updated our sig-windows jobs to use containerd containerd://1.7.18 on https://testgrid.k8s.io/sig-windows-1.27-release#capz-windows-containerd-1.27 and we are not seeing any issues with gathering logs.

I found an issue https://github.com/kubernetes/kubernetes/issues/39767 which looks similar to the report here. Is it possible some certs got corrupted during upgrade?

jsturtevant avatar Jul 02 '24 19:07 jsturtevant

Let's investigate the certificate corruption issue.

  1. Get the logs with verbosity
$ kubectl -v 8 logs comfyui-backend-4 robocopy-first
I0708 14:58:02.948618    8364 loader.go:373] Config loaded from file:  C:/Users/bberman/Documents/appmana/appmana-cluster/src/bootstrap/appmana-cluster-03/kubeconfig.yaml
I0708 14:58:02.961251    8364 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-4
I0708 14:58:02.961251    8364 round_trippers.go:469] Request Headers:
I0708 14:58:02.961788    8364 round_trippers.go:473]     Accept: application/json, */*
I0708 14:58:02.961788    8364 round_trippers.go:473]     User-Agent: kubectl.exe/v1.27.1 (windows/amd64) kubernetes/4c94112
I0708 14:58:02.975462    8364 round_trippers.go:574] Response Status: 200 OK in 13 milliseconds
I0708 14:58:02.975462    8364 round_trippers.go:577] Response Headers:
I0708 14:58:02.975462    8364 round_trippers.go:580]     Content-Type: application/json
I0708 14:58:02.975462    8364 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 545e31b4-1e93-452e-b5ff-9f8e0e7d5d0e
I0708 14:58:02.975462    8364 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: eb6e015d-344b-4b22-863f-3e5868c6662b
I0708 14:58:02.975462    8364 round_trippers.go:580]     Date: Mon, 08 Jul 2024 21:58:02 GMT
I0708 14:58:02.975462    8364 round_trippers.go:580]     Audit-Id: ad59a6e3-5a21-4b24-a9a2-24e59e0661f2
I0708 14:58:02.975462    8364 round_trippers.go:580]     Cache-Control: no-cache, private
I0708 14:58:02.975999    8364 request.go:1188] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"comfyui-backend-4","generateName":"comfyui-backend-","namespace":"appmana","uid":"19d57878-cac1-4d14-b019-196f53baa5a0","resourceVersion":"1206943901","creationTimestamp":"2024-07-08T21:24:52Z","labels":{"app":"comfyui-backend-statefulset","controller-revision-hash":"comfyui-backend-676ddb7d9d","statefulset.kubernetes.io/pod-name":"comfyui-backend-4"},"annotations":{"cni.projectcalico.org/containerID":"f2bb37e2996b77bd562ced418f3d0f8a2a31e385961851eb43af2e6238a7d603","cni.projectcalico.org/podIP":"10.3.48.199/32","cni.projectcalico.org/podIPs":"10.3.48.199/32"},"ownerReferences":[{"apiVersion":"apps/v1","kind":"StatefulSet","name":"comfyui-backend","uid":"cb7340a5-f27d-4916-ba09-1095b9b3090b","controller":true,"blockOwnerDeletion":true}],"managedFields":[{"manager":"kube-controller-manager","operation":"Update","apiVersion":"v1","time":"2024-07-08T21:24:52Z","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:generateName":{},"f:labels":{".":{},"f:app":{}," [truncated 12414 chars]
I0708 14:58:02.978122    8364 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-4/log?container=robocopy-first
I0708 14:58:02.978122    8364 round_trippers.go:469] Request Headers:
I0708 14:58:02.978122    8364 round_trippers.go:473]     Accept: application/json, */*
I0708 14:58:02.978122    8364 round_trippers.go:473]     User-Agent: kubectl.exe/v1.27.1 (windows/amd64) kubernetes/4c94112
I0708 14:58:03.050736    8364 round_trippers.go:574] Response Status: 401 Unauthorized in 72 milliseconds
I0708 14:58:03.050736    8364 round_trippers.go:577] Response Headers:
I0708 14:58:03.050736    8364 round_trippers.go:580]     Audit-Id: cccf22ec-ca11-49b6-bf92-9407b55bcfe6
I0708 14:58:03.050736    8364 round_trippers.go:580]     Cache-Control: no-cache, private
I0708 14:58:03.050736    8364 round_trippers.go:580]     Content-Type: application/json
I0708 14:58:03.050736    8364 round_trippers.go:580]     Content-Length: 262
I0708 14:58:03.050736    8364 round_trippers.go:580]     Date: Mon, 08 Jul 2024 21:58:03 GMT
I0708 14:58:03.051283    8364 request.go:1188] Response Body: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"the server has asked for the client to provide credentials ( pods/log comfyui-backend-4)","reason":"Unauthorized","details":{"name":"comfyui-backend-4","kind":"pods/log"},"code":401}
I0708 14:58:03.051817    8364 helpers.go:246] server response object: [{
  "metadata": {},
  "status": "Failure",
  "message": "the server has asked for the client to provide credentials ( pods/log comfyui-backend-4)",
  "reason": "Unauthorized",
  "details": {
    "name": "comfyui-backend-4",
    "kind": "pods/log"
  },
  "code": 401
}]
error: You must be logged in to the server (the server has asked for the client to provide credentials ( pods/log comfyui-backend-4))

Does this occur with any other requests? No, only pod subresources:

Getting pods works:

 $ kubectl -v 8 get pods comfyui-backend-4
I0708 15:00:30.511774   30480 loader.go:373] Config loaded from file:  C:/Users/bberman/Documents/appmana/appmana-cluster/src/bootstrap/appmana-cluster-03/kubeconfig.yaml
I0708 15:00:30.526774   30480 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-4
I0708 15:00:30.526774   30480 round_trippers.go:469] Request Headers:
I0708 15:00:30.526774   30480 round_trippers.go:473]     Accept: application/json;as=Table;v=v1;g=meta.k8s.io,application/json;as=Table;v=v1beta1;g=meta.k8s.io,application/json
I0708 15:00:30.527300   30480 round_trippers.go:473]     User-Agent: kubectl.exe/v1.27.1 (windows/amd64) kubernetes/4c94112
I0708 15:00:30.535440   30480 round_trippers.go:574] Response Status: 200 OK in 8 milliseconds
I0708 15:00:30.535986   30480 round_trippers.go:577] Response Headers:
I0708 15:00:30.535986   30480 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: eb6e015d-344b-4b22-863f-3e5868c6662b
I0708 15:00:30.535986   30480 round_trippers.go:580]     Date: Mon, 08 Jul 2024 22:00:30 GMT
I0708 15:00:30.535986   30480 round_trippers.go:580]     Audit-Id: a2acda26-1f39-4d73-8a0c-adc7c5b1afbd
I0708 15:00:30.535986   30480 round_trippers.go:580]     Cache-Control: no-cache, private
I0708 15:00:30.535986   30480 round_trippers.go:580]     Content-Type: application/json
I0708 15:00:30.535986   30480 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 545e31b4-1e93-452e-b5ff-9f8e0e7d5d0e
I0708 15:00:30.536529   30480 request.go:1188] Response Body: {"kind":"Table","apiVersion":"meta.k8s.io/v1","metadata":{"resourceVersion":"1206943901"},"columnDefinitions":[{"name":"Name","type":"string","format":"name","description":"Name must be unique within a namespace. Is required when creating resources, although some resources may allow a client to request the generation of an appropriate name automatically. Name is primarily intended for creation idempotence and configuration definition. Cannot be updated. More info: https://kubernetes.io/docs/concepts/overview/working-with-objects/names#names","priority":0},{"name":"Ready","type":"string","format":"","description":"The aggregate readiness state of this pod for accepting traffic.","priority":0},{"name":"Status","type":"string","format":"","description":"The aggregate status of the containers in this pod.","priority":0},{"name":"Restarts","type":"string","format":"","description":"The number of times the containers in this pod have been restarted and when the last container in this pod has restarted.","priority": [truncated 8098 chars]
NAME                READY   STATUS     RESTARTS   AGE
comfyui-backend-4   0/2     Init:0/1   0          35m

Execing into this pod doesn't work:

$ kubectl -v 8 exec -it comfyui-backend-4 robocopy-first -- /Windows/sh.exe
I0708 15:01:18.762691   27980 loader.go:373] Config loaded from file:  C:/Users/bberman/Documents/appmana/appmana-cluster/src/bootstrap/appmana-cluster-03/kubeconfig.yaml
I0708 15:01:18.778415   27980 round_trippers.go:463] GET https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-4
I0708 15:01:18.778415   27980 round_trippers.go:469] Request Headers:
I0708 15:01:18.778415   27980 round_trippers.go:473]     Accept: application/json, */*
I0708 15:01:18.778415   27980 round_trippers.go:473]     User-Agent: kubectl.exe/v1.27.1 (windows/amd64) kubernetes/4c94112
I0708 15:01:18.788720   27980 round_trippers.go:574] Response Status: 200 OK in 10 milliseconds
I0708 15:01:18.788720   27980 round_trippers.go:577] Response Headers:
I0708 15:01:18.788720   27980 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: eb6e015d-344b-4b22-863f-3e5868c6662b
I0708 15:01:18.788720   27980 round_trippers.go:580]     Date: Mon, 08 Jul 2024 22:01:18 GMT
I0708 15:01:18.788720   27980 round_trippers.go:580]     Audit-Id: 511ff915-1ac4-4e8d-baff-5d3b1a4a6295
I0708 15:01:18.788720   27980 round_trippers.go:580]     Cache-Control: no-cache, private
I0708 15:01:18.788720   27980 round_trippers.go:580]     Content-Type: application/json
I0708 15:01:18.788720   27980 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 545e31b4-1e93-452e-b5ff-9f8e0e7d5d0e
I0708 15:01:18.789272   27980 request.go:1188] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"comfyui-backend-4","generateName":"comfyui-backend-","namespace":"appmana","uid":"19d57878-cac1-4d14-b019-196f53baa5a0","resourceVersion":"1206943901","creationTimestamp":"2024-07-08T21:24:52Z","labels":{"app":"comfyui-backend-statefulset","controller-revision-hash":"comfyui-backend-676ddb7d9d","statefulset.kubernetes.io/pod-name":"comfyui-backend-4"},"annotations":{"cni.projectcalico.org/containerID":"f2bb37e2996b77bd562ced418f3d0f8a2a31e385961851eb43af2e6238a7d603","cni.projectcalico.org/podIP":"10.3.48.199/32","cni.projectcalico.org/podIPs":"10.3.48.199/32"},"ownerReferences":[{"apiVersion":"apps/v1","kind":"StatefulSet","name":"comfyui-backend","uid":"cb7340a5-f27d-4916-ba09-1095b9b3090b","controller":true,"blockOwnerDeletion":true}],"managedFields":[{"manager":"kube-controller-manager","operation":"Update","apiVersion":"v1","time":"2024-07-08T21:24:52Z","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:generateName":{},"f:labels":{".":{},"f:app":{}," [truncated 12414 chars]
Defaulted container "comfyui" out of: comfyui, robocopy-periodic, robocopy-first (init)
I0708 15:01:18.793035   27980 podcmd.go:88] Defaulting container name to comfyui
I0708 15:01:18.794107   27980 round_trippers.go:463] POST https://10.2.0.19:6443/api/v1/namespaces/appmana/pods/comfyui-backend-4/exec?command=%2FWindows%2Fsh.exe&container=comfyui&stdin=true&stdout=true&tty=true
I0708 15:01:18.794107   27980 round_trippers.go:469] Request Headers:
I0708 15:01:18.794107   27980 round_trippers.go:473]     X-Stream-Protocol-Version: v4.channel.k8s.io
I0708 15:01:18.794107   27980 round_trippers.go:473]     X-Stream-Protocol-Version: v3.channel.k8s.io
I0708 15:01:18.794107   27980 round_trippers.go:473]     X-Stream-Protocol-Version: v2.channel.k8s.io
I0708 15:01:18.794621   27980 round_trippers.go:473]     X-Stream-Protocol-Version: channel.k8s.io
I0708 15:01:18.794646   27980 round_trippers.go:473]     User-Agent: kubectl.exe/v1.27.1 (windows/amd64) kubernetes/4c94112
I0708 15:01:18.808443   27980 round_trippers.go:574] Response Status: 401 Unauthorized in 13 milliseconds
I0708 15:01:18.808443   27980 round_trippers.go:577] Response Headers:
I0708 15:01:18.808443   27980 round_trippers.go:580]     Date: Mon, 08 Jul 2024 22:01:18 GMT
I0708 15:01:18.808443   27980 round_trippers.go:580]     Content-Length: 12
I0708 15:01:18.808443   27980 round_trippers.go:580]     Content-Type: text/plain; charset=utf-8
error: unable to upgrade connection: Unauthorized

Does using the controller's admin credentials work? No:

# k0s kubectl -n appmana -v 8 exec -it comfyui-backend-4 robocopy-first -- /Windows/sh.exe
I0708 22:02:18.434256  346087 loader.go:373] Config loaded from file:  /var/lib/k0s/pki/admin.conf
...
# k0s kubectl -n appmana -v 8 exec -it comfyui-backend-4 robocopy-first -- /Windows/sh.exe
I0708 22:03:18.497821  347580 loader.go:373] Config loaded from file:  /var/lib/k0s/pki/admin.conf
I0708 22:03:18.505659  347580 round_trippers.go:463] GET https://localhost:6443/api/v1/namespaces/appmana/pods/comfyui-backend-4
I0708 22:03:18.505671  347580 round_trippers.go:469] Request Headers:
I0708 22:03:18.505679  347580 round_trippers.go:473]     User-Agent: k0s/v0.0.0 (linux/amd64) kubernetes/$Format
I0708 22:03:18.505685  347580 round_trippers.go:473]     Accept: application/json, */*
I0708 22:03:18.517392  347580 round_trippers.go:574] Response Status: 200 OK in 11 milliseconds
I0708 22:03:18.517406  347580 round_trippers.go:577] Response Headers:
I0708 22:03:18.517416  347580 round_trippers.go:580]     Audit-Id: 419e1590-1ba9-4fb6-8aa5-5bdae1bfecc1
I0708 22:03:18.517427  347580 round_trippers.go:580]     Cache-Control: no-cache, private
I0708 22:03:18.517436  347580 round_trippers.go:580]     Content-Type: application/json
I0708 22:03:18.517445  347580 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 545e31b4-1e93-452e-b5ff-9f8e0e7d5d0e
I0708 22:03:18.517456  347580 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: eb6e015d-344b-4b22-863f-3e5868c6662b
I0708 22:03:18.517466  347580 round_trippers.go:580]     Date: Mon, 08 Jul 2024 22:03:18 GMT
I0708 22:03:18.517615  347580 request.go:1188] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"comfyui-backend-4","generateName":"comfyui-backend-","namespace":"appmana","uid":"19d57878-cac1-4d14-b019-196f53baa5a0","resourceVersion":"1206943901","creationTimestamp":"2024-07-08T21:24:52Z","labels":{"app":"comfyui-backend-statefulset","controller-revision-hash":"comfyui-backend-676ddb7d9d","statefulset.kubernetes.io/pod-name":"comfyui-backend-4"},"annotations":{"cni.projectcalico.org/containerID":"f2bb37e2996b77bd562ced418f3d0f8a2a31e385961851eb43af2e6238a7d603","cni.projectcalico.org/podIP":"10.3.48.199/32","cni.projectcalico.org/podIPs":"10.3.48.199/32"},"ownerReferences":[{"apiVersion":"apps/v1","kind":"StatefulSet","name":"comfyui-backend","uid":"cb7340a5-f27d-4916-ba09-1095b9b3090b","controller":true,"blockOwnerDeletion":true}],"managedFields":[{"manager":"kube-controller-manager","operation":"Update","apiVersion":"v1","time":"2024-07-08T21:24:52Z","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:generateName":{},"f:labels":{".":{},"f:app":{}," [truncated 12414 chars]
Defaulted container "comfyui" out of: comfyui, robocopy-periodic, robocopy-first (init)
I0708 22:03:18.519149  347580 podcmd.go:88] Defaulting container name to comfyui
I0708 22:03:18.519617  347580 round_trippers.go:463] POST https://localhost:6443/api/v1/namespaces/appmana/pods/comfyui-backend-4/exec?command=%2FWindows%2Fsh.exe&container=comfyui&stdin=true&stdout=true&tty=true
I0708 22:03:18.519628  347580 round_trippers.go:469] Request Headers:
I0708 22:03:18.519635  347580 round_trippers.go:473]     X-Stream-Protocol-Version: v4.channel.k8s.io
I0708 22:03:18.519641  347580 round_trippers.go:473]     X-Stream-Protocol-Version: v3.channel.k8s.io
I0708 22:03:18.519662  347580 round_trippers.go:473]     X-Stream-Protocol-Version: v2.channel.k8s.io
I0708 22:03:18.519668  347580 round_trippers.go:473]     X-Stream-Protocol-Version: channel.k8s.io
I0708 22:03:18.519674  347580 round_trippers.go:473]     User-Agent: k0s/v0.0.0 (linux/amd64) kubernetes/$Format
I0708 22:03:18.530220  347580 round_trippers.go:574] Response Status: 401 Unauthorized in 10 milliseconds
I0708 22:03:18.530230  347580 round_trippers.go:577] Response Headers:
I0708 22:03:18.530236  347580 round_trippers.go:580]     Content-Length: 12
I0708 22:03:18.530243  347580 round_trippers.go:580]     Content-Type: text/plain; charset=utf-8
I0708 22:03:18.530249  347580 round_trippers.go:580]     Date: Mon, 08 Jul 2024 22:03:18 GMT
error: unable to upgrade connection: Unauthorized

Are the certs valid on the controller?: Yes

root@appmana-010:~# openssl x509 -in /var/lib/k0s/pki/server.crt -text -noout
Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number:
            37:...
        Signature Algorithm: sha256WithRSAEncryption
        Issuer: CN = kubernetes-ca
        Validity
            Not Before: Jul  3 17:00:00 2024 GMT
            Not After : Jul  3 17:00:00 2025 GMT
        Subject: O = kubernetes, CN = kubernetes
        Subject Public Key Info:
            Public Key Algorithm: rsaEncryption
                Public-Key: (2048 bit)
                Modulus:
                    00:...
                Exponent: 6...
        X509v3 extensions:
            X509v3 Key Usage: critical
                Digital Signature, Key Encipherment
            X509v3 Extended Key Usage:
                TLS Web Server Authentication, TLS Web Client Authentication
            X509v3 Basic Constraints: critical
                CA:FALSE
            X509v3 Subject Key Identifier:
                13:..
            X509v3 Authority Key Identifier:
                07:...
            X509v3 Subject Alternative Name:
                DNS:kubernetes, DNS:kubernetes.default, DNS:kubernetes.default.svc, DNS:kubernetes.default.svc.cluster, DNS:kubernetes.svc.cluster.local, DNS:localhost, DNS:appmana-010, DNS:appmana-010.i.appmana.com, DNS:appmana-011, DNS:appmana-011.i.appmana.com, DNS:appmana-012, DNS:appmana-012.i.appmana.com, IP Address:127.0.0.1, IP Address:127.0.1.1, IP Address:10.2.0.19, IP Address:FE80:..., IP Address:FE80:..., IP Address:10.152.184.1, IP Address:10.2.0.20, IP Address:10.2.0.22, IP Address:10.152.184.99
    Signature Algorithm: sha256WithRSAEncryption
    Signature Value:
        26:...
root@appmana-010:~# openssl x509 -in /var/lib/k0s/pki/ca.crt -text -noout
Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number:
            2b...
        Signature Algorithm: sha256WithRSAEncryption
        Issuer: CN = kubernetes-ca
        Validity
            Not Before: Mar  9 23:38:00 2023 GMT
            Not After : Mar  6 23:38:00 2033 GMT
        Subject: CN = kubernetes-ca
        Subject Public Key Info:
            Public Key Algorithm: rsaEncryption
                Public-Key: (2048 bit)
                Modulus:
                    00:...
                Exponent: 65537 (0x10001)
        X509v3 extensions:
            X509v3 Key Usage: critical
                Certificate Sign, CRL Sign
            X509v3 Basic Constraints: critical
                CA:TRUE
            X509v3 Subject Key Identifier:
                07:...
    Signature Algorithm: sha256WithRSAEncryption
    Signature Value:
        ...

Are the client certs valid? Yes:

# openssl x509 -text -noout -in ./client.pem
Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number:
            62:...
        Signature Algorithm: sha256WithRSAEncryption
        Issuer: CN = kubernetes-ca
        Validity
            Not Before: Jul  3 16:18:00 2024 GMT
            Not After : Jul  3 16:18:00 2025 GMT
        Subject: O = system:masters, CN = kubernetes-admin
        Subject Public Key Info:
            Public Key Algorithm: rsaEncryption
                Public-Key: (2048 bit)
                Modulus:
                    00:...
                Exponent: ...
        X509v3 extensions:
            X509v3 Key Usage: critical
                Digital Signature, Key Encipherment
            X509v3 Extended Key Usage:
                TLS Web Server Authentication, TLS Web Client Authentication
            X509v3 Basic Constraints: critical
                CA:FALSE
            X509v3 Subject Key Identifier:
                D7:...
            X509v3 Authority Key Identifier:
                07:...
    Signature Algorithm: sha256WithRSAEncryption
    Signature Value:
        12:...

Does this client cert verify with the server ca.crt? Yes:

# openssl verify -CAfile /var/lib/k0s/pki/ca.crt ./client.pem
./client.pem: OK

I think this bug is real, but I really need to understand what requesting a subresource actually does.

doctorpangloss avatar Jul 08 '24 22:07 doctorpangloss

could you look up the API server logs at that same time?

nothing notable appeared, same exact error that is reported to the client

doctorpangloss avatar Jul 08 '24 22:07 doctorpangloss

Further investigating shows that all debugging handlers are returning unauthorized, although they are indeed configured to be running (enableDebuggingHandlers is true in the config and it is responsive on the worker kubelet). Why might the Windows auth filter for this be broken?

doctorpangloss avatar Jul 10 '24 22:07 doctorpangloss

@doctorpangloss Hey, we've got an internal team investigating this issue.

From my understanding, we need a certificate to communicate between the controller (control loop for state of cluster) and Kubernetes API server. If that certificate isn't valid or expired, we can't run commands like exec or query info on sub-resources. However, both your Server and CA Certificates are valid and not expired.

Does this sound accurate to you?

ntrappe-msft avatar Jul 31 '24 18:07 ntrappe-msft

Does this sound accurate to you?

Yes. The certificates might be interacting with the issue, but not in an obvious way. This is more likely a real bug in kubelet starting with 1.27 related to upgrading nodes in place, which doesn't really happen in clouds.

doctorpangloss avatar Jul 31 '24 18:07 doctorpangloss

This issue has been open for 30 days with no updates. no assignees, please provide an update or close this issue.

microsoft-github-policy-service[bot] avatar Sep 02 '24 09:09 microsoft-github-policy-service[bot]

@doctorpangloss , is this still an issue on your side? We have yet to be able to reproduce it. Hence want to checkin with you if you are seeing the same issue on other clusters or is this only for a specific setup?

msft-linliu avatar Sep 03 '24 21:09 msft-linliu

I have managed to solve the issue.

  • The KubeletConfiguration needs more fields between 1.26 and 1.27 when using conforming clusters:
authentication:
  anonymous: {}
  webhook:
    cacheTTL: 0s
  x509:
    clientCAFile: C:/var/lib/kubelet/pki/ca.crt
authorization:
  webhook:
    cacheAuthorizedTTL: 0s
    cacheUnauthorizedTTL: 0s
  • writing the server certificate using Windows PowerShell puts the UTF-8 BOM into the certificate file, which borks kubelet

thanks for looking into this

doctorpangloss avatar Sep 08 '24 21:09 doctorpangloss