Supabase•4y ago

How to debug auth requests?

I'm having an issue where /auth/v1/token suddenly returns 400. I've set an expiration window of 20 seconds. This originated after finding out that the supabase token disappears from localStorage. It's not clear why I received a 400 for this refreshToken, the path to this should indicate a successful request. Here's a video walking through the situation: https://share.cleanshot.com/mc6hDzOEoD7lzwk4ZSrk

CleanShot Cloud

cleanshot_09_13_at_15_15 2

Video uploaded to CleanShot Cloud

119 Replies

garyaustin•4y ago

Are you setting jwt expire to 20 seconds? I thought they were supposed to limit it to 120 seconds min as the automatic refresh kicks in 60 seconds before expiration, so less than 60 refreshes all the time. https://github.com/supabase/gotrue-js/pull/274#discussion_r855047291 Maybe something changed since then... Not sure that has anything to do with your error though.

GitHub

fix: refresh token race condition by thorwebdev · Pull Request #274...

What kind of change does this PR introduce? Prevent token refresh race conditions and trigger recoverAndRefresh on visibility change. What is the current behavior? Currently our syncing across mult...

miguel.eOP•4y ago

huh... yup setting it to 20 seconds in the supabase admin ui.

miguel.eOP•4y ago

https://github.com/supabase/gotrue-js/pull/278/files#r865630374 Looks like minimum is 30 seconds, but not enforced

GitHub

fix: token refresh retry offline + recover on visible by thorwebdev...

What kind of change does this PR introduce? In combination with supabase/gotrue#466 this PR should resolve the most critical token refresh issues, Fixes #226 Fixes supabase/supabase#6464 Maybe Fix...

garyaustin•4y ago

Looks like it is now set to 10 seconds before expiration in v1 and v2...

miguel.eOP•4y ago

right 10 seconds for expiry margin and 30 seconds for JWT expiry for whatever reason 30 secs minimum for JWT expiry is not enforced.

garyaustin•4y ago

Sorry for the side bar, I just had the 60/120 thing in my head from back then.

garyaustin•4y ago

https://github.com/supabase/gotrue-js/issues/323 just linking as I'm scanning stuff with 400 error

GitHub

Not possible to keep user signed in · Issue #323 · supabase/gotrue-...

Bug report Describe the bug The issues is that the user gets kicked off the app and needs to sign in again over and over. After checking the many threads on this issue, these are the two scenarios ...

miguel.eOP•4y ago

All good. I can't prove this yet, but in production, JWT expiry is set to a week and I have users with tokens removed. The only thing I can attribute this production issue to is the 400 invalid refresh token response that I just reproduced in the video (using a staging database). I can't check in prod, because of 1 day retention 😬 I'm tempted to move to v2, but I have other hurdles, like setAuth() being removed. But, v2 is just a javascript library upgrade, right? the backend has not upgraded to /v2 from what I can tell. Looking at supabase-js@v2 the AuthClient still points to /auth/v1.

garyaustin•4y ago

The backend handles both, if there is anything needed for it to handle, there are not two different gotrue server releases on the instances. They are removed from local storage?

miguel.eOP•4y ago

yup, PR#323 and https://github.com/supabase/supabase/issues/7676. All point to 400 errors. All discussions then point to the supabase@v2 upgrade. But from what I can tell it's just a library upgrade not api upgrade. yup, as you mentioned only one gotrue server The video I shared, to me, points to an API issue. side-note. I re-authenticated and left it running for about an hour. It just now failed

miguel.eOP•4y ago

miguel.eOP•4y ago

I'm curious how I could debug this further. With limited access to API logs, it seems I don't have many options The only way I can think of is running the gotrue server locally and trying to reproduce. ugh, such a headache 🤦

garyaustin•4y ago

I would generate an issue in github so a dev might see it, even if you keep looking at it. I've got a test server running and I come back the next day and it is still logged in on v1. My dev code is on v2.

miguel.eOP•4y ago

I was thinking a dev would see it here lol I'll create a github issue

garyaustin•4y ago

Maybe, but probably not, this is mainly user helping user, with team members dropping in. I've been running my test server at 120, I'll lower and see if I see anything.

garyaustin•4y ago

What browser are you testing under?
Started a 20 second run

miguel.eOP•4y ago

🙌 thanks! what version of supabase-js are you running? I'm on Chrome for Mac Version 105.0.5195.102 (Official Build) (x86_64)

garyaustin•4y ago

1.35.6. Windows Firefox and Chrome running for 50 minutes now. I think I saw in your video you are using your own local storage handler, any reason for that?

miguel.eOP•4y ago

the app is an extension. Come 2023, the background script for extensions will be moved to a service worker. Which means no access to window.localStorage. Similar to React Native, I had to use a different localStorage engine. So I'm using chrome's localStorage engine. Before I create the Github issue, I'm going to verify I'm able to reproduce the 400 status code with only one process. That's one thing I didn't verify. If this occurs with one process, or if this occurs when I have two supabase clients initialized. Meaning, 1 supabase client in the background and another in a content script. lol, nevermind. I spoke too soon. Only one process and I got the 400 status code, just now

garyaustin•4y ago

