Internal Server Error after Login Attempt (status=401/403/500)

[zamashal]

Summary

Unable to log in to the console and getting redirected to a page with Internal Server Error instead.

Steps to Reproduce

1. Use the following docker-compose.yml.txt file
2. Follow the instructions at https://thethingsstack.io/v3.5.1/guides/getting-started/
3. Run docker-compose up and check the logs as you browse to the console

What do you see now?

As soon as I try to access the console by browsing to https://thethings.example.com on my pc, I see the following on my debug logs:

stack_1      |   INFO Request handled                          duration=7.006µs location=/console method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSBPQVEH1ST1W2D5Q63136Q response_size=0 status=302 url=/
stack_1      |   INFO Request handled                          duration=1.548043ms method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSBPQVN9T5EHYT2QAY4TGQ1 response_size=1917 status=200 url=/console
stack_1      |   INFO Request handled                          duration=817.708µs method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSBPR4GJ0PQDBV3QTW53VSF response_size=253 status=401 url=/console/api/auth/token
stack_1      |   INFO Request handled                          duration=380.101µs method=POST namespace=web remote_addr=pc_ip:61768 request_id=01DZSBPR70NGGNQXPWTTZGCJ6S response_size=249 status=403 url=/console/api/auth/logout

After I click Login on the first screen, I get the following:

stack_1      |   INFO Request handled                          duration=796.436µs location=/oauth/authorize?client_id=console&redirect_uri=%2Fconsole%2Foauth%2Fcallback&response_type=code&state=NkJcx6v_UHD3L_1z method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSCA3Y2BAEXV5TN0QHK0ZQ6 response_size=0 status=302 url=/console/login/ttn-stack
stack_1      |   INFO Request handled                          duration=183.793µs location=/oauth/login?n=%2Foauth%2Fauthorize%3Fclient_id%3Dconsole%26redirect_uri%3D%252Fconsole%252Foauth%252Fcallback%26response_type%3Dcode%26state%3DNkJcx6v_UHD3L_1z method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSCA3YBBQ5ZPSWSGR3QAS71 response_size=0 status=302 url=/oauth/authorize?client_id=console&redirect_uri=%2Fconsole%2Foauth%2Fcallback&response_type=code&state=NkJcx6v_UHD3L_1z
stack_1      |   INFO Request handled                          duration=1.776339ms method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSCA3YJE00SSPXEKBS65DA2 response_size=1356 status=200 url=/oauth/login?n=%2Foauth%2Fauthorize%3Fclient_id%3Dconsole%26redirect_uri%3D%252Fconsole%252Foauth%252Fcallback%26response_type%3Dcode%26state%3DNkJcx6v_UHD3L_1z
stack_1      |   INFO Request handled                          duration=1.57978ms method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSCA41HH9V4ASGC7QNPC18W response_size=248 status=401 url=/oauth/api/me

Finally, after I enter the user id and password and click Login, I see this:

