Auth 0.38.0 causes panics and auth problems

[dionjwa]

This issue is causing all kinds of hard to debug auth issues. Downgrading auth to 0.37.1 solved the crashes reported below

[auth]
version = '0.38.0'

auth-1  | {"time":"2025-05-08T17:15:08.821332611Z","level":"INFO","msg":"call completed","trace":{"trace_id":"796273be-12f2-4c42-9171-0a8c8ffc7f58","span_id":"","parent_span_id":""},"request":{"client_ip":"127.0.0.1","method":"HEAD","url":"/healthz"},"response":{"status_code":200,"latency_time":936732,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:13.877288358Z","level":"INFO","msg":"call completed","trace":{"trace_id":"7acd5c4c-5045-4c73-b9c2-1e4b87f5fe0f","span_id":"","parent_span_id":""},"request":{"client_ip":"127.0.0.1","method":"HEAD","url":"/healthz"},"response":{"status_code":200,"latency_time":3474243,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:17.005800621Z","level":"ERROR","msg":"could not find user by refresh token","trace":{"trace_id":"f11d6976-6b61-4404-98be-0d23ee3be10a","span_id":"","parent_span_id":""},"request":{"client_ip":"192.168.147.1","method":"POST","url":"/v1/token"}}
auth-1  | {"time":"2025-05-08T17:15:17.005902294Z","level":"INFO","msg":"call completed","trace":{"trace_id":"f11d6976-6b61-4404-98be-0d23ee3be10a","span_id":"","parent_span_id":""},"request":{"client_ip":"192.168.147.1","method":"POST","url":"/v1/token"},"response":{"status_code":401,"latency_time":4734289,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:17.006203815Z","level":"ERROR","msg":"could not find user by refresh token","trace":{"trace_id":"910f3d14-2e21-45f6-808c-b2a49cb03f45","span_id":"","parent_span_id":""},"request":{"client_ip":"192.168.147.1","method":"POST","url":"/v1/token"}}
auth-1  | {"time":"2025-05-08T17:15:17.006269195Z","level":"INFO","msg":"call completed","trace":{"trace_id":"910f3d14-2e21-45f6-808c-b2a49cb03f45","span_id":"","parent_span_id":""},"request":{"client_ip":"192.168.147.1","method":"POST","url":"/v1/token"},"response":{"status_code":401,"latency_time":8276870,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:17.006249152Z","level":"ERROR","msg":"could not find user by refresh token","trace":{"trace_id":"cd12cb15-9532-4d35-9b4c-89ddf2302e27","span_id":"","parent_span_id":""},"request":{"client_ip":"192.168.147.1","method":"POST","url":"/v1/token"}}
auth-1  | {"time":"2025-05-08T17:15:17.006420497Z","level":"INFO","msg":"call completed","trace":{"trace_id":"cd12cb15-9532-4d35-9b4c-89ddf2302e27","span_id":"","parent_span_id":""},"request":{"client_ip":"192.168.147.1","method":"POST","url":"/v1/token"},"response":{"status_code":401,"latency_time":2189111,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:18.912408274Z","level":"INFO","msg":"call completed","trace":{"trace_id":"968afd46-0d42-4f36-9b57-c6418ccad398","span_id":"","parent_span_id":""},"request":{"client_ip":"127.0.0.1","method":"HEAD","url":"/healthz"},"response":{"status_code":200,"latency_time":1131663,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:23.931682123Z","level":"INFO","msg":"call completed","trace":{"trace_id":"cc6a2488-5ef3-48d4-92ff-ab16c7f8b370","span_id":"","parent_span_id":""},"request":{"client_ip":"127.0.0.1","method":"HEAD","url":"/healthz"},"response":{"status_code":200,"latency_time":734552,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:28.984665372Z","level":"INFO","msg":"call completed","trace":{"trace_id":"936aad1a-7400-472b-a89d-31747f876e81","span_id":"","parent_span_id":""},"request":{"client_ip":"127.0.0.1","method":"HEAD","url":"/healthz"},"response":{"status_code":200,"latency_time":4685411,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:31.215003704Z","level":"INFO","msg":"call completed","trace":{"trace_id":"59d85231-afd4-4815-b47a-1e73efb2b750","span_id":"","parent_span_id":""},"request":{"client_ip":"192.168.147.1","method":"POST","url":"/v1/signin/email-password"},"response":{"status_code":200,"latency_time":98504971,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:34.024451822Z","level":"INFO","msg":"call completed","trace":{"trace_id":"0c377361-3b01-4e01-a1a7-25e0986b43fa","span_id":"","parent_span_id":""},"request":{"client_ip":"127.0.0.1","method":"HEAD","url":"/healthz"},"response":{"status_code":200,"latency_time":1763457,"errors":null}}
auth-1  | {"time":"2025-05-08T17:15:37.55254315Z","level":"INFO","msg":"call completed","trace":{"trace_id":"4ef1e050-0905-4ea1-afdd-311cc203c441","span_id":"","parent_span_id":""},"request":{"client_ip":"192.168.147.1","method":"POST","url":"/v1/token"},"response":{"status_code":200,"latency_time":31117551,"errors":null}}
auth-1  |
auth-1  |
auth-1  | 2025/05/08 17:15:37 [Recovery] 2025/05/08 - 17:15:37 panic recovered:
auth-1  | runtime error: index out of range [0] with length 0
auth-1  | runtime/panic.go:115 (0x46903)
auth-1  | github.com/nhost/hasura-auth/go/controller/workflows.go:447 (0x813243)
auth-1  | github.com/nhost/hasura-auth/go/controller/post_token.go:33 (0x80b247)
auth-1  | github.com/nhost/hasura-auth/go/api/server.gen.go:1634 (0x75ccf7)
auth-1  | github.com/nhost/hasura-auth/go/api/server.gen.go:1640 (0x75ca93)
auth-1  | github.com/nhost/hasura-auth/go/api/server.gen.go:349 (0x753fa7)
auth-1  | github.com/gin-gonic/gin@v1.10.0/context.go:185 (0x862633)
auth-1  | github.com/nhost/hasura-auth/go/middleware/ratelimit/rate_limit.go:119 (0x862614)
auth-1  | github.com/gin-gonic/gin@v1.10.0/context.go:185 (0x521bdf)
auth-1  | github.com/nhost/hasura-auth/go/middleware/logger.go:58 (0x86c063)
auth-1  | github.com/gin-gonic/gin@v1.10.0/context.go:185 (0x521bdf)
auth-1  | github.com/nhost/hasura-auth/go/cmd/cors.go:33 (0x86c467)
auth-1  | github.com/gin-gonic/gin@v1.10.0/context.go:185 (0x52e43b)
auth-1  | github.com/gin-gonic/gin@v1.10.0/recovery.go:102 (0x52e41c)
auth-1  | github.com/gin-gonic/gin@v1.10.0/context.go:185 (0x52d303)
auth-1  | github.com/gin-gonic/gin@v1.10.0/gin.go:633 (0x52ce8c)
auth-1  | github.com/gin-gonic/gin@v1.10.0/gin.go:589 (0x52cab3)
auth-1  | net/http/server.go:3210 (0x31ea2b)
auth-1  | net/http/server.go:2092 (0x2ffdab)
auth-1  | runtime/asm_arm64.s:1223 (0x894b3)

[dbarrosop]

hello,
thanks, that 500 is a known race condition that masks a 401 error due to an invalid token request, we need to fix it but it is a legit error (you are just getting the wrong one). In any case, what we have seen is that 0.38.0 is surfacing some issues in some complex setups where there are multiple clients instantiated incorrectly and they are all fighting with each other. To confirm this theory, could you share some more details on where/how you are seeing this error? Also, are you running the latest SDK?

Regards

[dionjwa]

I am always running the latest sdk, I believe I very likely had multiple clients authenticating (most likely I just had too many tabs open with the dev browser authenticating all the time) so your theory matches my setup. I cannot offer more information, but I am on auth version 0.40.1 and it doesn't appear to be having the same issues.

[dbarrosop]

but I am on auth version 0.40.1 and it doesn't appear to be having the same issues

That's good to hear. If it starts happening again let us know.

[dionjwa]

I was mistaken, I am still seeing these issues: nhost/nhost#3393

[dionjwa]

0.37.1 does not cause these problems, I had to downgrade to 0.37.1 to prevent users constantly getting logged out

[dbarrosop]

We need a few clarifications:

1. Are you still seeing the 500s? That shouldn't be happening in the latest version. If you are, please, provide the traceback.
2. Do you have multiple instances of the same client? I am not referring to multiple tabs open, I am referring to multiple instances of Nhost. Since feat: refresh session with new refresh token #617 we have seen reports of users having this issue and in all cases it was due to having multiple instances of the nhost sdk instantiated at the same time with the refresh token enabled. If that's the case, please, make sure all instances but one are either removed or have the auto refresh token feature disabled. If that's not the case, we will need more information about the application. Alternatively, you can migrate to our beta SDK which doesn't have this issue.

[dionjwa]

1. I am seeing 500s in the auth logs, but there is no traceback, just status code 500s, see the duplicate issue for more details: Browser refresh after authentication causes a 500 server error, and logs the user out nhost#3393

2. No, I instantiate the nhost client in a module and import it where needed:

./nhost.tsx:

import { NhostClient } from "@nhost/react";

const config =
  import.meta.env.VITE_NHOST_SUBDOMAIN === "xxx"
    ? {
        authUrl: "https://auth.metapage.io/v1",
        storageUrl: "https://xxx.storage.us-east-1.nhost.run/v1",
        graphqlUrl: "https://graphql.metapage.io/v1/graphql",
        functionsUrl: "https://functions.metapage.io/v1",
      }
    : {
        subdomain: import.meta.env.VITE_NHOST_SUBDOMAIN || "local",
        region: import.meta.env.VITE_NHOST_REGION,
      };

export const nhost = new NhostClient(config);

I can't rule out having multiple tabs open, it's often necessary for development

[dbarrosop]

Having multiple tabs open shouldn't be a problem, in your case I suspect you have multiple clients as in the logs you shared in the other issue that was closed as duplicate I can see multiple requests (different trace_ids) at the same exact time. In any case, let's look at one issue at a time. Try the version 0.40.3-beta0 whenever you have the chance. This should get rid of the 500 which might fix your problem.

[dionjwa]

@dbarrosop no luck: I upgraded auth to 0.40.3-beta0, and could reproduce the same way:

1. start logged out
2. log in
3. refresh a few times
4. now I am logged out

A data point that I thought of when looking at configuration: I am using custom domains, and the storage uses a non-custom domain, perhaps there is jwt/cors/cookie issues there?

Could it be rate limiting? As in, I refresh too fast, and so I get logged out?

The user is logged in, I should not see these 401s? This is after refreshing, after successful authentication, so all requests should be authenticated requests.

Auth logs:

[dionjwa]

This is immediately after losing authentication after a refresh, and I tried to close all other tabs at that URL:

[dbarrosop]

Looking at your logs I can see the following:

1. The 500s seem gone
2. You most likely have at least two or (most likely) three clients trying to refresh the session at the same time, that's why you are running into this issue (see below)

Look at the time 14:19:35, you have three requests with three different trace ids running at the same exact time:

1. be87... - 200 success
2. 6596... - 401 due to refresh token already consumed
3. d85b... - 401 due to refresh token already consumed

This shouldn't happen and this most likely the reason you are being logged out.

At this point I think you have three courses of action:

1. Keep running the older version which doesn't consume the refresh token until you have time for (2) or (3), I would personally suggest going with (3) but that might be more time-consuming
2. Figure out why you may have more than one instance of the client and either consolidate or disable the refresh of the session in all but one
3. Migrate to the new SDK (currently in beta but used in production in our own dashboard) which doesn't have this issue

[dionjwa]

Ok, how do I use the new beta sdk?

[dbarrosop]

You can find some information here:

https://github.com/nhost/sdk-experiment/tree/main/packages/nhost-js

with some examples here:

https://github.com/nhost/sdk-experiment/tree/main/demos

and the reference documentation (which isn't yet available online) here:

https://github.com/nhost/sdk-experiment/tree/main/docs/reference/javascript/nhost-js

You can also join us on discord and ask in the sdk-experiment channel if you need any help