Signing up sometimes fails

[dnywh]

3923976 and a few earlier commits introduced styled emails for:

• Auth actions (like signing up, changing email address)
• New chat messages

I made a custom hook for auth actions called send-email-for-auth-action. It's very similar to the official example for Supabase.

Very occasionally, user sign up (email_action_type === "signup") fails with a 422/500 error:

422: Failed to reach hook within maximum time of 5.000000 seconds

This is returned to the user as a server error message on the sign up form, like this:

On the Supabase side, I see the following:

The user who failed sign up still receives the sign up email (via Resend) but the verification link inside that email doesn't work (as you would expect, since sign up didn't properly complete).

Details

The Supabase auth hooks documentation says:

Outside of runtime errors, both HTTP Hooks and Postgres Hooks return timeout errors. Postgres Hooks have 2 seconds to complete processing while HTTP Hooks should complete in 5 seconds. Both HTTP Hooks and Postgres Hooks are run in a transaction do limit the duration of execution to avoid delays in authentication process.

So, for some reason, and only very occasionally, sign ups seem to take longer than five seconds. I suppose that checks out when I look at the average execution time for that edge function:

What isn't clear to me is how to reduce the time this edge function takes. Here's how it's set up:

• The function is small (~50KB bundle)
• Boot time is always fast (200–500ms)
• The error only happens on email_action_type === "signup", and only sometimes, seemingly random
• The email is always sent, even when the error happens
• Timing logs show no single step is consistently slow
• The error is always a 5s timeout from Supabase’s side

[dnywh]

4211711 adds the following:

• Better error message for this case, encouraging the user to press the Sign up button again
• Timestamp logs to track what part of the edge function is going too long

I managed to replicate the bug and get those logs: I failed to sign up and then was successful simply by pressing the Sign up button again. The full logs are below, but what they tell me:

Failed attempt:

• [global] After resend.emails.send 1251 ms for Resend send
• The total time spent in the Resend call was 1.25 seconds.
• The entire function (from boot to end) is well under 2 seconds.

Successful attempt:

• [global] After resend.emails.send 504 ms for Resend send
• The Resend call was 0.5 seconds.
• Again, the total function time is well under 2 seconds.

In both cases, I'm nowhere near the 5-second timeout. I don't think the problem is with my function's execution time. I think it might have something to do with Supabase internal delays, queuing, network delays or region issues, or a cold start issue.

Logs:

[
  {
    "event_message": "[global] After resend.emails.send 504 ms for Resend send\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "16e6a85f-ef52-4dd8-b762-7f0a2103af79",
    "level": "log",
    "timestamp": 1745896590700866
  },
  {
    "event_message": "[global] Before resend.emails.send 47 ms since function start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "f966f99a-f072-4170-92a4-5592c31b6145",
    "level": "log",
    "timestamp": 1745896590700729
  },
  {
    "event_message": "[signup] Before Resend send 47 ms since start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "b2d11bf5-42ad-4073-a7ff-97308db82d2f",
    "level": "log",
    "timestamp": 1745896590700572
  },
  {
    "event_message": "[signup] After renderAsync TEXT 47 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "aec0828d-a071-4f0d-8b49-f9d15ad72aa7",
    "level": "log",
    "timestamp": 1745896590700398
  },
  {
    "event_message": "[signup] After renderAsync HTML 24 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "45d0dda2-0152-4ac5-88ad-a5feb97ec8fa",
    "level": "log",
    "timestamp": 1745896590700221
  },
  {
    "event_message": "[signup] Start renderAsync 1745896587156\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "575b8cc7-508c-4241-a81d-f5efc6378958",
    "level": "log",
    "timestamp": 1745896590700078
  },
  {
    "event_message": "{ email_action_type: \"signup\" }\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "b5ec70fc-3a31-4f97-9073-e13c5a33be36",
    "level": "log",
    "timestamp": 1745896590699891
  },
  {
    "event_message": "booted (time: 250ms)",
    "event_type": "Boot",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "1b0aab2d-def6-4735-9605-5414fc70b154",
    "level": "log",
    "timestamp": 1745896590699599
  },
  {
    "event_message": "[global] After resend.emails.send 1251 ms for Resend send\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "8adf3a07-5878-40c7-8c4e-83b4af38502d",
    "level": "log",
    "timestamp": 1745896539020832
  },
  {
    "event_message": "[global] Before resend.emails.send 62 ms since function start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "9b31d32b-f22e-479b-8e0d-aab406bca425",
    "level": "log",
    "timestamp": 1745896534024556
  },
  {
    "event_message": "[signup] Before Resend send 62 ms since start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "bfe15c47-9576-4e00-ae0c-0fe829609770",
    "level": "log",
    "timestamp": 1745896534024320
  },
  {
    "event_message": "[signup] After renderAsync TEXT 61 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "397b9b65-6fa8-4534-8e15-5f824a6cadf8",
    "level": "log",
    "timestamp": 1745896534024048
  },
  {
    "event_message": "[signup] After renderAsync HTML 37 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "9a8a1d7a-bab4-4661-b361-194b22296d9d",
    "level": "log",
    "timestamp": 1745896534023762
  },
  {
    "event_message": "[signup] Start renderAsync 1745896533012\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "fbb69212-ab11-4928-b1d6-c313ce8e0df1",
    "level": "log",
    "timestamp": 1745896534023477
  },
  {
    "event_message": "{ email_action_type: \"signup\" }\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "f80fd7b5-ba11-420a-8ae8-7972c7272158",
    "level": "log",
    "timestamp": 1745896534023202
  },
  {
    "event_message": "booted (time: 226ms)",
    "event_type": "Boot",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "468f1dc4-fd0a-41e7-9311-7f00bc17b99f",
    "level": "log",
    "timestamp": 1745896534022920
  }
]