stack_1      |  DEBUG Run database query                       duration=75ms namespace=identityserver query=SELECT users.id, users.created_at, users.updated_at, password FROM "users" LEFT JOIN accounts ON accounts.account_type = $1 AND accounts.account_id = users.id WHERE "users"."deleted_at" IS NULL AND ((accounts.uid = $2)) ORDER BY "users"."id" ASC LIMIT 1 rows=1 source=user_store.go:121 values=[user admin]
stack_1      |  DEBUG Run database query                       duration=3ms namespace=identityserver query=SELECT * FROM "accounts"  WHERE "accounts"."deleted_at" IS NULL AND (("account_id" IN ($1) AND "account_type" = $2)) ORDER BY "accounts"."id" ASC rows=1 source=user_store.go:121 values=[f67caa0e-b52c-462e-b518-20c8aab2bf7b user]
stack_1      |  DEBUG Run database query                       duration=4ms namespace=identityserver query=SELECT users.id FROM "users" LEFT JOIN accounts ON accounts.account_type = $1 AND accounts.account_id = users.id WHERE "users"."deleted_at" IS NULL AND ((accounts.uid = $2)) ORDER BY "users"."id" ASC LIMIT 1 rows=1 source=store.go:57 values=[user admin]
stack_1      |  DEBUG Run database query                       duration=17ms namespace=identityserver query=INSERT INTO "user_sessions" ("created_at","updated_at","user_id","expires_at") VALUES ($1,$2,$3,$4) RETURNING "user_sessions"."id" rows=1 source=store.go:70 values=[2020-01-29 19:29:12.669 +0000 UTC 2020-01-29 19:29:12.669 +0000 UTC f67caa0e-b52c-462e-b518-20c8aab2bf7b <nil>]
stack_1      |   INFO Request handled                          duration=157.624378ms method=POST namespace=web remote_addr=pc_ip:61768 request_id=01DZSCETBD645J1D6VRYY1NENF response_size=0 status=204 url=/oauth/api/auth/login
stack_1      |  DEBUG Run database query                       duration=2ms namespace=identityserver query=SELECT users.id FROM "users" LEFT JOIN accounts ON accounts.account_type = $1 AND accounts.account_id = users.id WHERE "users"."deleted_at" IS NULL AND ((accounts.uid = $2)) ORDER BY "users"."id" ASC LIMIT 1 rows=1 source=store.go:57 values=[user admin]
stack_1      |  DEBUG Run database query                       duration=2ms namespace=identityserver query=SELECT * FROM "user_sessions"  WHERE ("user_sessions"."id" = $1) AND ("user_sessions"."user_id" = $2) rows=1 source=user_session_store.go:88 values=[8388df94-bb5b-461a-9d0b-fac4fef0f878 f67caa0e-b52c-462e-b518-20c8aab2bf7b]
stack_1      |  DEBUG Run database query                       duration=16ms namespace=identityserver query=SELECT * FROM "clients"  WHERE "clients"."deleted_at" IS NULL AND ((client_id = $1)) ORDER BY "clients"."id" ASC LIMIT 1 rows=1 source=client_store.go:113 values=[console]
stack_1      |  DEBUG Run database query                       duration=18ms namespace=identityserver query=SELECT * FROM "attributes"  WHERE ("entity_id" IN ($1) AND "entity_type" = $2) ORDER BY "attributes"."id" ASC rows=0 source=client_store.go:113 values=[2b538685-3948-427b-b6f7-afa97e7be601 client]
stack_1      |  DEBUG Run database query                       duration=1ms namespace=identityserver query=SELECT clients.id FROM "clients"  WHERE "clients"."deleted_at" IS NULL AND ((client_id = $1)) ORDER BY "clients"."id" ASC LIMIT 1 rows=1 source=store.go:57 values=[console]
stack_1      |  DEBUG Run database query                       duration=1ms namespace=identityserver query=SELECT users.id FROM "users" LEFT JOIN accounts ON accounts.account_type = $1 AND accounts.account_id = users.id WHERE "users"."deleted_at" IS NULL AND ((accounts.uid = $2)) ORDER BY "users"."id" ASC LIMIT 1 rows=1 source=store.go:57 values=[user admin]
stack_1      |  DEBUG Run database query                       duration=16ms namespace=identityserver query=SELECT * FROM "client_authorizations"  WHERE ("client_authorizations"."client_id" = $1) AND ("client_authorizations"."user_id" = $2) ORDER BY "client_authorizations"."id" ASC LIMIT 1 rows=1 source=oauth_store.go:103 values=[2b538685-3948-427b-b6f7-afa97e7be601 f67caa0e-b52c-462e-b518-20c8aab2bf7b]
stack_1      |  DEBUG Run database query                       duration=1ms namespace=identityserver query=UPDATE "client_authorizations" SET "created_at" = $1, "updated_at" = $2, "client_id" = $3, "user_id" = $4, "rights" = $5  WHERE "client_authorizations"."id" = $6 rows=1 source=oauth_store.go:115 values=[2020-01-24 22:42:03.173 +0000 UTC 2020-01-29 19:29:12.808 +0000 UTC 2b538685-3948-427b-b6f7-afa97e7be601 f67caa0e-b52c-462e-b518-20c8aab2bf7b {[RIGHT_ALL] {} 0} 871d2811-51b3-4ad7-873e-6833282eb1cb]
stack_1      |  DEBUG Run database query                       duration=1ms namespace=identityserver query=SELECT clients.id FROM "clients"  WHERE "clients"."deleted_at" IS NULL AND ((client_id = $1)) ORDER BY "clients"."id" ASC LIMIT 1 rows=1 source=store.go:57 values=[console]
stack_1      |  DEBUG Run database query                       duration=2ms namespace=identityserver query=SELECT users.id FROM "users" LEFT JOIN accounts ON accounts.account_type = $1 AND accounts.account_id = users.id WHERE "users"."deleted_at" IS NULL AND ((accounts.uid = $2)) ORDER BY "users"."id" ASC LIMIT 1 rows=1 source=store.go:57 values=[user admin]
stack_1      |  DEBUG Run database query                       duration=18ms namespace=identityserver query=INSERT INTO "authorization_codes" ("created_at","updated_at","client_id","user_id","rights","code","redirect_uri","state","expires_at") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING "authorization_codes"."id" rows=1 source=store.go:70 values=[2020-01-29 19:29:12.789 +0000 UTC 2020-01-29 19:29:12.839 +0000 UTC 2b538685-3948-427b-b6f7-afa97e7be601 f67caa0e-b52c-462e-b518-20c8aab2bf7b {[RIGHT_ALL] {} 0} MF2XI.XQS7DKRCVUL6VGAM56QVWVLJC2ATXZKHL74LZNA.FV57FSVS2IZ4FJ5YDIKYP4WOTIEDNIDQLQNKNRJXVZCIR5KAO7YQ /console/oauth/callback NkJcx6v_UHD3L_1z 2020-01-29 19:34:12.789231182 +0000 UTC]
stack_1      |   INFO Request handled                          duration=140.075216ms location=/console/oauth/callback?code=MF2XI.XQS7DKRCVUL6VGAM56QVWVLJC2ATXZKHL74LZNA.FV57FSVS2IZ4FJ5YDIKYP4WOTIEDNIDQLQNKNRJXVZCIR5KAO7YQ&state=NkJcx6v_UHD3L_1z method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSCETH8HPVWWW7ZYPTHXZ97 response_size=0 status=302 url=/oauth/authorize?client_id=console&redirect_uri=%2Fconsole%2Foauth%2Fcallback&response_type=code&state=NkJcx6v_UHD3L_1z
stack_1      |  ERROR Request error                            duration=1.44237ms method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSCETNWWY9G6ZAS88R4WKDV response_size=2286 status=500 url=/console/oauth/callback?code=MF2XI.XQS7DKRCVUL6VGAM56QVWVLJC2ATXZKHL74LZNA.FV57FSVS2IZ4FJ5YDIKYP4WOTIEDNIDQLQNKNRJXVZCIR5KAO7YQ&state=NkJcx6v_UHD3L_1z
stack_1      |   INFO Request handled                          duration=1.571086ms method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSCETWZ18QVNM88077KBRSZ response_size=253 status=401 url=/console/api/auth/token
stack_1      |   INFO Request handled                          duration=1.397057ms method=POST namespace=web remote_addr=pc_ip:61768 request_id=01DZSCETY2KQKJM0VDSNRKVY29 response_size=249 status=403 url=/console/api/auth/logo

