feat: add logging to gotrue

Author: Vinzent03

packages/gotrue/lib/src/broadcast_web.dart

@@ -3,7 +3,9 @@ import 'dart:html' as html;
 import 'dart:js_util' as js_util;
 
 import 'package:gotrue/src/types/types.dart';
+import 'package:logging/logging.dart';
 
+final _log = Logger('supabase.gotrue');
 BroadcastChannel getBroadcastChannel(String broadcastKey) {
   final broadcast = html.BroadcastChannel(broadcastKey);
   return (
@@ -15,6 +17,7 @@ BroadcastChannel getBroadcastChannel(String broadcastKey) {
       return json.decode(json.encode(dataMap));
     }),
     postMessage: (message) {
+      _log.fine('Broadcasting message: $message');
       final jsMessage = js_util.jsify(message);
       broadcast.postMessage(jsMessage);
     },

packages/gotrue/lib/src/gotrue_client.dart

@@ -14,6 +14,7 @@ import 'package:jwt_decode/jwt_decode.dart';
 import 'package:meta/meta.dart';
 import 'package:retry/retry.dart';
 import 'package:rxdart/subjects.dart';
+import 'package:logging/logging.dart';
 
 import 'broadcast_stub.dart' if (dart.library.html) './broadcast_web.dart'
     as web;
@@ -87,6 +88,8 @@ class GoTrueClient {
 
   final AuthFlowType _flowType;
 
+  final _log = Logger('supabase.gotrue');
+
   /// Proxy to the web BroadcastChannel API. Should be null on non-web platforms.
   BroadcastChannel? _broadcastChannel;
 
@@ -107,6 +110,9 @@ class GoTrueClient {
         _flowType = flowType {
     _autoRefreshToken = autoRefreshToken ?? true;
 
+    _log.config(
+        'GoTrueClient initialized with url: $_url, autoRefreshToken: $_autoRefreshToken, flowType: $_flowType, tickDuration: ${Constants.autoRefreshTickDuration}, tickThreshold: ${Constants.autoRefreshTickThreshold}');
+
     final gotrueUrl = url ?? Constants.defaultGotrueUrl;
     final gotrueHeader = {
       ...Constants.defaultHeaders,
@@ -617,6 +623,7 @@ class GoTrueClient {
   /// If the current session's refresh token is invalid, an error will be thrown.
   Future<AuthResponse> refreshSession([String? refreshToken]) async {
     if (currentSession?.accessToken == null) {
+      _log.warning("Can't refresh session, no current session found.");
       throw AuthSessionMissingException();
     }
 
@@ -842,6 +849,7 @@ class GoTrueClient {
   Future<void> signOut({
     SignOutScope scope = SignOutScope.local,
   }) async {
+    _log.info('Signing out user with scope: $scope');
     final accessToken = currentSession?.accessToken;
 
     if (scope != SignOutScope.others) {
@@ -966,13 +974,15 @@ class GoTrueClient {
     try {
       final session = Session.fromJson(json.decode(jsonStr));
       if (session == null) {
+        _log.warning("Can't recover session from string, session is null");
         await signOut();
         throw notifyException(
           AuthException('Current session is missing data.'),
         );
       }
 
       if (session.isExpired) {
+        _log.fine('Session from recovery is expired');
         final refreshToken = session.refreshToken;
         if (_autoRefreshToken && refreshToken != null) {
           return await _callRefreshToken(refreshToken);
@@ -1002,6 +1012,7 @@ class GoTrueClient {
   void startAutoRefresh() async {
     stopAutoRefresh();
 
+    _log.fine('Starting auto refresh');
     _autoRefreshTicker = Timer.periodic(
       Constants.autoRefreshTickDuration,
       (Timer t) => _autoRefreshTokenTick(),
@@ -1013,6 +1024,7 @@ class GoTrueClient {
 
   /// Stops an active auto refresh process running in the background (if any).
   void stopAutoRefresh() {
+    _log.fine('Stopping auto refresh');
     _autoRefreshTicker?.cancel();
     _autoRefreshTicker = null;
   }
@@ -1037,12 +1049,15 @@ class GoTrueClient {
                   Constants.autoRefreshTickDuration.inMilliseconds)
               .floor();
 
+      _log.finer('Access token expires in $expiresInTicks ticks');
+
       // Only tick if the next tick comes after the retry threshold
       if (expiresInTicks <= Constants.autoRefreshTickThreshold) {
         await _callRefreshToken(refreshToken);
       }
     } catch (error) {
-      // Do nothing. JS client prints here
+      // Do nothing. JS client prints here, but error is already tracked via
+      // [notifyException]
     }
   }
 
@@ -1055,6 +1070,7 @@ class GoTrueClient {
       // Make a GET request
       () async {
         attempt++;
+        _log.fine('Attempt $attempt to refresh token');
         final options = GotrueRequestOptions(
             headers: _headers,
             body: {'refresh_token': refreshToken},
@@ -1129,11 +1145,13 @@ class GoTrueClient {
 
   /// set currentSession and currentUser
   void _saveSession(Session session) {
+    _log.fine('Save session: $session');
     _currentSession = session;
     _currentUser = session.user;
   }
 
   void _removeSession() {
+    _log.fine('Remove session');
     _currentSession = null;
     _currentUser = null;
   }
@@ -1150,6 +1168,7 @@ class GoTrueClient {
         _broadcastChannel = web.getBroadcastChannel(broadcastKey);
         _broadcastChannelSubscription =
             _broadcastChannel?.onMessage.listen((messageEvent) {
+          _log.info('Received broadcast message: $messageEvent');
           final rawEvent = messageEvent['event'];
           final event = switch (rawEvent) {
             // This library sends the js name of the event to be comptabile with
@@ -1202,6 +1221,7 @@ class GoTrueClient {
   Future<AuthResponse> _callRefreshToken(String refreshToken) async {
     // Refreshing is already in progress
     if (_refreshTokenCompleter != null) {
+      _log.finer("Don't call refresh token, already in progress");
       return _refreshTokenCompleter!.future;
     }
 
@@ -1213,6 +1233,7 @@ class GoTrueClient {
         (_) => null,
         onError: (_, __) => null,
       );
+      _log.fine('Refresh access token');
 
       final data = await _refreshAccessToken(refreshToken);
 
@@ -1232,15 +1253,15 @@ class GoTrueClient {
         _removeSession();
         notifyAllSubscribers(AuthChangeEvent.signedOut);
       } else {
-        _onAuthStateChangeController.addError(error, stack);
+        notifyException(error, stack);
       }
 
       _refreshTokenCompleter?.completeError(error);
 
       rethrow;
     } catch (error, stack) {
       _refreshTokenCompleter?.completeError(error);
-      _onAuthStateChangeController.addError(error, stack);
+      notifyException(error, stack);
       rethrow;
     } finally {
       _refreshTokenCompleter = null;
@@ -1265,13 +1286,15 @@ class GoTrueClient {
       });
     }
     final state = AuthState(event, session, fromBroadcast: !broadcast);
+    _log.fine('Notifying subscribers: $state');
     _onAuthStateChangeController.add(state);
     _onAuthStateChangeControllerSync.add(state);
   }
 
   /// For internal use only.
   @internal
   Object notifyException(Object exception, [StackTrace? stackTrace]) {
+    _log.warning('Notifying exception', exception, stackTrace);
     _onAuthStateChangeController.addError(
       exception,
       stackTrace ?? StackTrace.current,

packages/gotrue/pubspec.yaml

@@ -16,6 +16,7 @@ dependencies:
   retry: ^3.1.0
   rxdart: '>=0.27.7 <0.29.0'
   meta: ^1.7.0
+  logging: ^1.2.0
 
 dev_dependencies:
   dart_jsonwebtoken: ^2.4.1