Fails to connect to existing server

[Nuru]

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

[agaudreault]

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

[int128]

Thank you for your reports. I'm considering adding a timeout of authentication.

It seems the below lines may block.
https://github.com/int128/oauth2cli/blob/v1.12.1/server.go#L64-L66

[int128]

int128/oauth2cli#51 may fix this issue. I will release the new version of kubelogin later.

[int128]

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

[agaudreault]

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

[anwarchk]

This issue still persist.

[int128]

I added the authentication timeout (default 180 sec) in https://github.com/int128/kubelogin/releases/tag/v1.21.0. It may fix this issue but still #389 is needed for a fundamental solution.

[agaudreault]

@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...

[int128]

Thank you for your detailed report!

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.

I suspect a connection between kubelogin and the browser remains after login.
Could you send me a verbose log with -v1 flag as follows?

users:
- name: oidc
  user:
    exec:
      apiVersion: client.authentication.k8s.io/v1beta1
      command: kubectl
      args:
      - oidc-login
      - get-token
      - -v1

(please don't forget to mask your credentials)

the bad news is that it stays in that loop instead of exiting completely and freeing the port

Yes, this is an side effect of the timeout. I'm investigating #389.

[agaudreault]

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]...

[int128]

Let me clarify. Did you see the success page after login like below?

According to the log, the browser accessed the following URLs:

1. http://localhost:8000 (kubelogin local server)
2. https://login.microsoftonline.com/TENANT_ID/oauth2/v2.0/authorize... (your identity provider)

the browser finally should receive a code from your identity provider via a redirect like http://localhost:8000/?code=***&state=*** but it seems not received.

[agaudreault]

@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!

[parthpalkhiwala-vonage]

Hello Guys

I'm having an issue with the kubectl since last week - we are using OIDC to connect with the K8s server but since last week kubectl is not able to connect with the server
Below is an example

kubectl version --user=oidc
I0222 15:20:14.351279 47104 get_token.go:53] WARNING: log may contain your secrets such as token or password
I0222 15:20:14.351575 47104 get_token.go:60] acquiring a lock get-token-8000-18000
W0222 15:20:46.291885 47103 transport.go:260] Unable to cancel request for *exec.roundTripper

Any help would be greatly appreciated.

Environment
OS: macOS Big Sur 11.6
kubelogin/oidc-login version: v1.25.1
kubectl version: v1.21.2 (Docker Desktop Version 3.5)
OpenID Connect provider: Google's Oauth 2

CC: @int128

[lknite]

Also experiencing this, could use a work around. Tried adding --authentication-timeout-sec 30 but it didn't help:

$ kubelogin-oidc get-token --oidc-issuer-url=https://keycloak.mydomain.com/auth/realms/mydomain.com --oidc-client-id=kubernetes -v 5 --authentication-timeout-sec 30
I0406 12:33:25.248735   32909 get_token.go:53] WARNING: log may contain your secrets such as token or password
I0406 12:33:25.248801   32909 get_token.go:60] acquiring a lock get-token-8000-18000

$ kubelogin-oidc --version
kubelogin version v1.25.1

$ k version --client
Client Version: version.Info{Major:"1", Minor:"18+", GitVersion:"v1.18.2-6+38ac483e736488", GitCommit:"38ac483e736488517dd754156441b89e0b2060e2", GitTreeState:"clean", BuildDate:"2020-07-07T13:54:17Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"}

$ k version
this hang so can't put it here, but it's the same version of the client

Everything was working, now seeing this seemingly out of the blue. There something I can do to get this working again?

For those who come along after this... I got back to working by simply rebooting the system where kubelogin is being run.

[cpotter302]

Hello, whats the status of this issue. I am facing the same problem (login loop and program exit).
On first try it was working, but after i couldnt make it work again.
Are there any new solutions to this problem?

[lknite]

Not at a computer at the moment but if I am remembering correctly a login was interrupted  resulting in a hung session which was using the port.  Ended up rebooting the system and everything started working again and just made sure not to interrupt the login process.  I think it's an issue that is reproducible if you close the browser without logging in. I eventually switched to pinniped which has an option to display a url the client can copy I to a browser.  Maybe we need this "display a url" instead of opening Brower for kubelogin .... (or maybe it already has the option and I just haven't found it yet.)