It redirects me to a page showing "Internal Server Error" and gets stuck there.

What do you want to see instead?

Successful login to the console

Environment

Ubuntu 18.04.3 LTS (Bionic Beaver)

The Things Stack for LoRaWAN: ttn-lw-stack
Version:             3.5.1
Build date:          2020-01-29T11:11:22Z
Git commit:          35c639db4
Go version:          go1.13.7
OS/Arch:             linux/amd64

How do you propose to implement this?

...

Can you do this yourself and submit a Pull Request?

...

[zamashal]

After troubleshooting cookies and site permissions, I was able for once to get to this screen:

Nothing further and errors I mentioned earlier came back.

[johanstokking]

It looks like you fixed it yourself! Please reopen if I misunderstood.

[zamashal]

Hey @johanstokking - sorry for the misunderstanding. It's actually not fixed and I still get the error mentioned. I am not able to access the console because after login I keep hitting an "Internal Server Error" page. Also, after I delete all the cookies and start fresh, I am able to log in the first attempt, but I only get to the blank screen that I shared above without being able to access the console. Hope that clears up the current situation.

Thanks and I would appreciate your feedback on this!

[johanstokking]

stack_1      |  ERROR Request error                            duration=1.44237ms method=GET namespace=web remote_addr=pc_ip:61768 request_id=01DZSCETNWWY9G6ZAS88R4WKDV response_size=2286 status=500 url=/console/oauth/callback?code=MF2XI.XQS7DKRCVUL6VGAM56QVWVLJC2ATXZKHL74LZNA.FV57FSVS2IZ4FJ5YDIKYP4WOTIEDNIDQLQNKNRJXVZCIR5KAO7YQ&state=NkJcx6v_UHD3L_1z

Looks like we need to know why this request failed with 500; I think we're missing logging the error.

[htdvisser]

Perhaps we should start by making it possible to display the error details in the UI. When I made a typo in my configuration, I also got an unhelpful error without details, while those details were in fact available:

(the typo was that I configured The Things Stack to use https on port 1885)

[OladapoAjala]

I have been able to access the console when I put in the full url (www.example.com) in my docker-compose.yml file. It works fine for me without HTTPS. I'm off to configuring with HTTPS wish me luck!

[zamashal]

@htdvisser, here is the output from my console (Chrome Browser): thethingsexample-1582139031550.log

[zamashal]

I have been able to access the console when I put in the full url (www.example.com) in my docker-compose.yml file. It works fine for me without HTTPS. I'm off to configuring with HTTPS wish me luck!

@OladapoAjala You are amazing! I changed the links from https to http in my docker-compose.yml and it worked! Thank you!

[johanstokking]

Can you guys provide the configuration (ttn-lw-stack config or the configuration settings)?

Also can you provide the full, clean log, preferably with log.level=debug (or TTN_LW_LOG_LEVEL=debug) from starting the stack and accessing the Console via https?

I'm a bit lost now what's wrong with your https setup. I'm not sure why there would be a 500 on https. Again, we can do better on the logging, and that is why this issue is open, but maybe there's an underlying error that we need to fix too.

[zamashal]

@johanstokking , I already have that included in my first comment: https://github.com/TheThingsNetwork/lorawan-stack/issues/1942#issue-557106729

Thanks for looking into this!

[johanstokking]

@zamashal we did numerous changes in the meantime; please reopen if this is still relevant.