kubelogin: Fails to connect to existing server

Describe the bug In some circumstances, kubelogin will not talk to an existing kubelogin server, and then fails because it cannot start a new server on the same port.

$ kubectl version
error: get-token: could not get a token: authentication error: authcode-browser error: authentication error: authorization code flow error: oauth2 error: authorization error: could not start a local server: no available port: could not listen: listen tcp 127.0.0.1:20904: bind: address already in use

To Reproduce I am not entirely sure how to reproduce this. What I have seen is that it works one day and then fails the next. Whether it is because the computer went to sleep in between, or the refresh token expired, or something else, I do not know. I am happy to do further debugging but need guidance.

Kubeconfig excerpt

users:
  user:
    exec:
      apiVersion: client.authentication.k8s.io/v1beta1
      args:
      - oidc-login
      - get-token
      - --oidc-client-id=kubernetes
      - --oidc-extra-scope=roles
      - --listen-address=localhost:20904
      - --oidc-issuer-url=https://keycloak/auth/realms/master
      command: kubectl
      env: null

Expected behavior I expect kubelogin to use the existing server if it is running and shut it down if it is somehow unusable. Instead, it keeps the server running but does not use it.

Environment

OS: macOS 10.15.6
kubelogin version: v1.20.0
kubectl version: v1.16.6-beta.0 (ships with Docker for Mac)
OpenID Connect provider: Keycloak

About this issue

Original URL
State: open
Created 4 years ago
Reactions: 1
Comments: 16 (6 by maintainers)

Most upvoted comments

I just tried it and the old processes don’t seem to be closed.

$ kubelogin version
kubelogin version v1.20.1 (go1.14.7 darwin_amd64)
$ lsof -n -i :8000  
COMMAND     PID        USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
kubelogin 35576 agaudreault   18u  IPv4 0xeedb67730632abcd      0t0  TCP 127.0.0.1:irdmi (LISTEN)
$ lsof -n -i :18000 
COMMAND     PID        USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
kubelogin 35774 agaudreault   18u  IPv4 0xeedb67730634dcba      0t0  TCP 127.0.0.1:biimenu (LISTEN)
$ kubectl get pods -v 9 
I0908 09:48:42.250664   37351 loader.go:375] Config loaded from file:  /Users/agaudreault/.kube/config
I0908 09:48:42.253482   37351 round_trippers.go:423] curl -k -v -XGET  -H "Accept: application/json, */*" -H "User-Agent: kubectl/v1.18.6 (darwin/amd64) kubernetes/dff82dc" 'https://my.domain/api?timeout=32s'
error: get-token: could not get a token: authentication error: authcode-browser error: authentication error: authorization code flow error: oauth2 error: authorization error: could not start a local server: no available port: could not listen: listen tcp 127.0.0.1:8000: bind: address already in use, could not listen: listen tcp 127.0.0.1:18000: bind: address already in use
I0908 09:48:42.738157   37351 round_trippers.go:443] GET https://my.domain/api?timeout=32s  in 483 milliseconds
I0908 09:48:42.738186   37351 round_trippers.go:449] Response Headers:
I0908 09:48:42.738263   37351 cached_discovery.go:121] skipped caching discovery info due to Get "https://my.domain/api?timeout=32s": getting credentials: exec: exit status 1

agaudreault-jive on Sep 8, 2020

I just released https://github.com/int128/kubelogin/releases/tag/v1.20.1 and please try using it.

int128 on Sep 5, 2020

@int128 No, I am intentionally letting the window open 3 minutes (or the timeout duration value) so the timeout condition is triggered. Then, another tab opens. This happens exactly 5 times.

Sorry for that! I actually never mentioned that I was not logging in!

agaudreault-jive on Oct 8, 2020

I have the following logs. But at this point, I think there is a retry somewhere in the Kubernetes client and this has nothing to do with the plugin. Sadly, I don’t see any options to disable them with kubectl options.

