kubectl port-forward reports `error: error upgrading connection: unable to upgrade connection: pod does not exist`

Question

We are trying to get this example to work on a kubernetes setup on a bunch of virtual servers as a proof of concept. However, we are running in to a problem with the kubectl port-forward command.

The error we get is error: error upgrading connection: unable to upgrade connection: pod does not exist, and tacking on a -v=10 reveals a 404 on an API call to /portforward. The entire output of the command:

oschusler@shepherd:~$ kubectl port-forward pod/redis-master-6b464554c8-vwns2 6379:6379 -v=10
I0815 11:28:18.281223   17549 loader.go:359] Config loaded from file /home/oschusler/.kube/config
I0815 11:28:18.282045   17549 loader.go:359] Config loaded from file /home/oschusler/.kube/config
I0815 11:28:18.284388   17549 loader.go:359] Config loaded from file /home/oschusler/.kube/config
I0815 11:28:18.285945   17549 cached_discovery.go:104] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/servergroups.json
I0815 11:28:18.286747   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apps/v1beta2/serverresources.json
I0815 11:28:18.287309   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/v1/serverresources.json
I0815 11:28:18.287655   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apiregistration.k8s.io/v1/serverresources.json
I0815 11:28:18.287985   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apiregistration.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.288132   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/scheduling.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.288536   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apps/v1beta1/serverresources.json
I0815 11:28:18.288611   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/events.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.288761   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/authentication.k8s.io/v1/serverresources.json
I0815 11:28:18.288981   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/authentication.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.289049   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/authorization.k8s.io/v1/serverresources.json
I0815 11:28:18.289137   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/extensions/v1beta1/serverresources.json
I0815 11:28:18.289247   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/autoscaling/v1/serverresources.json
I0815 11:28:18.289138   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/authorization.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.289309   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/autoscaling/v2beta1/serverresources.json
I0815 11:28:18.289364   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/batch/v1/serverresources.json
I0815 11:28:18.289412   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/batch/v1beta1/serverresources.json
I0815 11:28:18.289463   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/certificates.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.289503   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/networking.k8s.io/v1/serverresources.json
I0815 11:28:18.289560   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/policy/v1beta1/serverresources.json
I0815 11:28:18.289704   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/rbac.authorization.k8s.io/v1/serverresources.json
I0815 11:28:18.289853   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/rbac.authorization.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.289854   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apps/v1/serverresources.json
I0815 11:28:18.289914   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/storage.k8s.io/v1/serverresources.json
I0815 11:28:18.289967   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/storage.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.290016   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apiextensions.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.290165   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/admissionregistration.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.290626   17549 cached_discovery.go:104] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/servergroups.json
I0815 11:28:18.291271   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/v1/serverresources.json
I0815 11:28:18.291664   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apiregistration.k8s.io/v1/serverresources.json
I0815 11:28:18.291893   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apiregistration.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.292185   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/extensions/v1beta1/serverresources.json
I0815 11:28:18.292520   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apps/v1/serverresources.json
I0815 11:28:18.293000   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apps/v1beta2/serverresources.json
I0815 11:28:18.293328   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apps/v1beta1/serverresources.json
I0815 11:28:18.293618   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/events.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.293839   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/authentication.k8s.io/v1/serverresources.json
I0815 11:28:18.294052   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/authentication.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.294293   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/authorization.k8s.io/v1/serverresources.json
I0815 11:28:18.294445   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/authorization.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.294646   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/autoscaling/v1/serverresources.json
I0815 11:28:18.294800   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/autoscaling/v2beta1/serverresources.json
I0815 11:28:18.294946   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/batch/v1/serverresources.json
I0815 11:28:18.294989   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/batch/v1beta1/serverresources.json
I0815 11:28:18.295137   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/certificates.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.295283   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/networking.k8s.io/v1/serverresources.json
I0815 11:28:18.295433   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/policy/v1beta1/serverresources.json
I0815 11:28:18.295648   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/rbac.authorization.k8s.io/v1/serverresources.json
I0815 11:28:18.295702   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/rbac.authorization.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.295855   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/storage.k8s.io/v1/serverresources.json
I0815 11:28:18.296005   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/storage.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.296320   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/admissionregistration.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.296602   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/apiextensions.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.296678   17549 cached_discovery.go:70] returning cached discovery info from /home/oschusler/.kube/cache/discovery/192.168.99.100_6443/scheduling.k8s.io/v1beta1/serverresources.json
I0815 11:28:18.297839   17549 loader.go:359] Config loaded from file /home/oschusler/.kube/config
I0815 11:28:18.298363   17549 round_trippers.go:386] curl -k -v -XGET  -H "User-Agent: kubectl/v1.11.2 (linux/amd64) kubernetes/bb9ffb1" -H "Accept: application/json, */*" 'https://192.168.99.100:6443/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2'
I0815 11:28:18.308319   17549 round_trippers.go:405] GET https://192.168.99.100:6443/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2 200 OK in 9 milliseconds
I0815 11:28:18.308336   17549 round_trippers.go:411] Response Headers:
I0815 11:28:18.308341   17549 round_trippers.go:414]     Content-Type: application/json
I0815 11:28:18.308345   17549 round_trippers.go:414]     Content-Length: 2525
I0815 11:28:18.308348   17549 round_trippers.go:414]     Date: Wed, 15 Aug 2018 11:28:18 GMT
I0815 11:28:18.308379   17549 request.go:897] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"redis-master-6b464554c8-vwns2","generateName":"redis-master-6b464554c8-","namespace":"default","selfLink":"/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2","uid":"0730fdd1-a07c-11e8-8302-02a6922ff6a3","resourceVersion":"569","creationTimestamp":"2018-08-15T11:11:59Z","labels":{"app":"redis","pod-template-hash":"2602011074","role":"master","tier":"backend"},"ownerReferences":[{"apiVersion":"apps/v1","kind":"ReplicaSet","name":"redis-master-6b464554c8","uid":"07250bc2-a07c-11e8-8302-02a6922ff6a3","controller":true,"blockOwnerDeletion":true}]},"spec":{"volumes":[{"name":"default-token-xzf8z","secret":{"secretName":"default-token-xzf8z","defaultMode":420}}],"containers":[{"name":"master","image":"k8s.gcr.io/redis:e2e","ports":[{"containerPort":6379,"protocol":"TCP"}],"resources":{"requests":{"cpu":"100m","memory":"100Mi"}},"volumeMounts":[{"name":"default-token-xzf8z","readOnly":true,"mountPath":"/var/run/secrets/kubernetes.io/serviceaccount"}],"terminationMessagePath":"/dev/termination-log","terminationMessagePolicy":"File","imagePullPolicy":"IfNotPresent"}],"restartPolicy":"Always","terminationGracePeriodSeconds":30,"dnsPolicy":"ClusterFirst","serviceAccountName":"default","serviceAccount":"default","nodeName":"sheep01","securityContext":{},"schedulerName":"default-scheduler","tolerations":[{"key":"node.kubernetes.io/not-ready","operator":"Exists","effect":"NoExecute","tolerationSeconds":300},{"key":"node.kubernetes.io/unreachable","operator":"Exists","effect":"NoExecute","tolerationSeconds":300}],"priority":0},"status":{"phase":"Running","conditions":[{"type":"Initialized","status":"True","lastProbeTime":null,"lastTransitionTime":"2018-08-15T11:11:59Z"},{"type":"Ready","status":"True","lastProbeTime":null,"lastTransitionTime":"2018-08-15T11:12:01Z"},{"type":"ContainersReady","status":"True","lastProbeTime":null,"lastTransitionTime":null},{"type":"PodScheduled","status":"True","lastProbeTime":null,"lastTransitionTime":"2018-08-15T11:11:59Z"}],"hostIP":"10.0.2.15","podIP":"10.244.1.3","startTime":"2018-08-15T11:11:59Z","containerStatuses":[{"name":"master","state":{"running":{"startedAt":"2018-08-15T11:12:00Z"}},"lastState":{},"ready":true,"restartCount":0,"image":"k8s.gcr.io/redis:e2e","imageID":"docker-pullable://k8s.gcr.io/redis@sha256:f066bcf26497fbc55b9bf0769cb13a35c0afa2aa42e737cc46b7fb04b23a2f25","containerID":"docker://b2a009cc40d81a188bb9d8c96f2c7c60bc043260b1bed707408439a6b7f8ad80"}],"qosClass":"Burstable"}}
I0815 11:28:18.314658   17549 loader.go:359] Config loaded from file /home/oschusler/.kube/config
I0815 11:28:18.315684   17549 loader.go:359] Config loaded from file /home/oschusler/.kube/config
I0815 11:28:18.316465   17549 loader.go:359] Config loaded from file /home/oschusler/.kube/config
I0815 11:28:18.316846   17549 round_trippers.go:386] curl -k -v -XGET  -H "Accept: application/json, */*" -H "User-Agent: kubectl/v1.11.2 (linux/amd64) kubernetes/bb9ffb1" 'https://192.168.99.100:6443/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2'
I0815 11:28:18.319240   17549 round_trippers.go:405] GET https://192.168.99.100:6443/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2 200 OK in 2 milliseconds
I0815 11:28:18.319258   17549 round_trippers.go:411] Response Headers:
I0815 11:28:18.319262   17549 round_trippers.go:414]     Content-Type: application/json
I0815 11:28:18.319268   17549 round_trippers.go:414]     Content-Length: 2525
I0815 11:28:18.319272   17549 round_trippers.go:414]     Date: Wed, 15 Aug 2018 11:28:18 GMT
I0815 11:28:18.319301   17549 request.go:897] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"redis-master-6b464554c8-vwns2","generateName":"redis-master-6b464554c8-","namespace":"default","selfLink":"/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2","uid":"0730fdd1-a07c-11e8-8302-02a6922ff6a3","resourceVersion":"569","creationTimestamp":"2018-08-15T11:11:59Z","labels":{"app":"redis","pod-template-hash":"2602011074","role":"master","tier":"backend"},"ownerReferences":[{"apiVersion":"apps/v1","kind":"ReplicaSet","name":"redis-master-6b464554c8","uid":"07250bc2-a07c-11e8-8302-02a6922ff6a3","controller":true,"blockOwnerDeletion":true}]},"spec":{"volumes":[{"name":"default-token-xzf8z","secret":{"secretName":"default-token-xzf8z","defaultMode":420}}],"containers":[{"name":"master","image":"k8s.gcr.io/redis:e2e","ports":[{"containerPort":6379,"protocol":"TCP"}],"resources":{"requests":{"cpu":"100m","memory":"100Mi"}},"volumeMounts":[{"name":"default-token-xzf8z","readOnly":true,"mountPath":"/var/run/secrets/kubernetes.io/serviceaccount"}],"terminationMessagePath":"/dev/termination-log","terminationMessagePolicy":"File","imagePullPolicy":"IfNotPresent"}],"restartPolicy":"Always","terminationGracePeriodSeconds":30,"dnsPolicy":"ClusterFirst","serviceAccountName":"default","serviceAccount":"default","nodeName":"sheep01","securityContext":{},"schedulerName":"default-scheduler","tolerations":[{"key":"node.kubernetes.io/not-ready","operator":"Exists","effect":"NoExecute","tolerationSeconds":300},{"key":"node.kubernetes.io/unreachable","operator":"Exists","effect":"NoExecute","tolerationSeconds":300}],"priority":0},"status":{"phase":"Running","conditions":[{"type":"Initialized","status":"True","lastProbeTime":null,"lastTransitionTime":"2018-08-15T11:11:59Z"},{"type":"Ready","status":"True","lastProbeTime":null,"lastTransitionTime":"2018-08-15T11:12:01Z"},{"type":"ContainersReady","status":"True","lastProbeTime":null,"lastTransitionTime":null},{"type":"PodScheduled","status":"True","lastProbeTime":null,"lastTransitionTime":"2018-08-15T11:11:59Z"}],"hostIP":"10.0.2.15","podIP":"10.244.1.3","startTime":"2018-08-15T11:11:59Z","containerStatuses":[{"name":"master","state":{"running":{"startedAt":"2018-08-15T11:12:00Z"}},"lastState":{},"ready":true,"restartCount":0,"image":"k8s.gcr.io/redis:e2e","imageID":"docker-pullable://k8s.gcr.io/redis@sha256:f066bcf26497fbc55b9bf0769cb13a35c0afa2aa42e737cc46b7fb04b23a2f25","containerID":"docker://b2a009cc40d81a188bb9d8c96f2c7c60bc043260b1bed707408439a6b7f8ad80"}],"qosClass":"Burstable"}}
I0815 11:28:18.320165   17549 round_trippers.go:386] curl -k -v -XPOST  -H "X-Stream-Protocol-Version: portforward.k8s.io" -H "User-Agent: kubectl/v1.11.2 (linux/amd64) kubernetes/bb9ffb1" 'https://192.168.99.100:6443/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2/portforward'
I0815 11:28:18.339785   17549 round_trippers.go:405] POST https://192.168.99.100:6443/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2/portforward 404 Not Found in 19 milliseconds
I0815 11:28:18.340171   17549 round_trippers.go:411] Response Headers:
I0815 11:28:18.340348   17549 round_trippers.go:414]     Date: Wed, 15 Aug 2018 11:28:18 GMT
I0815 11:28:18.340515   17549 round_trippers.go:414]     Content-Length: 18
I0815 11:28:18.340674   17549 round_trippers.go:414]     Content-Type: text/plain; charset=utf-8
F0815 11:28:18.340939   17549 helpers.go:119] error: error upgrading connection: unable to upgrade connection: pod does not exist
oschusler@shepherd:~$

