Authentication fails with a 500 internal server error

[nint8835]

Describe the bug

When attempting to log in via gh auth login, logging in is failing with a 500 internal server error. I first ran into this today, but someone else I spoke to has reported he's been running into this for a week now.

I've attempted debugging with GH_DEBUG=api, but I see no actual 500s being returned. The last request I see before the error message is a call to https://github.com/login/oauth/access_token, which according to the logs returned a 200 OK.

Apologies for the lack of details - if there's any way I can get any other details to help troubleshoot this I'd be more than happy to provide them.

Version:

> gh --version
gh version 2.14.2 (2022-07-14)
https://github.com/cli/cli/releases/tag/v2.14.2

Steps to reproduce the behavior

1. Run gh auth login
2. Select any options for preferred protocol & git config
3. When prompted for how to authenticate, select web browser
4. Complete the login flow in the browser

Expected vs actual behavior

Expected: Login would be successful

Actual: Login fails with an internal server error

Logs

> gh auth login
? What account do you want to log into? GitHub.com
? What is your preferred protocol for Git operations? HTTPS
? Authenticate Git with your GitHub credentials? Yes
? How would you like to authenticate GitHub CLI? Login with a web browser

! First copy your one-time code: XXXX-XXXX
Press Enter to open github.com in your browser...
failed to authenticate via web browser: non-200 OK status code: 500 Internal Server Error body: ""

[mislav]

Hi, sorry to hear that you're unable to log in! I've never heard of this issue before. Are you saying that when you enable verbose logging, the last response from the server is definitely a HTTP 200 and looks like this?

> POST /login/oauth/access_token HTTP/1.1
> Host: github.com
> Content-Type: application/x-www-form-urlencoded

< HTTP/2.0 200 OK
< Content-Type: application/x-www-form-urlencoded; charset=utf-8
< Date: Thu, 21 Jul 2022 12:25:52 GMT
< Server: GitHub.com
(snip)
* Request took 212.054548ms

[nint8835]

That is correct, here's the relevant excerpt from the logs:

* Request to https://github.com/login/oauth/access_token
> POST /login/oauth/access_token HTTP/1.1
> Host: github.com
> Content-Type: application/x-www-form-urlencoded

< HTTP/2.0 200 OK
< Content-Type: application/x-www-form-urlencoded; charset=utf-8
< Date: Thu, 21 Jul 2022 12:03:30 GMT
< Server: GitHub.com
(snip)

* Request took 152.665542ms
failed to authenticate via web browser: non-200 OK status code: 500 Internal Server Error body: ""

[mislav]

OK, thank you! I will investigate on the platform end.

The workaround you can try is to use the GitHub web interface to generate a Personal Access Token with repo and read:org (and possibly other) scopes, then paste it to gh auth login. https://github.com/settings/tokens

[mislav]

@nint8835 Does the failed to authenticate via web browser error happen even after you've completed the login flow in the browser, i.e. the authorization flow in the browser presented the successful login screen?

[nint8835]

OK, thank you! I will investigate on the platform end.

The workaround you can try is to use the GitHub web interface to generate a Personal Access Token with repo and read:org (and possibly other) scopes, then paste it to gh auth login. https://github.com/settings/tokens

Doing this doesn't work either, but in this case I actually see a 500 show up in the logs

* Request to https://api.github.com/
> GET / HTTP/1.1
> Host: api.github.com
> Authorization: token ██████████████
> Content-Type: application/json; charset=utf-8
> Time-Zone:
> User-Agent: GitHub CLI 2.14.2

< HTTP/2.0 500 Internal Server Error
< Content-Type: application/json; charset=utf-8
< Date: Thu, 21 Jul 2022 12:46:47 GMT
< Server: GitHub.com
(snip)

* Request took 1.068518416s
error validating token: HTTP 500 (https://api.github.com/)

@nint8835 Does the failed to authenticate via web browser error happen even after you've completed the login flow in the browser, i.e. the authorization flow in the browser presented the successful login screen?

Yes, it does. The error only shows up in the terminal after I've gone through the authorization flow and reach the screen saying my device is connected.

[mislav]

Oh wow that is really strange. So both OAuth tokens and PATs (personal access tokens) are rejected for your account by the GitHub API. And this seems to be affecting someone else you've spoken with as well?

Was there a JSON body as part of the 500 Internal Server Error response in your last comment? Were there any error messages encoded in the JSON body that you could share?

[nint8835]

And this seems to be affecting someone else you've spoken with as well?

Correct, at least one of my coworkers is running into the exact same issue with the same behaviour as me for both the PAT method and the OAuth method

Was there a JSON body as part of the 500 Internal Server Error response in your last comment?

Is the JSON body supposed to show up in the debug output? If so, doesn't seem there was any body in the response

[mislav]

Is the JSON body supposed to show up in the debug output? If so, doesn't seem there was any body in the response

Often there is a JSON body response for HTTP errors, but sometimes not. If nothing was shown for you, then the body was empty, which can sometimes happen with HTTP 500 requests. Thank you for checking 🙇

[mislav]

@nint8835 If you could share some request IDs, that would help us a lot. When enabling GH_DEBUG=api, request IDs will be printed as the X-Github-Request-Id header. Please paste us the request IDs for either the final HTTP 200 response from gh auth login browser flow, or from the HTTP 500 response when attempting to use a PAT. Thank you!

[nint8835]

Final 200 from browser flow: C69B:8C19:F195:1AA94:62D9408D
500 when using PAT: DD45:5C29:381F4:ACF1F:62D94AB7

[mislav]

Thanks, we've been able to track down the bug.

Do you have the TZ environment variable set by any chance? In any case, you might be able to temporarily work around your issue by setting export TZ=UTC before using gh. For some reason, we were unable to detect your local time zone from gh. We then send the request header Time-Zone: (empty value) to the API server, which errors out on the invalid value.

[nint8835]

Thanks, that did the trick!

As for the TZ environment variable, I don't have it set. I took a quick look at the timezone code out of curiosity and my immediate guess is something with the timezone detection code in the go-gh library.

The currentTimeZone function is hitting the Local branch for me, and is getting an offset value of -9000 (-2.5 hours). However, when looking up the timezone from the value, the map is seemingly expecting the value to be -12600 (-3.5 hours) for my time zone, so the offset doesn't seem to be resolving to my timezone

[mislav]

Thanks for debugging that. I wonder whether the -2.5h vs -3.5h discrepancy could be because of Daylight Saving Time? In any case, we will make a change to not send any Time-Zone header if we fail to detect the timezone.

[nint8835]

I wonder whether the -2.5h vs -3.5h discrepancy could be because of Daylight Saving Time?

I'm pretty sure that's the case.

I took a look into it and I think the reason this hasn't been encountered previously / hasn't been encountered that often is that the vast majority of timezones will still resolve to a value even during DST. If my quick pass through the values are correct, there are 3 timezones where it'll correctly resolve to a value when DST is not in effect and will not resolve to a value when DST is in effect.

These time zones are:

• America/St_Johns
• Australia/Adelaide
• Pacific/Chatham