k get pods -v8
I1007 18:07:58.463551   49503 loader.go:375] Config loaded from file:  /Users/agaudreault/.kube/config
I1007 18:07:58.464453   49503 round_trippers.go:420] GET https://my.domain/api?timeout=32s
I1007 18:07:58.464465   49503 round_trippers.go:427] Request Headers:
I1007 18:07:58.464470   49503 round_trippers.go:431]     Accept: application/json, */*
I1007 18:07:58.464474   49503 round_trippers.go:431]     User-Agent: kubectl/v1.19.0 (darwin/amd64) kubernetes/e199641
I1007 18:07:58.541212   49504 get_token.go:51] WARNING: log may contain your secrets such as token or password
I1007 18:07:58.541616   49504 get_token.go:64] finding a token from cache directory /Users/agaudreault/.kube/cache/oidc-login
I1007 18:07:58.541750   49504 get_token.go:76] could not find a token cache: could not open file /Users/agaudreault/.kube/cache/oidc-login/e1f6fc628391a83a773c92a8c230ed48ecbdc52eabc025266aea744f4f90ec1f: open /Users/agaudreault/.kube/cache/oidc-login/e1f6fc628391a83a773c92a8c230ed48ecbdc52eabc025266aea744f4f90ec1f: no such file or directory
I1007 18:07:58.542111   49504 authentication.go:104] initializing an OpenID Connect client
I1007 18:07:59.253316   49504 browser.go:34] starting the authentication code flow using the browser
I1007 18:07:59.253571   49504 browser.go:77] opening http://localhost:8000 in the browser
I1007 18:07:59.254535   49504 server.go:36] oauth2cli: starting a server at 127.0.0.1:8000
I1007 18:07:59.496192   49504 server.go:135] oauth2cli: sending redirect to https://login.microsoftonline.com/TENANT_ID/oauth2/v2.0/authorize?access_type=offline&client_id=REDACTED...
W1007 18:08:30.468326   49503 transport.go:260] Unable to cancel request for *exec.roundTripper
I1007 18:10:59.258899   49504 server.go:66] oauth2cli: shutting down the server
I1007 18:10:59.259080   49504 server.go:70] oauth2cli: force-closing the server: shutdown failed: context deadline exceeded
I1007 18:10:59.259093   49504 server.go:47] oauth2cli: stopped the server
error: get-token: could not get a token: authentication error: authcode-browser error: authentication error: authorization code flow error: oauth2 error: authorization error: authorization error: context deadline exceeded
I1007 18:10:59.259166   49504 cmd.go:66] stacktrace: get-token:
    github.com/int128/kubelogin/pkg/adaptors/cmd.(*GetToken).New.func2
        /Users/distiller/project/pkg/adaptors/cmd/get_token.go:71
  - could not get a token:
    github.com/int128/kubelogin/pkg/usecases/credentialplugin.(*GetToken).Do
        /Users/distiller/project/pkg/usecases/credentialplugin/get_token.go:54
  - authentication error:
    github.com/int128/kubelogin/pkg/usecases/credentialplugin.(*GetToken).getTokenFromCacheOrProvider
        /Users/distiller/project/pkg/usecases/credentialplugin/get_token.go:102
  - authcode-browser error:
    github.com/int128/kubelogin/pkg/usecases/authentication.(*Authentication).Do
        /Users/distiller/project/pkg/usecases/authentication/authentication.go:135
  - authentication error:
    github.com/int128/kubelogin/pkg/usecases/authentication/authcode.(*Browser).Do
        /Users/distiller/project/pkg/usecases/authentication/authcode/browser.go:100
  - authorization code flow error:
    github.com/int128/kubelogin/pkg/usecases/authentication/authcode.(*Browser).Do.func2
        /Users/distiller/project/pkg/usecases/authentication/authcode/browser.go:93
  - oauth2 error:
    github.com/int128/kubelogin/pkg/adaptors/oidcclient.(*client).GetTokenByAuthCode
        /Users/distiller/project/pkg/adaptors/oidcclient/oidcclient.go:91
  - authorization error: authorization error: context deadline exceeded
I1007 18:10:59.261119   49503 round_trippers.go:446] Response Status:  in 180791 milliseconds
I1007 18:10:59.261131   49503 round_trippers.go:449] Response Headers:
I1007 18:10:59.261177   49503 cached_discovery.go:121] skipped caching discovery info due to Get "https://my.domain/api?timeout=32s": getting credentials: exec: executable kubectl failed with exit code 1 (Client.Timeout exceeded while awaiting headers)
I1007 18:10:59.261718   49503 round_trippers.go:420] GET https://my.domain/api?timeout=32s
I1007 18:10:59.261733   49503 round_trippers.go:427] Request Headers:
I1007 18:10:59.261738   49503 round_trippers.go:431]     Accept: application/json, */*
I1007 18:10:59.261742   49503 round_trippers.go:431]     User-Agent: kubectl/v1.19.0 (darwin/amd64) kubernetes/e199641
I1007 18:10:59.336678   49924 get_token.go:51] WARNING: log may contain your secrets such as token or password
I1007 18:10:59.337062   49924 get_token.go:64] finding a token from cache directory /Users/agaudreault/.kube/cache/oidc-login
I1007 18:10:59.337221   49924 get_token.go:76] could not find a token cache: could not open file /Users/agaudreault/.kube/cache/oidc-login/e1f6fc628391a83a773c92a8c230ed48ecbdc52eabc025266aea744f4f90ec1f: open /Users/agaudreault/.kube/cache/oidc-login/e1f6fc628391a83a773c92a8c230ed48ecbdc52eabc025266aea744f4f90ec1f: no such file or directory
I1007 18:10:59.337257   49924 authentication.go:104] initializing an OpenID Connect client
I1007 18:11:00.015832   49924 browser.go:34] starting the authentication code flow using the browser
I1007 18:11:00.016042   49924 browser.go:77] opening http://localhost:8000 in the browser
I1007 18:11:00.016072   49924 server.go:36] oauth2cli: starting a server at 127.0.0.1:8000
...[repeat]...