Both mine just passed an hour Pure javascript on my test server. So onething I see in your network tab is the failures are not going out (seemingly with the fast response time).

miguel.eOP•4y ago

I don't see how this could be an issue just in the context of an extension, but I'll see if in the next few days I can create a sample extension connected to supabse

miguel.eOP•4y ago

fast response time: what are you averaging? I'm staying below 150ms. Is that slow? Granted this is a free supabase instance.

miguel.eOP•4y ago

Issue - https://github.com/supabase/supabase/issues/8959

garyaustin•4y ago

In your video you had about 20 failures most were in less than 10 msec.

miguel.eOP•4y ago

Ah that was from disabling the network connection. So it triggered the request retry logic in supabase

garyaustin•4y ago

On your failing request are the headers apikey and authorization good? Mine are still running.

miguel.eOP•4y ago

apikey looks good and authorization bearer token looks good. To be clear, these two should match, right? Because they're matching for me

garyaustin•4y ago

Yes, plus that error is from gotrue server not gotrue-js so it got to the server.

miguel.eOP•4y ago

Mine are still running.

That's such a bummer, I'll have to isolate it to a sample extension to see if there's something with my code or extensions in general that causes this discrepancy correct, that 400 error originates from the server. Which is why I may have to run gotrue server locally to see if I can reproduce.

garyaustin•4y ago

user, token, err := models.FindUserWithRefreshToken(a.db, params.RefreshToken)
    if err != nil {
        if models.IsNotFoundError(err) {
            return oauthError("invalid_grant", "Invalid Refresh Token")
        }
        return internalServerError(err.Error())
    }

user, token, err := models.FindUserWithRefreshToken(a.db, params.RefreshToken)
    if err != nil {
        if models.IsNotFoundError(err) {
            return oauthError("invalid_grant", "Invalid Refresh Token")
        }
        return internalServerError(err.Error())
    }

Is the main spot... There is a banned case and one other dealing with rotation. Think it means the refresh token is not in the table that was last sent. Can you tell if the refreshes right before the failure were at 10 seconds (if you are running at 20)

miguel.eOP•4y ago

Maybe you could enlighten me here. Two tabs/processes with supabase run their token refresh logic. This would cause race conditions, but the server side consolidates duplicate requests to return the true refresh token. This shouldn't cause hiccups, right?

miguel.eOP•4y ago

thanks for sharing the snippet on the Go side I haven't been measuring time, let me see

garyaustin•4y ago

Supabase has a setting to deal with that. I think default is 10 seconds you can request the same refresh token.

miguel.eOP•4y ago

woah, how curious!

miguel.eOP•4y ago

and yup, wait time is 10 seconds

miguel.eOP•4y ago

The 10sec default imo should be enough of a window to avoid compromised refresh tokens

garyaustin•4y ago

You might be able to look in the auth refresh_token table right after failure (stop all access to make life easier). Sort in time order and see if you see the failing token with another token requested after it. Your symptom is what would happen if you "burned" the token somewhere else. Or easier look in the API log....

miguel.eOP•4y ago

nice! yeh, that's what I needed. A way to debug this. thanks for that suggestion. API logs didn't give me the information I needed, it didn't even show the refresh_tokens I have a hunch this is an issue I've created because of an orphaned content script that still has supabase-js active. Maybe...

garyaustin•4y ago

If either of mine error I'll let you know.

miguel.eOP•4y ago

cool, thanks. so far I've been good. Got these logs handy for debugging

miguel.eOP•4y ago

thanks once again! I'll be out shortly, but will definitely look at this tomorrow. I'll keep you posted

garyaustin•4y ago

Yeah I went to logs when I was debugging mobile devices with a token issue on power down mode.

miguel.eOP•4y ago

oh boy, got the 400 and no new tokens. It's the last one. The process just borks

miguel.eOP•4y ago

But at this point. I think it might have to do with the race condition. So I may have to upgrade to v2 after all.

garyaustin•4y ago

It says it is revoked. Hmmm

miguel.eOP•4y ago

Yeh I see a few 400 requests. Telling me several supabase clients attempted to refresh token. Unfortunately the API logs do not tell me which refresh_token caused the 400

miguel.eOP•4y ago

Yup and refresh token reuse interval is still on 10 seconds but according to your theory. I should have seen the new refresh_token, but instead I got zero

garyaustin•4y ago

Well if you requested the one before the last one, after the 10 second reuse setting, it probably wipes the chain. Any short interval API token POST events right before the failure?

miguel.eOP•4y ago

Any short interval API token POST events right before the failure?

That's the kicker, I have no POST events whatsoever to supabase. This extension is only using /auth, lol. It's a basic app for now, I have a branch that will use database tables, but I haven't merged that yet

garyaustin•4y ago

I meant auth/v1/token API calls. Is there one not on the 10 second interval right before the failure?

miguel.eOP•4y ago

oh yup, there were a few. I started to add more supabase instances to see if I could break the api But the very first /auth/v1/token should have revoked the refresh token and created a new one. But that never happend, as we saw in the auth.refresh_token table leading up until the 400, the database had the latest refresh_token at the top. I queried it a few time, while I had a live refresh token cycle

garyaustin•4y ago

