Server returns 502 "authentik starting..."

[0xcd0e]

Describe the bug
While authenticating and generally just moving around the site, requests fail with response 502.
Seems like its mainly POST requests that get redirected so they become GET requests, sometimes the redirect seems to result in the 502.
Dev console in my browser shows "authentik starting..." as the server response, the GUI just shows "Whooops! Something went wrong! Please try again later.".
After retrying again and again, it starts working after some time, requests are answered with a 302 and a GET request is sent by the browser which makes it work.

To Reproduce
The behavior is random!
Steps to reproduce the behavior:

1. Visit authentik /if/flow/default-authentication-flow/?next=%2F
2. Enter username
3. Press enter
4. Sometimes it work, sometimes it doesnt

Expected behavior
Being able to navigate the site and authenticate without having to roll a dice.

Logs
Server log:

Invalid HTTP request received.
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/http/httptools_impl.py", line 132, in data_received
self.parser.feed_data(data)
File "httptools/parser/parser.pyx", line 212, in httptools.parser.parser.HttpParser.feed_data
httptools.parser.errors.HttpParserInvalidMethodError: Invalid method encountered
Invalid HTTP request received.
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/http/httptools_impl.py", line 132, in data_received
self.parser.feed_data(data)
File "httptools/parser/parser.pyx", line 212, in httptools.parser.parser.HttpParser.feed_data
httptools.parser.errors.HttpParserInvalidMethodError: Invalid method encountered
{"event":"EOF","level":"warning","logger":"authentik.router","timestamp":"2022-02-06T19:05:11+01:00"}

Version and Deployment (please complete the following information):

• authentik version: ghcr.io/goauthentik/server:2022.1.4
• Deployment: docker on unraid

[Akruidenberg]

Ik have the same problem with 2022.1.4. Previous version is working fine

[beniwtv]

I have the same issue, just clicking around the admin interface will trigger this, as well as trying to authenticate, which only works sometimes.

[rhaex]

This also affects requests done by external clients that use Authentik as an IdentityProvider for OpenID Connect. This means the version is not usable for production environments. We did a rollback to 2022.1.3 and in that version the issue is not present.

[BeryJu]

I've not been able to reproduce this issue and it also hasn't occurred for me.

What's everyone's setup like? Reverse proxy or direct access to authentik? Docker-compose or kubernetes?

[Akruidenberg]

Traefik 2.5.7 with docker compose. 2022.1.3 is running fine.

[BeryJu]

@Akruidenberg can you post the related traefik logs? I can reproduce the error if I send it an invalid method on purpose, but not with normal usage so I'm curious to see what traefik is sending it.

[beniwtv]

Using Docker here + NGINX reverse proxy. Even before I added NGINX, I got that error.

[0xcd0e]

Same here, docker (on unraid) + nginx, seeing the error with and without nginx

[BeryJu]

There is a similar issue here encode/uvicorn#1296 but that shouldn't have changed anything between 22.1.3 and 22.1.4

[Akruidenberg]

What exactly are the differences between .3 and .4? Strange thing is, the previous version don't have the issue.

[BeryJu]

version/2022.1.3...version/2022.1.4, the only change that could've done something is the uvicorn upgrade, but I can't test rolling it back since I can't reproduce the error

[BeryJu]

Could some of you test the latest gh-next build, and set the log level to trace? That will log the URL and headers for those failed requests which should help debug the issue.

[0xcd0e]

Just tried gh-next but cant reproduce the error because this version is stopping me from taking any administrative action, always returning
"CSRF Failed: Origin checking failed - https://authentik.mydomain.com does not match any trusted origins."
(instead of authentik.mydomain.com it shows the correct fqdn of authentik).

Even just trying to edit a user, trace log shows

{"event": "/api/v3/core/users/1/", "host": "localhost:8000", "level": "info", "logger": "authentik.asgi", "method": "PUT", "pid": 28, "remote": "2a02:xxx:1ec4", "request_id": "7f0089ce2cb34db58ea6e7ae1fd9b319", "runtime": 18, "scheme": "https", "status": 403, "timestamp": "2022-02-09T13:06:50.412740", "user": "", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.82 Safari/537.36"}
{"event": "Forbidden: /api/v3/core/users/1/", "level": "warning", "logger": "django.request", "timestamp": 1644412010.4137774}

[BeryJu]

CSRF issues can happen when an old webui is cached somewhere, can you try clearing that? The webui should send an X-Authentik-CSRF header (iirc)

[0xcd0e]

Ive cleared all caches, used a fresh browser profile and even restarted nginx, but the error is still there

[BeryJu]

Oops I misread the error, yeah that was actually caused by a mistake on my side, will be fixed in the next gh-next build

@0xcd0e build is up now

[0xcd0e]

Ok the csrf error seems to be gone, and so is the 502 error... I cant reproduce it on gh-next, but it happens again as soon as i switch back to 22.1.4

[BeryJu]

on 22.1.4, when the error happens, could you look in the browser's developer console, and post a screenshot of a failing request here? I'm still curious what requests break it since I can't reproduce it locally, even when running the same commit as 22.1.4

[0xcd0e]

For example, a simple request to change a users Name:

curl 'https://authentik.mydomain.com/api/v3/core/users/1/' \
  -X 'PUT' \
  -H 'authority: authentik.mydomain.com' \
  -H 'sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="98", "Google Chrome";v="98"' \
  -H 'dnt: 1' \
  -H 'sec-ch-ua-mobile: ?0' \
  -H 'user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.82 Safari/537.36' \
  -H 'content-type: application/json' \
  -H 'x-authentik-csrf: opXXXFt' \
  -H 'sentry-trace: eaXXXad-0' \
  -H 'sec-ch-ua-platform: "Windows"' \
  -H 'accept: */*' \
  -H 'origin: https://authentik.mydomain.com' \
  -H 'sec-fetch-site: same-origin' \
  -H 'sec-fetch-mode: cors' \
  -H 'sec-fetch-dest: empty' \
  -H 'referer: https://authentik.mydomain.com/if/admin/' \
  -H 'accept-language: en-US,en;q=0.9,de-DE;q=0.8,de;q=0.7' \
  -H 'cookie: authentik_csrf=opXXXFt; authentik_session=afXXXmt' \
  --data-raw '{"username":"akadmin","name":"New Authentik Admin Name","is_active":true,"groups":["0XXXeb"],"email":"REDACTED","attributes":{"settings":{"locale":""}}}' \
  --compressed

Returns 502 "authentik starting...", waiting for a moment and hitting the Update button again returns 200 and the user gets updated.
The two requests are exactly the same, i've checked.
The request that results in a 502 also produces two error popups in the top right corner, one is completely empty, the other one says

API request failed
PUT /api/v3/core/users/1/: 502

[0xcd0e]

I think this is a uvicorn 0.17.1 issue, on their releases page on version 0.17.2 (https://github.com/encode/uvicorn/releases/tag/0.17.2), they rolled back some changes because of a problem with httptools encode/uvicorn#1345

The error im seeing is exactly that
File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/http/httptools_impl.py"

So updating uvicorn to 0.17.2 or later should fix the issue

[BeryJu]

Cheers for the digging, that would explain it not being in the latest build since c1c8e4c was merged.

Let me quickly build an image with that commit cherrypicked to tests and then I can ship 22.1.5

[BeryJu]

@0xcd0e please try with ghcr.io/goauthentik/dev-server:gh-version-2022.1, that should have the issue fixed

[0xcd0e]

Thanks, I will pull that and use it until a official release is out

[BeryJu]

Fixed by cf600f6