search

supabase / auth

A JWT based API for managing users and issuing JWT tokens
https://supabase.com/docs/guides/auth
MIT License
1.54k stars 373 forks source link

`token_revoked` with large-ish `raw_app_meta_data` #1416

Closed donalffons closed 6 months ago

donalffons commented 9 months ago

In my application, I'm setting a relatively large amount of data in raw_app_meta_data (containing user roles) and ran into issues, where supabase would sign me out immediately after I had signed in. There are no errors in the logs, only this message:

 supabase-auth            | {"auth_event":{"action":"token_revoked","actor_id":"80d9bddd-b54e-4a68-b534-4082a982477b","actor_name":"Firstname Lastname","actor_username":"firstname.lastname@domain.com","actor_via_sso":false,"log_type":"token"},"component":"api","duration":11616508,"level":"info","method":"POST","msg":"request completed","path":"/token","referer":"http://localhost:3000/","remote_addr":"88.74.xxx.xx","status":200,"time":"2024-02-10T20:48:30Z","timestamp":"2024-02-10T20:48:30Z"}

I was able to reproduce that by changing the size of raw_app_meta_data. In my test, the issue starts appearing around the mark of 800 x letters:

UPDATE auth.users
SET raw_app_meta_data = '{"test": "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}'
WHERE id = '80d9bddd-b54e-4a68-b534-4082a982477b';