It looks like the issue is with POST https://192.168.99.100:6443/api/v1/namespaces/default/pods/redis-master-6b464554c8-vwns2/portforward 404 Not Found in 19 milliseconds.

We've been at this issue for days straight, but haven't been able to figure it out so far. People suggested RBAC might be the culprit, but we are unsure how to check this. We also tried starting the kubelets with the AlwaysAllow authorization mode, but that gave all kinds of different issues.

Not sure how to proceed on this one, we're at our wits end.

Answer 1

After diving into the apiserver logs (--v=9 as argument in the apiserver yaml config, which we found a hint of on this and this github issue) we found a line that suggested the actual problem:

I0815 12:18:23.953732       1 handler.go:143] kube-apiserver: POST "/api/v1/namespaces/default/pods/redis-master-6b464554c8-jsxrp/portforward" satisfied by gorestful with webservice /api/v1
I0815 12:18:23.975756       1 upgradeaware.go:259] Connecting to backend proxy (intercepting redirects) https://10.0.2.15:10250/portForward/default/redis-master-6b464554c8-jsxrp
  Headers: map[Connection:[Upgrade] Upgrade:[SPDY/3.1] X-Stream-Protocol-Version:[portforward.k8s.io] User-Agent:[kubectl/v1.11.2 (linux/amd64) kubernetes/bb9ffb1] Content-Length:[0] X-Forwarded-For:[192.168.99.100]]

The request is forwarded to 10.0.2.15, which happens to be a local NAT-ed IP that is assigned to all VM's. So every vm has the internal ip 10.0.2.15, as was also seen by listing the nodes:

NAME       STATUS    ROLES     AGE       VERSION   INTERNAL-IP      EXTERNAL-IP   OS-IMAGE             KERNEL-VERSION      CONTAINER-RUNTIME
sheep01    Ready     <none>    49m       v1.11.2   10.0.2.15        <none>        Ubuntu 18.04.1 LTS   4.15.0-32-generic   docker://17.12.1-ce
shepherd   Ready     master    1h        v1.11.2   10.0.2.15        <none>        Ubuntu 18.04.1 LTS   4.15.0-32-generic   docker://17.12.1-ce

As specified in this answer, we added --node-ip option to override what the kubelet thinks is it's IP and that fixed the issue.