Just saying if a token is reused somewhere else for that user after 10 seconds, I think the entire chain for that users gets invalidated, even tokens after that. I've got to run. Good luck

miguel.eOP•4y ago

yeh that makes sense. I'll review the API logs to see what metadata I can find. thanks!

garyaustin•4y ago

I'm stopping my runs. Over 3 hours and I added a second tab on one browser with same user. No issues.

miguel.eOP•4y ago

so I upgraded to v2 and it didn't last long 🤦

miguel.eOP•4y ago

going to report it in the Github issue Since you've had conversations with supabase devs. Are there any I can ping? It would be great if I could escalate this somehow

garyaustin•4y ago

kangmingtay is the main gotrue guy. I'm still thinking it is on your side, based on now v1/v2 failing and mine working for hours even with double tabs.
Also you might try to turn off reuse detection or set a much longer period to rule out something reusing a token that was used more than one cycle back.

miguel.eOP•4y ago

thanks. it sure could be me. If that's the case, what's the limit of "tabs" I could have open. That's something I have to find out. I'm running another test with double tabs. But my extension can run on 10s, even 100s of tabs. I didn't test that many when I got the 400, but I would have thought since multiTab issues were addressed, this wouldn't be a problem My only other approach is to isolate the supabase instance to only one process. That way I avoid any race conditions

garyaustin•4y ago

I might have time later to spin up a new instance just to make sure a few month old instance is not difference. I have all default settings in my init, I don't remember besides your localStorage handler if you had anything set.

miguel.eOP•4y ago

const browserStorageInterface: SupportedStorage = {
  async getItem(key: string): Promise<string | null> {
    const storage = await browser.storage.local.get(key);
    return storage?.[key];
  },
  setItem(key: string, value: string) {
    browser.storage.local.set({
      [key]: value,
    });
  },
  removeItem(key: string) {
    browser.storage.local.remove(key);
  },
};

const supabase = createClient(supabaseUrl, supabaseKey, {
  auth: {
    autoRefreshToken: true,
    persistSession: true,
    storage: browserStorageInterface,
  },
});

const browserStorageInterface: SupportedStorage = {
  async getItem(key: string): Promise<string | null> {
    const storage = await browser.storage.local.get(key);
    return storage?.[key];
  },
  setItem(key: string, value: string) {
    browser.storage.local.set({
      [key]: value,
    });
  },
  removeItem(key: string) {
    browser.storage.local.remove(key);
  },
};

const supabase = createClient(supabaseUrl, supabaseKey, {
  auth: {
    autoRefreshToken: true,
    persistSession: true,
    storage: browserStorageInterface,
  },
});

This is all I have, now on v2. But storage engine shouldn't really matter. fwiw, I'm not seeing any issues with two sb instances running since 12 mins ago. Which leads me to believe the gotrue server cant handle after a certain number of tabs

garyaustin•4y ago

Are they all using the same refresh tokens?

miguel.eOP•4y ago

yes and suddenly no. It's hard to explain... I'm trying to make sense of this right now. I'm going to attempt your approach of turning off reuse detection

miguel.eOP•4y ago

the only explanation I could come up with is that the timeout clock is not balanced with other instances, causing a clash with getting a new refresh token. I don't think the JWT expiry of 20 seconds is a real scenario test, but it shows stability concerns after a certain limit

garyaustin•4y ago

Yes, on 20 seconds, if the instability is random timing versus you have 10 seconds to get everything done on 100 tabs before something gives. The second is not real world. I'd have to look closer but I think the multitab stuff involved syncing and waiting for the other tab to finish (could be wrong)

miguel.eOP•4y ago

syncing would have been an ideal solution, but I doubt thats the case. Each tab is responsible for making a request to refresh token

garyaustin•4y ago