Is there a defined limit for the size of this field (I couldn't find one)? Is there a way to change this limit?

hf commented 8 months ago

Hi @donalffons,

The issue you're facing is probably likely due to the limitation of the size of Cookies stored in the browser, instead of a backend limitation (there is none).

What do you use on the frontend?

donalffons commented 8 months ago

Thank you for getting back to me about this issue. I assumed (and might have read somewhere) that gotrue splits up large tokens into multiple cookies.

I'm using keycloak as the authentication provider. I handle the sign-up using this code from the front-end:

supabase?.auth.signInWithOAuth({
  provider: "keycloak",
  options: {
    scopes: "openid",
    redirectTo: `${window.location.origin}/login`,
  },
});

After trying this again today, I cannot reproduce the token_revoked issue. Instead, I'm stuck in an infinite loop on sign-up. image

Here is a HAR dump of the network requests: localhost.har.tar.gz

It's unclear to me why the request to /login?code=... is being canceled...

These are the cookies that are being set: image It does look like some of the cookies are missing, here.

In case you have a suggestion on how to debug this further, please let me know. I'm using the Gotrue Image version supabase/gotrue:v2.145.0-rc.13.

hf commented 7 months ago

Could you please check the logs of the server, see what they say?

donalffons commented 7 months ago

The logs don't say anything suspicious...

supabase-auth  | {"component":"api","level":"info","method":"GET","msg":"request started","path":"/authorize","referer":"http://localhost:3000/login","remote_addr":"172.18.0.1","time":"2024-03-26T08:49:55Z","timestamp":"2024-03-26T08:49:55Z"}
supabase-auth  | {"component":"api","level":"info","method":"GET","msg":"Redirecting to external provider","path":"/authorize","provider":"keycloak","referer":"http://localhost:3000/login","remote_addr":"172.18.0.1","time":"2024-03-26T08:49:55Z","timestamp":"2024-03-26T08:49:55Z"}
supabase-auth  | {"component":"api","duration":11639958,"level":"info","method":"GET","msg":"request completed","path":"/authorize","referer":"http://localhost:3000/login","remote_addr":"172.18.0.1","status":302,"time":"2024-03-26T08:49:55Z","timestamp":"2024-03-26T08:49:55Z"}
supabase-auth  | {"component":"api","level":"info","method":"GET","msg":"request started","path":"/callback","referer":"https://www.deag.cloud/","remote_addr":"172.18.0.1","time":"2024-03-26T08:49:55Z","timestamp":"2024-03-26T08:49:55Z"}
supabase-auth  | {"auth_event":{"action":"login","actor_id":"3b89c7c8-1d95-4bed-8d19-55f92711d4cd","actor_username":"user@example.com","actor_via_sso":false,"log_type":"account","traits":{"provider":"keycloak"}},"component":"api","duration":11841630,"level":"info","method":"GET","msg":"request completed","path":"/callback","referer":"https://www.deag.cloud/","remote_addr":"172.18.0.1","status":302,"time":"2024-03-26T08:49:55Z","timestamp":"2024-03-26T08:49:55Z"}
supabase-auth  | {"component":"api","level":"info","method":"POST","msg":"request started","path":"/token","referer":"http://localhost:3000/","remote_addr":"172.18.0.1","time":"2024-03-26T08:49:56Z","timestamp":"2024-03-26T08:49:56Z"}
supabase-auth  | {"auth_event":{"action":"login","actor_id":"3b89c7c8-1d95-4bed-8d19-55f92711d4cd","actor_username":"user@example.com","actor_via_sso":false,"log_type":"account","traits":{"provider_type":"keycloak"}},"component":"api","duration":5352089,"level":"info","method":"POST","msg":"request completed","path":"/token","referer":"http://localhost:3000/","remote_addr":"172.18.0.1","status":200,"time":"2024-03-26T08:49:56Z","timestamp":"2024-03-26T08:49:56Z"}

The reason for the infinite loop in my code was a call to window.location.reload(), which I've commented out in the snippet below.

export default function SignIn() {
  const searchParams = useSearchParams();
  const supabase = useSupabaseBrowser();
  const isSigningInRef = useRef(false);
  const session = useSession();
  useEffect(() => {
    if (isSigningInRef.current || searchParams?.get("code") || searchParams?.get("error")) return;
    isSigningInRef.current = true;
    supabase?.auth.signInWithOAuth({
      provider: "keycloak",
      options: {
        scopes: "openid",
        redirectTo: `${window.location.origin}/login`,
      },
    });
  }, [supabase, searchParams]);

  useEffect(() => {
    const unsub = supabase.auth.onAuthStateChange((event, newSession) => {
      if ((session && !newSession) || (!session && newSession)) {
        // window.location.reload(); // This will trigger some server-side code to re-run, which redirects away from the login page if the user is already signed in
        console.log("session changed", { event, newSession });
      }
    });
    return () => unsub.data.subscription.unsubscribe();
  }, [session, supabase]);

  console.log({ session });
  // ...

This logs

Navigated to http://localhost:3000/login
{session: null}
{session: null}
Navigated to http://localhost:3000/login?code=da5f4bf3-4b07-41d2-bd08-ac2c4e6cf6f4
{session: null}
{session: null}
session changed {event: 'SIGNED_IN', newSession: {…}}
session changed {event: 'SIGNED_IN', newSession: {…}}

newSession appears to be a vaild session, with tokens etc. However, the useSession hook never returns a new session != null and it appears that this new session never propagates correctly. Now there are 3 cookies set for this page - and it appears that cookies .0 ... .3 are missing?! image

Apologies if this is getting confusing. I haven't seen the token_revoked issue again.

If I remove the large payload from raw_app_meta_data, remove the cookies and try signing in again, it works fine and I end up with 5 cookies image

Does this look more like a client-side or server-side issue to you? I'm a bit clueless...

kangmingtay commented 7 months ago

hi @donalffons, seems like you are using the supabase/ssr package? can you check if you are on the latest version (https://github.com/supabase/auth-helpers/releases/tag/%40supabase%2Fssr%400.1.0)? it contains a fix for the cookie chunking algorithm which should handle splitting large cookies correctly

donalffons commented 7 months ago

Thank you for pointing that out. Updating that package does improve the situation for me. However, my application still behaves incorrectly with large tokens. It looks like the session is handled inconsistently and incorrectly on the server and client (session is valid during ssr but then get's revoked client-side?!). I have to investigate that further and might open a new ticket for that issue. Thanks for your help, so far!

donalffons commented 7 months ago

Apologies for the confusion. After the package update, I can now reliably reproduce the initially mentioned token_revoked error message. Here are the relevant log outputs:

Apr 11 13:46:11 hostname docker[1344]: supabase-auth            | {"component":"api","level":"info","method":"GET","msg":"request started","path":"/user","referer":"https://www.example.com/","remote_addr":"172.18.0.9","time":"2024-04-11T13:46:11Z","timestamp":"2024-04-11T13:46:11Z"}
Apr 11 13:46:11 hostname docker[1344]: supabase-auth            | {"component":"api","duration":2894644,"level":"info","method":"GET","msg":"request completed","path":"/user","referer":"https://www.example.com/","remote_addr":"172.18.0.9","status":200,"time":"2024-04-11T13:46:11Z","timestamp":"2024-04-11T13:46:11Z"}
Apr 11 13:46:11 hostname docker[1344]: supabase-kong            | 172.18.0.9 - - [11/Apr/2024:13:46:11 +0000] "GET /auth/v1/user HTTP/1.1" 200 6127 "-" "Deno/1.40.3 (variant; SupabaseEdgeRuntime/1.40.0)" kong_request_id: "ee01754cc94db73dbd6cd32e6834a443"
Apr 11 13:46:11 hostname docker[1344]: supabase-auth            | {"component":"api","duration":1476073,"level":"info","method":"GET","msg":"request completed","path":"/admin/users/9bcd4517-fa0a-40eb-bf9c-0da7c977389f","referer":"https://www.example.com/","remote_addr":"172.18.0.9","status":200,"time":"2024-04-11T13:46:11Z","timestamp":"2024-04-11T13:46:11Z","user_id":"9bcd4517-fa0a-40eb-bf9c-0da7c977389f"}
Apr 11 13:46:11 hostname docker[1344]: supabase-kong            | 172.18.0.9 - - [11/Apr/2024:13:46:11 +0000] "GET /auth/v1/admin/users/9bcd4517-fa0a-40eb-bf9c-0da7c977389f HTTP/1.1" 200 6127 "-" "Deno/1.40.3 (variant; SupabaseEdgeRuntime/1.40.0)" kong_request_id: "e738405c0bf3986c761b5547ac5b332e"
Apr 11 13:46:11 hostname docker[1344]: supabase-auth            | {"component":"api","level":"info","method":"PUT","msg":"request started","path":"/admin/users/9bcd4517-fa0a-40eb-bf9c-0da7c977389f","referer":"https://www.example.com/","remote_addr":"172.18.0.9","time":"2024-04-11T13:46:11Z","timestamp":"2024-04-11T13:46:11Z"}
Apr 11 13:46:11 hostname docker[1344]: supabase-auth            | {"auth_event":{"action":"user_modified","actor_id":"00000000-0000-0000-0000-000000000000","actor_username":"service_role","actor_via_sso":false,"log_type":"user","traits":{"user_email":"user@example.com","user_id":"9bcd4517-fa0a-40eb-bf9c-0da7c977389f","user_phone":""}},"component":"api","duration":7729084,"level":"info","method":"PUT","msg":"request completed","path":"/admin/users/9bcd4517-fa0a-40eb-bf9c-0da7c977389f","referer":"https://www.example.com/","remote_addr":"172.18.0.9","status":200,"time":"2024-04-11T13:46:11Z","timestamp":"2024-04-11T13:46:11Z","user_id":"9bcd4517-fa0a-40eb-bf9c-0da7c977389f"}
Apr 11 13:46:11 hostname docker[1344]: supabase-kong            | 172.18.0.9 - - [11/Apr/2024:13:46:11 +0000] "PUT /auth/v1/admin/users/9bcd4517-fa0a-40eb-bf9c-0da7c977389f HTTP/1.1" 200 6127 "-" "Deno/1.40.3 (variant; SupabaseEdgeRuntime/1.40.0)" kong_request_id: "61357f6667981e55f618333b2d7d9b00"
Apr 11 13:46:11 hostname docker[1344]: supabase-kong            | 88.66.XXX.X - - [11/Apr/2024:13:46:11 +0000] "OPTIONS /auth/v1/token?grant_type=refresh_token HTTP/2.0" 200 0 "https://www.example.com/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" kong_request_id: "b80d883e7007d36d6a8fd436d0abd748"
Apr 11 13:46:11 hostname docker[1344]: supabase-auth            | {"component":"api","level":"info","method":"POST","msg":"request started","path":"/token","referer":"https://www.example.com/","remote_addr":"88.66.XXX.X","time":"2024-04-11T13:46:11Z","timestamp":"2024-04-11T13:46:11Z"}
Apr 11 13:46:11 hostname docker[1344]: supabase-auth            | {"action":"login","instance_id":"00000000-0000-0000-0000-000000000000","level":"info","login_method":"token","metering":true,"msg":"Login","time":"2024-04-11T13:46:11Z","user_id":"9bcd4517-fa0a-40eb-bf9c-0da7c977389f"}
Apr 11 13:46:11 hostname docker[1344]: supabase-auth            | {"auth_event":{"action":"token_revoked","actor_id":"9bcd4517-fa0a-40eb-bf9c-0da7c977389f","actor_name":"Donald Duck","actor_username":"user@example.com","actor_via_sso":false,"log_type":"token"},"component":"api","duration":21910188,"level":"info","method":"POST","msg":"request completed","path":"/token","referer":"https://www.example.com/","remote_addr":"88.66.XXX.X","status":200,"time":"2024-04-11T13:46:11Z","timestamp":"2024-04-11T13:46:11Z"}
Apr 11 13:46:11 hostname docker[1344]: supabase-kong            | 88.66.XXX.X - - [11/Apr/2024:13:46:11 +0000] "POST /auth/v1/token?grant_type=refresh_token HTTP/2.0" 200 13521 "https://www.example.com/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" kong_request_id: "057b713cc9efa348d2cf6d6404392234"

EDIT: The error seems to originate from here. What could be the root cause? Are there any limits on the size of the transaction?

donalffons commented 6 months ago

..apparently, I had some issues in the auth-flow code in my application. The following change fixed it for me:

    supabase?.auth.signInWithOAuth({
      provider: "keycloak",
      options: {
        scopes: "openid",
-        redirectTo: `${window.location.origin}/login`, // This was just redirecting back to my login page
+        redirectTo: `${window.location.origin}/auth/callback`, // see docs on how to implement the auth/callback route
      },
    });

Not sure how this ever worked :man_shrugging:.