Angular application started polluting logs with exception.

[glani]

Bug report

Describe the bug

The simple angular application started polluting logs.

To Reproduce

app.module.ts

in AppModule

export const initializer1 =
  (
  ): (() => Promise<boolean>) =>
    async () => {
      const supabase = createClient(
        'url',
        'key',
        {
          auth: {
            debug: true,
          }
        }
      );
      supabase.auth.onAuthStateChange(() => {});

      return true;
    };


{
      provide: APP_INITIALIZER,
      useFactory: initializer1,
      multi: true,
    },

Expected behavior

No errors in Zone or opportunity to customize showing exceptions.

Screenshots

If applicable, add screenshots to help explain your problem.

System information

• OS: macOS, centos
• Browser chrome
• Version of supabase-js: [^2.39.12]
• Version of Node.js: [e.g. 20.10.0]

Additional context

Debug output in the browser console from GoTrue

GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.619Z #_acquireLock begin -1
render-document-frontend-impl.ts:80 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.619Z #onAuthStateChange() registered callback with id 83bf91bd-ddb2-4add-803e-0e3b2cf2b78d
render-document-frontend-impl.ts:89 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.619Z #onAuthStateChange() registered callback with id a347217b-4993-4ee7-af13-921531e6c12e
core.mjs:26656 Angular is running in development mode.
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.643Z #_acquireLock lock acquired for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.644Z #_initialize() begin is PKCE flow false
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.644Z #_recoverAndRefresh() begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.644Z #_recoverAndRefresh() session from storage null
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.644Z #_recoverAndRefresh() session is not valid
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.644Z #_recoverAndRefresh() end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.644Z #_handleVisibilityChange()
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.644Z #_onVisibilityChanged(true) visibilityState visible
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.644Z #_stopAutoRefresh()
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.645Z #_startAutoRefresh()
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.645Z #_initialize() end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.645Z #_acquireLock lock released for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.645Z #_acquireLock end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.645Z #_acquireLock begin -1
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.646Z #_acquireLock begin -1
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.646Z #_acquireLock begin -1
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.658Z #_autoRefreshTokenTick() begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.658Z #_acquireLock begin 0
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.690Z #_acquireLock lock acquired for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.690Z #_useSession begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.691Z #__loadSession() begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.691Z #getSession() session from storage null
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.691Z #__loadSession() end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.691Z #_acquireLock lock released for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.691Z INITIAL_SESSION callback id 83bf91bd-ddb2-4add-803e-0e3b2cf2b78d session null
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.691Z #_useSession end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.691Z #_acquireLock end
zone.js:1043 Unhandled Promise rejection: Acquiring an exclusive Navigator LockManager lock "lock:sb-guksenxnyizhahqwwusz-auth-token" immediately failed ; Zone: ; Task: null ; Value: Error: Acquiring an exclusive Navigator LockManager lock "lock:sb-guksenxnyizhahqwwusz-auth-token" immediately failed
at locks.js:93:23
at Generator.next ()
at asyncGeneratorStep (asyncToGenerator.js:3:1)
at _next (asyncToGenerator.js:22:1)
at asyncToGenerator.js:27:1
at new ZoneAwarePromise (zone.js:1411:21)
at asyncToGenerator.js:19:1
at locks.js:113:6 Error: Acquiring an exclusive Navigator LockManager lock "lock:sb-guksenxnyizhahqwwusz-auth-token" immediately failed
at https://app.dev.cp.ccwar.io/vendor.js:4186:19
at Generator.next ()
at asyncGeneratorStep (https://app.dev.cp.ccwar.io/vendor.js:92879:24)
at _next (https://app.dev.cp.ccwar.io/vendor.js:92898:9)
at https://app.dev.cp.ccwar.io/vendor.js:92903:7
at new ZoneAwarePromise (https://app.dev.cp.ccwar.io/polyfills.js:1360:21)
at https://app.dev.cp.ccwar.io/vendor.js:92895:12
at https://app.dev.cp.ccwar.io/vendor.js:4206:21
api.onUnhandledError @ zone.js:1043
handleUnhandledRejection @ zone.js:1068
api.microtaskDrainDone @ zone.js:1062
drainMicroTaskQueue @ zone.js:588
Promise.then (async)
nativeScheduleMicroTask @ zone.js:557
scheduleMicroTask @ zone.js:568
resolvePromise @ zone.js:1209
(anonymous) @ zone.js:1100
(anonymous) @ zone.js:1116
asyncGeneratorStep @ asyncToGenerator.js:6
_next @ asyncToGenerator.js:22
(anonymous) @ asyncToGenerator.js:27
ZoneAwarePromise @ zone.js:1411
(anonymous) @ asyncToGenerator.js:19
(anonymous) @ locks.js:113
Show 15 more frames
Show less
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.725Z #_acquireLock end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.725Z auto refresh token tick lock not available
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.745Z #_acquireLock lock acquired for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.745Z #_useSession begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.745Z #__loadSession() begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.746Z #getSession() session from storage null
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.746Z #__loadSession() end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.746Z #_acquireLock lock released for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.746Z INITIAL_SESSION callback id a347217b-4993-4ee7-af13-921531e6c12e session null
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.746Z #_useSession end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.746Z #_acquireLock end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.767Z #_acquireLock lock acquired for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.767Z #_useSession begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.767Z #__loadSession() begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.767Z #getSession() session from storage null
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.767Z #__loadSession() end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.767Z #_useSession end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.767Z #_acquireLock lock released for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.768Z #_acquireLock end
VM5217:5407 page lang detection: 3.60888671875 ms
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.864Z #_acquireLock begin -1
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.866Z #_acquireLock begin -1
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.891Z #_acquireLock lock acquired for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.891Z #_useSession begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.891Z #__loadSession() begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.891Z #getSession() session from storage null
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.891Z #__loadSession() end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.891Z #_useSession end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.891Z #_acquireLock lock released for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.891Z #_acquireLock end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.893Z #_acquireLock lock acquired for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.893Z #_useSession begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.894Z #__loadSession() begin
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.894Z #getSession() session from storage null
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.894Z #__loadSession() end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.894Z #_useSession end
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.894Z #_acquireLock lock released for storage key sb-guksenxnyizhahqwwusz-auth-token
GoTrueClient.js:131 GoTrueClient@0 (2.62.0) 2023-12-23T09:37:44.894Z #_acquireLock end

[Unkn0wn0x]

Are there any updates on this? It's flooding my Sentry instance on every visibility change of the window / tab of my application.

[Klunk75]

Hi there,
after some test I found that the issue should be related to the merge of this Pull Request in @supabase/gotrue-js version 2.62.0:
#807
If you try to downgrade @supabase/gotrue-js to version 2.61.0 (the previous one), the problem should disappear.
Please Supabase Team can you check and try to solve this issue?
Thank you!

Paolo

[davidboothe]

nother solution to this is to tell angular to run the create script outside of angular.

angular/angular-cli#26395 (comment)

this.supabase = this.ngZone.runOutsideAngular(() => createClient(environment.supabase.url, environment.supabase.key));

I don't know if this is just hiding the real issue or not, but my logs are a little cleaner. This also seems required for later versions of angular where SSR is enabled.

ignore this comment. I still eventually see this error log after enough time

[nowfred]

Those logs appear when you set 'debug' to 'true' - you shouldn't need that on unless you are debugging specific aspects of the supabase client connection.

Remove this part of your init:

{
  auth: {
    debug: true,
  }
}

and the logs will disappear...?

[glani]

@nowfred debug true shows the auth flow. The exception is still in place.

[nowfred]

@nowfred debug true shows the auth flow. The exception is still in place.

Lol of course my bad - I came across this because we are debugging potentially related lock collision issues. Will update if I have something useful beyond misreading your initial question.

[hf]

OK so the issue here is really the console.error invocation, not that this is malfunctioning. Will track down why it's logged like so and move it to console.warn or .log.

[hf]

There's a block that should properly handle this and not log the error. There may be something funky going on with your transpilation environment maybe, as the condition:

      if (e.isAcquireTimeout || e instanceof LockAcquireTimeoutError) {
        this._debug('auto refresh token tick lock not available')
      } else {
        throw e
      }

Does not re-throw the error. Anyone able to add a comment in your setup to se what's the type of the error thrown here and what properties it has?

https://github.com/supabase/gotrue-js/blob/master/src/GoTrueClient.ts#L2117-L2121

[glani]

Consider that it happens once in SPA when page is loading

waiting for fix:

For prod build we use this post-install hook:

const fs = require('fs');

const filesToFix = [
  'node_modules/@supabase/gotrue-js/dist/main/lib/locks.js',
  'node_modules/@supabase/gotrue-js/dist/module/lib/locks.js',
];

filesToFix.forEach((fileToFix) => {
  fs.readFile(fileToFix, 'utf8', function (err, data) {
    if (err) {
      return console.log(err);
    }
    const re = new RegExp(/\s+throw new NavigatorLockAcquireTimeoutError/, "g");
    let result = data.replace(re,
      '\n// hide error\n//throw new NavigatorLockAcquireTimeoutError',
    );
    if (result !== data) {
      console.log(`Replaced successfully in ${fileToFix}`);
      fs.writeFile(fileToFix, result, 'utf8', function (err) {
        if (err) return console.log(err);
      });
    } else {
      console.warn(`No Replacement found in ${fileToFix}`);

    }
  });
});

[hf]

I also see a lot of Generator.next which unfortunately points to using generators instead of Promises, so the issue may be coming because it really is an unhandled promise rejection; but it's lifted somehow into a generator Promise implementation.

[hf]

Probably related to this bug / report: angular/angular#51328

[filippo-brigati]

I solved it temporarily by downgrading supabase gotrue, just add this in the package.json

"overrides": { "@supabase/gotrue-js": "2.54.2" }