agaudreault-jive on Oct 7, 2020

@int128 it seems to fix it on my side, or at least remediate to the issue with a weird side effect.

With the CLI, I get a transport error when I close a tab, then I get the get-token error after 3 minutes and a new tab reopens. For as long as the process is running, a new tab will open every 3 minutes.

W1007 17:04:20.735991   39742 transport.go:260] Unable to cancel request for *exec.roundTripper
error: get-token: could not get a token: authentication error: authcode-browser error: authentication error: authorization code flow error: oauth2 error: authorization error: authorization error: context deadline exceeded

With Lens, once the id_token expires, the login page pops up in the browser. If I wait 180 seconds without login, another tab opens with the login page.

The good thing is that the process always reuses the same port when it reopens a tab, the bad news is that it stays in that loop instead of exiting completely and freeing the port.

I would expect lens or the CLI to just return an authentication error after the timeout

EDIT: Actually, it retries exactly 5 times…

agaudreault-jive on Oct 7, 2020

https://github.com/int128/oauth2cli/pull/51 may fix this issue. I will release the new version of kubelogin later.

int128 on Sep 1, 2020

Same thing is happening to me. Especially when using https://k8slens.dev/, but it will also cause problems on the CLI. Whenever it prompts you to login and open the browser, if you close it then, the socket (8000) will stay open forever. If you use the CLI, dont cancel the process manually. The second time, it will use the socket 18000.

You can see that the socket is still open with

$ lsof -i :8000                      
COMMAND     PID        USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
kubelogin 44140 agaudreault   11u  IPv4 0xeedb6772f57f6aaa      0t0  TCP localhost:irdmi (LISTEN)
$ lsof -i :18000
COMMAND     PID        USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
kubelogin 55880 agaudreault   18u  IPv4 0xeedb6772f57f8d27      0t0  TCP localhost:biimenu (LISTEN)

Finally, you will get the error the third time.

error: get-token: could not get a token: authentication error: authcode-browser error: authentication error: authorization code flow error: oauth2 error: authorization error: could not start a local server: no available port: could not listen: listen tcp 127.0.0.1:8000: bind: address already in use, could not listen: listen tcp 127.0.0.1:18000: bind: address already in use

You can workaround the problem by killing these hanging processes before calling kubectl oidc-login.

I believe some sort of timeout that would close the socket and the kubelogin process if it takes too long would solve/mitigate the issue.

$ kubelogin --version
kubelogin version v1.20.0

agaudreault-jive on Sep 2, 2020