[dnywh]

I've been able to replicate twice more. I can see that the Resend API call took 4.3s in one case and 2.9s in another:

[global] After resend.emails.send 4343 ms for Resend send

[global] After resend.emails.send 2856 ms for Resend send

So this is dangerously close to the Supabase 5s timeout for auth hooks. If there's a delay elsewhere, I'll hit the timeout and the signup will fail. That's what I'm guessing is happening: Resend is sometimes slow, and sometimes there's other latency (cold start, for example). The combination of those things causes the auth hook to time out.

Full logs:

[
  {
    "event_message": "[global] After resend.emails.send 2856 ms for Resend send\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "35a4be14-8f29-48d0-b7eb-c8a00ea73e4d",
    "level": "log",
    "timestamp": 1745910087630208
  },
  {
    "event_message": "[global] Before resend.emails.send 88 ms since function start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "faef02e0-dad3-4667-80d9-399c065486bb",
    "level": "log",
    "timestamp": 1745910082620825
  },
  {
    "event_message": "[signup] Before Resend send 88 ms since start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "508a844a-d139-49d1-905f-4cfec12c85d3",
    "level": "log",
    "timestamp": 1745910082620569
  },
  {
    "event_message": "[signup] After renderAsync TEXT 87 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "44dacd19-1f49-4ae4-8734-025672d51b32",
    "level": "log",
    "timestamp": 1745910082620392
  },
  {
    "event_message": "[signup] After renderAsync HTML 64 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "0ae9933d-3f80-4764-8dc3-0a8cc3ff718b",
    "level": "log",
    "timestamp": 1745910082620231
  },
  {
    "event_message": "[signup] Start renderAsync 1745910080700\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "e228e051-80a8-4084-a86b-72c706030a25",
    "level": "log",
    "timestamp": 1745910082619550
  },
  {
    "event_message": "{ email_action_type: \"signup\" }\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "356b2780-0325-41ac-b598-70a20f39d972",
    "level": "log",
    "timestamp": 1745910082619345
  },
  {
    "event_message": "booted (time: 544ms)",
    "event_type": "Boot",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "f4fd08c5-fc9c-4fce-8b15-24ee653eb6dd",
    "level": "log",
    "timestamp": 1745910082618730
  },
  {
    "event_message": "[global] After resend.emails.send 4343 ms for Resend send\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "87efc928-c12e-4a87-9b2d-03aabdf3f3b6",
    "level": "log",
    "timestamp": 1745910082255056
  },
  {
    "event_message": "[global] Before resend.emails.send 46 ms since function start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "2126e3c0-8f4d-4826-8a3a-938b8ec76fa7",
    "level": "log",
    "timestamp": 1745910082252472
  },
  {
    "event_message": "[signup] Before Resend send 46 ms since start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "192c05b1-3d76-4f88-b7d0-e57315addce4",
    "level": "log",
    "timestamp": 1745910082252259
  },
  {
    "event_message": "[signup] After renderAsync TEXT 46 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "447582a6-363f-4c32-b6be-e07ecba311a8",
    "level": "log",
    "timestamp": 1745910082252027
  },
  {
    "event_message": "[signup] After renderAsync HTML 24 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "7d9ab143-0fcd-476c-a865-8af12c3bd9d6",
    "level": "log",
    "timestamp": 1745910082251469
  },
  {
    "event_message": "[global] After resend.emails.send 4343 ms for Resend send\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "1d98a562-a052-4c7f-91d3-03eed33e0f01",
    "level": "log",
    "timestamp": 1745910077240259
  },
  {
    "event_message": "[global] Before resend.emails.send 46 ms since function start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "4f21cad0-88f1-490f-a560-bf9cfc43063d",
    "level": "log",
    "timestamp": 1745910077238601
  },
  {
    "event_message": "[signup] Before Resend send 46 ms since start\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "9e0005e7-26a8-4a08-8a4c-6ad5ef145cba",
    "level": "log",
    "timestamp": 1745910077238453
  },
  {
    "event_message": "[signup] After renderAsync TEXT 46 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "71f08c61-a9ba-4a27-a748-0e4eae85f48b",
    "level": "log",
    "timestamp": 1745910077238286
  },
  {
    "event_message": "[signup] After renderAsync HTML 24 ms\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "258a6d8b-cb1d-48ea-9cdc-340340339756",
    "level": "log",
    "timestamp": 1745910077238075
  },
  {
    "event_message": "[signup] Start renderAsync 1745910072066\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "8e0529ed-3ec7-48dc-a48e-c80cd8ffbf4e",
    "level": "log",
    "timestamp": 1745910072236631
  },
  {
    "event_message": "{ email_action_type: \"signup\" }\n",
    "event_type": "Log",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "f1b47f2e-e665-4245-9ca5-6455b5d2802a",
    "level": "log",
    "timestamp": 1745910072236442
  },
  {
    "event_message": "booted (time: 213ms)",
    "event_type": "Boot",
    "function_id": "782d8fa7-5e98-481c-9d68-68afb9272515",
    "id": "cd2dc974-ebbc-44e8-bb80-0a5e970dd9fa",
    "level": "log",
    "timestamp": 1745910072231225
  }
]

[dnywh]

I've turned off the custom hook until this is resolved. That means any future auth email will go through the default templates, not through the hook. So at least users can reliably sign up.

It can be turned back on with a few taps, here. See the Peels wiki for more info.