I'm on a vid chat, and this is just a quick glance, but how is this handled with an alternate storage method (v1)?

 /**
   * Listens for changes to LocalStorage and updates the current session.
   */
  private _listenForMultiTabEvents() {
    if (!this.multiTab || !isBrowser() || !window?.addEventListener) {
      return false
    }

    try {
      window?.addEventListener('storage', (e: StorageEvent) => {
        if (e.key === STORAGE_KEY) {
          const newSession = JSON.parse(String(e.newValue))
          if (newSession?.currentSession?.access_token) {
            this._saveSession(newSession.currentSession)
            this._notifyAllSubscribers('SIGNED_IN')
          } else {
            this._removeSession()
            this._notifyAllSubscribers('SIGNED_OUT')
          }

 /**
   * Listens for changes to LocalStorage and updates the current session.
   */
  private _listenForMultiTabEvents() {
    if (!this.multiTab || !isBrowser() || !window?.addEventListener) {
      return false
    }

    try {
      window?.addEventListener('storage', (e: StorageEvent) => {
        if (e.key === STORAGE_KEY) {
          const newSession = JSON.parse(String(e.newValue))
          if (newSession?.currentSession?.access_token) {
            this._saveSession(newSession.currentSession)
            this._notifyAllSubscribers('SIGNED_IN')
          } else {
            this._removeSession()
            this._notifyAllSubscribers('SIGNED_OUT')
          }

miguel.eOP•4y ago

So in v1, I disabled multiTab. So this logic is not executed In v2, my understanding of this logic is that it was removed vidchat with a supabase dev? If so, I'm happy to jump on the chat I may have something that may help. I'm noticing the refresh token expire_at timestamp is being adjusted sharing logs t1, t2, t3 indicates tab 1, 2, 3

11:26:6:793 -t1- auth.event:  TOKEN_REFRESHED 1663169166.793
11:26:6:793 -t1- new.token - expires in:  1663169187 2w3To_30sYO4jz3hsEe1qg
11:26:7:961 -t2- auth.event:  TOKEN_REFRESHED 1663169167.961
11:26:7:961 -t2- new.token - expires in:  1663169188 2w3To_30sYO4jz3hsEe1qg
11:26:15:263 -t3- auth.event:  TOKEN_REFRESHED 1663169175.263
11:26:15:263 -t3- new.token - expires in:  1663169195 2w3To_30sYO4jz3hsEe1qg
11:26:17:43 -t1- auth.event:  TOKEN_REFRESHED 1663169177.043
11:26:17:43 -t1- new.token - expires in:  1663169197 Gwz-MP20glWi7phSADOCWQ
11:26:18:228 -t2- auth.event:  TOKEN_REFRESHED 1663169178.228
11:26:18:228 -t2- new.token - expires in:  1663169198 Gwz-MP20glWi7phSADOCWQ
11:26:26:279 -t3- auth.event:  TOKEN_REFRESHED 1663169186.279
11:26:26:279 -t3- new.token - expires in:  1663169206 Gwz-MP20glWi7phSADOCWQ
POST https://kepynfotwvuetexxphcf.supabase.co/auth/v1/token?grant_type=refresh_token 400
11:26:27:318 -t1- auth.event:  TOKEN_REFRESHED 1663169187.318
11:26:27:318 -t1- new.token - expires in:  1663169207 cFCa5xrDMx2aj0XZf074Wg
POST https://kepynfotwvuetexxphcf.supabase.co/auth/v1/token?grant_type=refresh_token 400
11:26:28:413 -t2- auth.event:  TOKEN_REFRESHED 1663169188.413
11:26:28:413 -t2- new.token - expires in:  1663169208 cFCa5xrDMx2aj0XZf074Wg
POST https://kepynfotwvuetexxphcf.supabase.co/auth/v1/token?grant_type=refresh_token 400

11:26:6:793 -t1- auth.event:  TOKEN_REFRESHED 1663169166.793
11:26:6:793 -t1- new.token - expires in:  1663169187 2w3To_30sYO4jz3hsEe1qg
11:26:7:961 -t2- auth.event:  TOKEN_REFRESHED 1663169167.961
11:26:7:961 -t2- new.token - expires in:  1663169188 2w3To_30sYO4jz3hsEe1qg
11:26:15:263 -t3- auth.event:  TOKEN_REFRESHED 1663169175.263
11:26:15:263 -t3- new.token - expires in:  1663169195 2w3To_30sYO4jz3hsEe1qg
11:26:17:43 -t1- auth.event:  TOKEN_REFRESHED 1663169177.043
11:26:17:43 -t1- new.token - expires in:  1663169197 Gwz-MP20glWi7phSADOCWQ
11:26:18:228 -t2- auth.event:  TOKEN_REFRESHED 1663169178.228
11:26:18:228 -t2- new.token - expires in:  1663169198 Gwz-MP20glWi7phSADOCWQ
11:26:26:279 -t3- auth.event:  TOKEN_REFRESHED 1663169186.279
11:26:26:279 -t3- new.token - expires in:  1663169206 Gwz-MP20glWi7phSADOCWQ
POST https://kepynfotwvuetexxphcf.supabase.co/auth/v1/token?grant_type=refresh_token 400
11:26:27:318 -t1- auth.event:  TOKEN_REFRESHED 1663169187.318
11:26:27:318 -t1- new.token - expires in:  1663169207 cFCa5xrDMx2aj0XZf074Wg
POST https://kepynfotwvuetexxphcf.supabase.co/auth/v1/token?grant_type=refresh_token 400
11:26:28:413 -t2- auth.event:  TOKEN_REFRESHED 1663169188.413
11:26:28:413 -t2- new.token - expires in:  1663169208 cFCa5xrDMx2aj0XZf074Wg
POST https://kepynfotwvuetexxphcf.supabase.co/auth/v1/token?grant_type=refresh_token 400

miguel.eOP•4y ago

should the auth token expires_at property be changing?

miguel.eOP•4y ago

this is what I have for onAuthStateChanged

miguel.eOP•4y ago

I'll be out for the next hour. jumping into a call

miguel.eOP•4y ago

I mentioned Kang in the Github issue. Hopefully these logs are helpful to give him an idea what's up https://github.com/supabase/supabase/issues/8959#issuecomment-1247032665

GitHub

Getting 400 on /auth/v1/token?grant_type=refresh_token · Issue #895...

Bug report Describe the bug I'm having an issue where /auth/v1/token?grant_type=refresh_token suddenly returns 400. It's unclear what could cause this issue. When the token is appro...

garyaustin•4y ago

So if I look at your last trace correctly "you" are using the refresh token for the 3rd time right at the 10 second boundary (probably past so it violates reuse). On v1 with multitab on it updates all the refresh tokens to the latest and expire time resets, so they don't get reused (if I understand it correctly). Not sure how v2 deals with this case. If it is any consolation, I'm back to thinking it is a bug on v2. I just don't see anything to communicate to all tabs there is a new token from another tab in v2 and after 10 seconds if any tab uses the same token it dies. At startup they all fetch the stored refresh token, so start with same token. Seems to basic though to be right.

garyaustin•4y ago

https://github.com/supabase/gotrue-js/pull/366 In reading the release notes and this it is certainly possible they did not consider this case as they seemed focused on getSession working now that it is async. I don't think they replaced the multi-tab stuff with anything else, just eliminated the race condition that was an original problem.

GitHub

fix: remove unnecessary events and multi-tab by kangmingtay · Pull ...

What kind of change does this PR introduce? Remove unnecessary events emitted Remove multi-tab stuff because getSession() will always ensure that a valid session is returned or no session at all

garyaustin•4y ago

I guess the refresh timer synchronizes everything. Based on the time left in the jwt, no matter when you get it from localStorage it will refresh 10 seconds before expiration (or less if already less than 10 seconds). At one time I found a rounding error of one second in their almost expired case, and not sure they fixed it, but not sure how that comes into play with your traces. mainly for my reference adding the link here: https://github.com/supabase/gotrue-js/issues/272

GitHub

Token refresh time is likely set too "short" if less than 60 second...

Bug report In looking into another issue I found this code in gotrue.js: if (expiresAt) { const timeNow = Math.round(Date.now() / 1000) const expiresIn = expiresAt - timeNow const refreshDurationBe...

miguel.eOP•4y ago

So if I look at your last trace correctly "you" are using the refresh token for the 3rd time right at the 10 second boundary (probably past so it violates reuse).

Right, so refresh token is used for the 3rd time, but, if you notice that tab called the api to get that refresh token with a new expires_at property. It adjusted by +9 seconds. Unsure if that's expected, so I pinged Kang about that logic. Thanks for looking into v2 mutiTab logic. It was removed according to what I remember when reading the release notes for v2.

Deprecated and removed setting for multitab support because getSession() and gotrue’s reuse interval setting takes care of session management across multiple tabs

https://supabase.com/docs/reference/javascript/next/release-notes I had to change gears yesterday afternoon for another project I'm working on. But this has been bugging me haha. I'm thinking about locally installing supabase-js and adding sync logic for multiTabs. I've been thinking about a few ideas. Mainly one that revolves around localStorage. * Cache the first instance someone calls api/v1/auth to refresh tokens. Something like sb-sync-refresh-token. I haven't figured out what I'd store. I'm thinking something simple like TOKEN_REFRESHING. But will have to think through the stages of this process. Will I need additional metadata? * Any subsequent tabs will have to wait. Thinking polling mechanism * Once api/v1/auth resolves with new refresh token. It'll cache in sb-auth-token key in storage * subsequent tabs can then pull from storage with latest refresh token. Avoiding a request to the API It really bugs me the idea of depending on only one supabase instance. It feels like an anti-pattern. I would be limited in how I can request data in my extension. Hopefully I can get to this before the weekend, we'll see

garyaustin•4y ago

So it looks like the token expire does get reset for each token refresh, even for token refresh use. https://github.com/supabase/gotrue/blob/064a33182cdd24938810dc75a88252d5ccfb3996/api/token.go#L241

tokenString, terr = generateAccessToken(user, newToken.SessionId, time.Second*time.Duration(config.JWT.Exp), config.JWT.Secret)

GitHub

gotrue/token.go at 064a33182cdd24938810dc75a88252d5ccfb3996 · supab...

A JWT based API for managing users and issuing JWT tokens - gotrue/token.go at 064a33182cdd24938810dc75a88252d5ccfb3996 · supabase/gotrue

garyaustin•4y ago

If correct then if you reuse a token several seconds after the others your refresh timer for that use could go off later than the others. If this drifts to around 10 seconds (you still get a reuse) you will likely be at the edge of the next reuse window with rounding and such. I relooked at the refresh timer code and it rounds up or down by a second depending on how close the date.now() is to .5. That one second difference when you are already firing the timer 9 seconds or so after the "others" could put you over the edge.

garyaustin•4y ago

I was able to somewhat force an error with two tabs at 30 second/10 second reuse. Basically I put a timeout in at 20 seconds (30-10expiremargin-10reusemax) less than the initial expire time from getSession. Let 1 tab start running for a few cycles then start the next tab. When it runs about 10 seconds out of phase with the first tab on refresh cycles it hits the 400 fairly quickly. The problem is I have to try a couple of times to get the timers right around 10 seconds. Need to figure out a better way to set the delay of one tab from the other by about 10 seconds to show the error more easily. 1) tab 1 refresh and gets token1 2) tab 2 starts up and gets session from localStorage with token1 3) tab 2 is forced to getSession at 10 seconds before expire of tab 1 to simulate starting up right around 10 seconds before expire. It burns token 1 and gets token 2. 4) tab 1 tries to refresh the original token 1 and can not as reuse window is up. The question is the a real world simulation of tabs out of sync? 30 seconds does not matter here, could be 1 hour. Key is the use of the token 10 seconds before the other tab.

garyaustin•4y ago

I'm not sure this is an edge case at all in my test above. I ran it with 60/10 and setSession at 30 seconds. Fails immediately. It appears if you start up two tabs that share a refresh token and do setSession() anytime before the reuse window of the other tab refreshing, it fails when the other tab trys to timer refresh. Makes sense as the setSession burned the token and in v2 the other tab does not know. So the question is can a similar thing happen just based on when you start a tab, or move between tabs?

garyaustin•4y ago

I went ahead and documented an issue with using setSession in multitab situations in v2. It won't work. I don't think this is directly related to your issue, but likely the same solution would be needed to fix it (unless they just say don't use setSession in multi-tab. I think there is a timing issue beyond this you are hitting. https://github.com/supabase/gotrue-js/issues/441

GitHub

setSession cannot be used in a multi-tab situation (v2) · Issue #44...

Bug report Describe the bug With two or more tabs running with a shared refresh token from localStorage, setSession will get a new refresh token and invalidate the first shared token if after the r...

garyaustin•4y ago

This PR is interesting... mentions working on the token refresh https://github.com/supabase/gotrue/pull/663

GitHub

feat: add hashed refresh tokens by hf · Pull Request #663 · supabas...

Today refresh tokens are stored raw in the database. Should the database be stolen, leaked or misused by an external or internal party, it would be nearly trivial to issue a valid access token for ...

miguel.eOP•4y ago

Thanks for providing details in the issue ticket I created and sharing with me this latest PR. I cross posted the issue I created with that PR. Maybe that can provide more details to the core team

garyaustin•4y ago

Hey I've also got a failure that occurs (which is likely your issue) when you start a tab, then start another tab right at the 10 seconds to expire point. I've got a delay setup and use localStorage to set start time on first tab and then second tab uses that to delay 20 seconds (using 30 second expire) from the other. This causes the first refresh right as the other tab is refreshing. I can get 400 errors regularly (but still somewhat random). I believe there is a timing/rounding issue if you refresh right at the 10 seconds left mark. Their formula using time left to expire or .5 with around 10 seconds left I think is flawed do to rounding and the 500msec to 1 second time on the wire. But I'm trying to get it more reproduceable so it is obvious. Good beer drinking, football watching activity....

garyaustin•4y ago

OK one more: https://github.com/supabase/gotrue-js/issues/442 I think this can be masked by making the resuse interval several seconds longer than the 10 second expire margin. But I thought I saw you running a test with 15 second expire, so there maybe something else....

GitHub

2nd Tab starting 10 seconds before expiration of session can cause ...

Bug report Describe the bug If a tab is running and a second tab starts up with createClient (or possibly becoming visible ... not tested) 10 seconds before expiration of session, a timing rounding...

miguel.eOP•4y ago

right on. Yeh I had a reuse interval of 15 seconds and getting a 400. Glad to see though that you're now encountering the issue, that's a good sign, we're narrowing down to the culprit.

garyaustin•4y ago

I pointed out this timing issue with a chart a long time ago from a jwt expiration issue and still believe it is there. Just is very rare to have a tab come back 9.5 seconds before expiration and then issue a request 9.5 seconds later (probably 100msec either way window) for failure. That is a single tab issue. Looks like the timing issue at the boundary to request would require a wire delay of a bit more than 1 second. I used an rpc call returning time and constantly can see 1.2 seconds to the jwt being expired. Not sure why they want to cut it that close, but I can't break it.

pixtron•4y ago

@miguel.e aren't browser.storage.local.set and browser.storage.local.remove async methods? Won't fix your issue, but might be correct thing to await them as well.

miguel.eOP•4y ago

@pixtron, you're correct, those methods are asynchronous. Thanks for pointing that out. Wouldn't be a bad idea to await those calls.

miguel.eOP•4y ago

Hey @garyaustin, I'd love to get your thoughts on this change. I've been running this change locally for half a day without any hiccups. No 400 errors! I'll be pushing a change to production once I've tested this for a couple of days and see how well it performs. https://github.com/supabase/gotrue-js/pull/444

GitHub

Support refresh token syncing for multiple tabs by miguelespinoza ·...

What kind of change does this PR introduce? This change introduces a mechanism to sync refresh tokens at the client level, rather than depending on the backend. The current behavior of supabase-js ...

garyaustin•4y ago

I'd use 12 seconds for your reuse in production just to pad past the 10 seconds refresh boundary. I just skimmed and will look more tomorrow, but v1 multitab mode synced all the refresh tokens thru local storage I thought. Is this more than that? (if it is clear in your code don't bother to answer as like I said I just glanced tonite).

miguel.eOP•4y ago

12 second isn't a bad idea. I noticed the timeout executing a few milliseconds before the 10 second refresh boundary. So I padded with 500 milliseconds, but 12 seconds would more than cover that window. I added implementation details in the PR for clarity on the change. Let me know if you have any questions 🙂

garyaustin•4y ago

On chrome/edge and I'm sure mobile, timers get throttled in background. https://developer.chrome.com/blog/timer-throttling-in-chrome-88/#intensive-throttling You have potentially alot of timers that will get throttled to 1 minute (realtime breaks in background because of loss of heartbeat for instance). Need to think thru what that could do here. Also on mobile these tabs might not run at all until they become visible again. gotrue-js added a check for coming back from hidden recently.

Chrome Developers

Heavy throttling of chained JS timers beginning in Chrome 88 - Chro...

Intensive throttling takes effect when the page has been hidden for more than 5 minutes, the page has been silent for at least 30 seconds, WebRTC is not in use, and the chain of timers is 100 or greater.

miguel.eOP•4y ago

thanks for sharing. They have a section for this actually, State Polling: https://developer.chrome.com/blog/timer-throttling-in-chrome-88/#state-polling The original multiTab had this approach, I'm curious why it was removed. Granted when I opted-in for the option, I still had issues.

Chrome Developers

Heavy throttling of chained JS timers beginning in Chrome 88 - Chro...

miguel.eOP•4y ago

I didn't know realtime breaks in background. I had originally thought of doing something like that. Take a break on refresh logic until user returns. Maybe that's a less intensive way of handling multitabs

garyaustin•4y ago

I shut down my realtime code at 5 minutes, or error and in background, just to save resources anyway with connections doing nothing. Then on visible restart with initial load. I don't do it on just hidden because you could just be tabbing to check discord and coming right back...

miguel.eOP•4y ago

yup, makes sense. I'll add a comment about this in the PR. Hopefully we can start working towards a solution that we can all agree on

pixtron•4y ago

Thats actually - combined with the rounding errors - why we see that many 400 errrors.

pixtron•4y ago

@miguel.e had a glance at your PR. My gut feeling tells me that it introduces a bunch of new timing issues. Wouldn't it be better to just, check here if there is a new session in storage? The refresh token passed in by the session might be expired when the actual timeout fires: https://github.com/supabase/gotrue-js/blob/a15296288d15919d2ec8a64654a545a375fb3a57/src/GoTrueClient.ts#L911-L924

GitHub

gotrue-js/GoTrueClient.ts at a15296288d15919d2ec8a64654a545a375fb3a...

An isomorphic Javascript library for GoTrue. Contribute to supabase/gotrue-js development by creating an account on GitHub.

pixtron•4y ago

Another thing: if i pass a custom InMemoryStorage i won't need the checks at all. So my thinking goes that handling multitab is related to the storage in use. Therefore the actual storage should implement the handling of expired refresh tokens. Eg for local storage this could be solved with storage events (https://developer.mozilla.org/en-US/docs/Web/API/Window/storage_event) or eventually with a SharedWorker (https://developer.mozilla.org/en-US/docs/Web/API/SharedWorker?retiredLocale=de). For your case this could potentially solved with storage.onChanged event (https://developer.mozilla.org/en-US/docs/Mozilla/Add-ons/WebExtensions/API/storage/onChanged) or a SharedWorker as well. Not sure how that would be solved in ract native (is there even a multitab scenario?). Also take note that supbase-js tries to be an isomorphic library that could as well be used in a long running node.js proces s(eg express server).

miguel.eOP•4y ago

Thanks for your thoughts @pixtron. If you don't mind could you publish these comments in the PR. I want to consolidate this into one thread so we can work towards a solution and leave a trail for others having this same issue. You're 100% right, even though this solution has been working for me for the past two days, we have to consider other strategies that are optimal for capturing most use cases. Thanks for pointing this out. One consideration was to add a flag refreshTokenSync so you have to opt-in to this behavior. But the timing issue that's been mentioned, I started to think about this yesterday and we're already bound to one timeout which is used to kick off a network request 10 seconds before expiration. At most if a network request takes longer than the sync poll interval, let's say a 500 ms request with 5 tabs. There are 4 tabs waiting for roughly 4-5 interval cycles. Unless we use exponential backoff. More often a network request fulfills on average in 150ms. So that's 1 cycle on the interval. But I hear you on timing concerns, specifically with the throttling behavior of browsers. That throttling though also applies to the timeout set for firing a refresh token call to the API, so there's something to be said about that. If I understood you correctly "Thats actually - combined with the rounding errors - why we see that many 400 errrors." Were you referring to the throttling behavior of browsers? Because I would have to disagree, from my testing, the 400 error just occurs from thrashing the server with multiple request. Which is an intended behavior by the supabase library. "Let the backend reconcile refresh tokens for multiple requests from multiple tabs". Which would be fine if the backend reconciliation was stable, but there's a flaw. More details can be found in this issue comment: https://github.com/supabase/supabase/issues/8959#issuecomment-1247032665 So here's my realization. For a chrome extension that uses supabase on multiple tabs. I need to opt-out of autoRefreshToken and handle that on my own, using browser native methods. * Instead of a setTimeout. Use chrome.alarm to trigger an event 10 seconds before token expiration * Refresh token manually * Update that in storage * storage.onChange picks up the new token in other tabs. This is what you mentioned @pixtron so we're aligned with that solution. I'm still wondering why supabase removed multiTab local storage events support from v2 🤷‍♂️ . It's not the same interface as chrome.storage.onChange but I could have leveraged that logic to add an abstract version of onChange idk, waiting on a response from the core team on that decision.

pixtron•4y ago

from my testing, the 400 error just occurs from thrashing the server with multiple request

When you trash the server with too many requests, you get a a 429 http status with {"code":429,"msg":"Rate limit exceeded"} as response body. (Needs ~15-20 requests at the same time). There is the setting "Reuse Interval" which defaults to 10 seconds. If you use Token A at 12:00:00.000 you get a new access token and a new refresh token B. You can still use Token A until 12:00:10.000 to mint new access tokens. But if you use Token A after 12:00.10.001 you get a 400 error. Most likely that is why you see the 400 error. To better debug this scenario, you can add a console.log in gotrue-js _startAutoRefreshToken

_startAutoRefreshToken(value, session) {
  console.log('Starting auto Refresh', {value, at: (new Date(Date.now() + value)).toISOString()});

_startAutoRefreshToken(value, session) {
  console.log('Starting auto Refresh', {value, at: (new Date(Date.now() + value)).toISOString()});

If I understood you correctly "Thats actually - combined with the rounding errors - why we see that many 400 errors." Were you referring to the throttling behavior of browsers?

Im able to create 10 supabase clients at random intervals in one tab. They all sync up to refresh at the "same" time in a window of ~1-2 seconds. In this 10 independent clients in one single tab i never see 400 errors. As soon i start creating clients in multiple tabs the timing of refresh requests start to diverge over time. At the beginning they are in said ~1-2 seconds window but as longer the tabs are "backgrounded" the more the timing of the refresh requests start to diverge. Until a point where one tab uses Token A 10s before another tab uses Token A.

garyaustin•4y ago

@pixtron That is what I sort of forced here with just 2 tabs with one starting about 10 before expire. https://github.com/supabase/gotrue-js/issues/442 Some times it runs a few cycles but drifts out of the 10 second window.

GitHub

2nd Tab starting 10 seconds before expiration of session can cause ...

pixtron•4y ago

was actually starting with your work for my tests. Probably also depends on CPU usage of your operating system how long it takes until the tabs diverge too much. But it deinetly only happens when tabs are "backgrounded"

garyaustin•4y ago

The whole timer thing is a bit of mess. It is also counting on about 1 second margin for sending the request before the jwt expires mainly because of the 9.5 second round up, which puts it right on edge.

pixtron•4y ago

I agree this has to be fixed somehow. Maybe leader election and communication via postMessage is the way to go.

garyaustin•4y ago

I was mentioning to Miguel that an approach to check before use might be more reliable as you can sit on the operation until you get the refresh back. Then you just sync that operation with other tabs to limit the tabs doing the refresh. The weak link is realtime has to get notified of the change too.

miguel.eOP•4y ago

I recently posted a solution using chromes native alarm api and it's been working like a charm. https://github.com/supabase/gotrue-js/pull/444#issuecomment-1254141344 This has the benefit of relying on one process for the refresh token logic, much like the idea of leader election. One neat feature of supabase v2, is that fetch reconciles the auth token for header usage. So if you can isolate the refresh token logic to one process, fetch takes care of the rest for the remainder tabs. I'm not sure if realtime has the same behavior... that would have to be verified direct link to gist: https://gist.github.com/miguelespinoza/59d8dc57aaeae27ffac87989f06e8f0e

pixtron•4y ago

Realtime doesn't need to be handled in gotrue-js. supbase-js listens on the onAuthStateChanged event and notifies realtime: https://github.com/supabase/supabase-js/blob/rc/src/SupabaseClient.ts#L268-L294

miguel.eOP•4y ago

fetchWithAuth handles getting latest refresh token for any supabase request - https://github.com/supabase/supabase-js/blob/v2.0.0-rc.10/src/SupabaseClient.ts#L117

garyaustin•4y ago

Yeah except if you get rid of the timer and do it on demand... then realtime has nothing to update it... limited to my idea of ondemand refresh not timer. The jwt expires and there is no timer to refresh it for realtime.

pixtron•4y ago

Belive me you really don't want onDemand refresh. Been stuck in that hell before in another project 😄

garyaustin•4y ago

@miguel.e your api for the alarm api is ios 15 or later?

miguel.eOP•4y ago

the alarm api is for chrome extensions. Not mobile apps. https://developer.chrome.com/docs/extensions/reference/alarms/

pixtron•4y ago

There would also be Web Locks API that might be useful in this case. It is still experimental but browser support seems to be quite good already. https://developer.mozilla.org/en-US/docs/Web/API/Web_Locks_API So either a locking or Leader Election will be the final solution.

miguel.eOP•4y ago

I remember encountering Web Locks, but being that it was experimental it gave me a fuzzy feeling haha. Leader election makes sense. It could be as simple as the most recent tab in the foreground becomes the leader and handles network request. side note: day two with chrome alarm API support for refreshing token and still running 🙌

pixtron•4y ago

there are libraries out there for leader election. Probably quite some edge cases to handle as well.

Gaming

Programming

How to debug auth requests?

Did you find this page helpful?