feat: Add logging (#1042)

* feat: add logging to gotrue

* feat: add logging to postgrest

* feat: add logging to supabase package

* fix: log sensitive data at level finer

* feat: add logging to supabase_flutter

* feat: add logging to functions_client

* feat: add logging to realtime_client

* refactor: log sensitive data with level finest

* feat: add logging to storage_client

* docs: add documentation to supabase_flutter readme

* fix: log headers with level FINEST

* fix: save log stream subscription and print all from all loggers

* fix: log some realtime records with level FINE

Author: Vinzent03

packages/functions_client/lib/src/functions_client.dart

@@ -3,8 +3,10 @@ import 'dart:typed_data';
 
 import 'package:functions_client/src/constants.dart';
 import 'package:functions_client/src/types.dart';
+import 'package:functions_client/src/version.dart';
 import 'package:http/http.dart' as http;
 import 'package:http/http.dart' show MultipartRequest;
+import 'package:logging/logging.dart';
 import 'package:yet_another_json_isolate/yet_another_json_isolate.dart';
 
 class FunctionsClient {
@@ -13,6 +15,7 @@ class FunctionsClient {
   final http.Client? _httpClient;
   final YAJsonIsolate _isolate;
   final bool _hasCustomIsolate;
+  final _log = Logger("supabase.functions");
 
   /// In case you don't provide your own isolate, call [dispose] when you're done
   FunctionsClient(
@@ -24,7 +27,10 @@ class FunctionsClient {
         _headers = {...Constants.defaultHeaders, ...headers},
         _isolate = isolate ?? (YAJsonIsolate()..initialize()),
         _hasCustomIsolate = isolate != null,
-        _httpClient = httpClient;
+        _httpClient = httpClient {
+    _log.config("Initialize FunctionsClient v$version with url: $url");
+    _log.finest("Initialize with headers: $headers");
+  }
 
   /// Getter for the headers
   Map<String, String> get headers {
@@ -129,6 +135,8 @@ class FunctionsClient {
       request.headers[key] = value;
     });
 
+    _log.finest('Request: ${request.method} ${request.url} ${request.headers}');
+
     final response = await (_httpClient?.send(request) ?? request.send());
     final responseType = (response.headers['Content-Type'] ??
             response.headers['content-type'] ??
@@ -167,6 +175,7 @@ class FunctionsClient {
   ///
   /// Does nothing if you pass your own isolate
   Future<void> dispose() async {
+    _log.fine("Dispose FunctionsClient");
     if (!_hasCustomIsolate) {
       return _isolate.dispose();
     }

packages/functions_client/pubspec.yaml

@@ -10,6 +10,7 @@ environment:
 
 dependencies:
   http: '>=0.13.4 <2.0.0'
+  logging: ^1.2.0
   yet_another_json_isolate: 2.0.3
 
 dev_dependencies:

packages/gotrue/lib/src/broadcast_web.dart

@@ -3,6 +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);
@@ -15,6 +18,8 @@ BroadcastChannel getBroadcastChannel(String broadcastKey) {
       return json.decode(json.encode(dataMap));
     }),
     postMessage: (message) {
+      _log.finest('Broadcasting message: $message');
+      _log.fine('Broadcasting event: ${message['event']}');
       final jsMessage = js_util.jsify(message);
       broadcast.postMessage(jsMessage);
     },

packages/gotrue/lib/src/gotrue_client.dart

@@ -14,9 +14,11 @@ 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;
+import 'version.dart';
 
 part 'gotrue_mfa_api.dart';
 
@@ -87,6 +89,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;
 
@@ -101,20 +105,22 @@ class GoTrueClient {
     GotrueAsyncStorage? asyncStorage,
     AuthFlowType flowType = AuthFlowType.pkce,
   })  : _url = url ?? Constants.defaultGotrueUrl,
-        _headers = headers ?? {},
+        _headers = {
+          ...Constants.defaultHeaders,
+          ...?headers,
+        },
         _httpClient = httpClient,
         _asyncStorage = asyncStorage,
         _flowType = flowType {
     _autoRefreshToken = autoRefreshToken ?? true;
 
     final gotrueUrl = url ?? Constants.defaultGotrueUrl;
-    final gotrueHeader = {
-      ...Constants.defaultHeaders,
-      if (headers != null) ...headers,
-    };
+    _log.config(
+        'Initialize GoTrueClient v$version with url: $_url, autoRefreshToken: $_autoRefreshToken, flowType: $_flowType, tickDuration: ${Constants.autoRefreshTickDuration}, tickThreshold: ${Constants.autoRefreshTickThreshold}');
+    _log.finest('Initialize with headers: $_headers');
     admin = GoTrueAdminApi(
       gotrueUrl,
-      headers: gotrueHeader,
+      headers: _headers,
       httpClient: httpClient,
     );
     mfa = GoTrueMFAApi(
@@ -617,8 +623,10 @@ 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();
     }
+    _log.info('Refresh session');
 
     final currentSessionRefreshToken =
         refreshToken ?? _currentSession?.refreshToken;
@@ -842,6 +850,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 +975,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 +1013,7 @@ class GoTrueClient {
   void startAutoRefresh() async {
     stopAutoRefresh();
 
+    _log.fine('Starting auto refresh');
     _autoRefreshTicker = Timer.periodic(
       Constants.autoRefreshTickDuration,
       (Timer t) => _autoRefreshTokenTick(),
@@ -1013,6 +1025,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 +1050,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 +1071,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 +1146,14 @@ class GoTrueClient {
 
   /// set currentSession and currentUser
   void _saveSession(Session session) {
+    _log.finest('Saving session: $session');
+    _log.fine('Saving session');
     _currentSession = session;
     _currentUser = session.user;
   }
 
   void _removeSession() {
+    _log.fine('Removing session');
     _currentSession = null;
     _currentUser = null;
   }
@@ -1151,6 +1171,8 @@ class GoTrueClient {
         _broadcastChannelSubscription =
             _broadcastChannel?.onMessage.listen((messageEvent) {
           final rawEvent = messageEvent['event'];
+          _log.finest('Received broadcast message: $messageEvent');
+          _log.info('Received broadcast event: $rawEvent');
           final event = switch (rawEvent) {
             // This library sends the js name of the event to be comptabile with
             // the js library, so we need to convert it back to the dart name
@@ -1202,6 +1224,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 +1236,7 @@ class GoTrueClient {
         (_) => null,
         onError: (_, __) => null,
       );
+      _log.fine('Refresh access token');
 
       final data = await _refreshAccessToken(refreshToken);
 
@@ -1232,15 +1256,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 +1289,15 @@ class GoTrueClient {
       });
     }
     final state = AuthState(event, session, fromBroadcast: !broadcast);
+    _log.finest('onAuthStateChange: $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

packages/postgrest/lib/src/postgrest.dart

@@ -1,4 +1,5 @@
 import 'package:http/http.dart';
+import 'package:logging/logging.dart';
 import 'package:postgrest/postgrest.dart';
 import 'package:postgrest/src/constants.dart';
 import 'package:yet_another_json_isolate/yet_another_json_isolate.dart';
@@ -11,6 +12,7 @@ class PostgrestClient {
   final Client? httpClient;
   final YAJsonIsolate _isolate;
   final bool _hasCustomIsolate;
+  final _log = Logger('supabase.postgrest');
 
   /// To create a [PostgrestClient], you need to provide an [url] endpoint.
   ///
@@ -32,7 +34,10 @@ class PostgrestClient {
   })  : _schema = schema,
         headers = {...defaultHeaders, if (headers != null) ...headers},
         _isolate = isolate ?? (YAJsonIsolate()..initialize()),
-        _hasCustomIsolate = isolate != null;
+        _hasCustomIsolate = isolate != null {
+    _log.config('Initialize PostgrestClient with url: $url, schema: $_schema');
+    _log.finest('Initialize with headers: $headers');
+  }
 
   /// Authenticates the request with JWT.
   @Deprecated("Use setAuth() instead")
@@ -42,6 +47,7 @@ class PostgrestClient {
   }
 
   PostgrestClient setAuth(String? token) {
+    _log.finest("setAuth with: $token");
     if (token != null) {
       headers['Authorization'] = 'Bearer $token';
     } else {
@@ -95,6 +101,7 @@ class PostgrestClient {
   }
 
   Future<void> dispose() async {
+    _log.fine("dispose PostgrestClient");
     if (!_hasCustomIsolate) {
       return _isolate.dispose();
     }

packages/postgrest/lib/src/postgrest_builder.dart

@@ -6,6 +6,7 @@ import 'dart:core';
 
 import 'package:http/http.dart' as http;
 import 'package:http/http.dart';
+import 'package:logging/logging.dart';
 import 'package:meta/meta.dart';
 import 'package:postgrest/postgrest.dart';
 import 'package:yet_another_json_isolate/yet_another_json_isolate.dart';
@@ -44,6 +45,7 @@ class PostgrestBuilder<T, S, R> implements Future<T> {
   final Client? _httpClient;
   final YAJsonIsolate? _isolate;
   final CountOption? _count;
+  final _log = Logger('supabase.postgrest');
 
   PostgrestBuilder({
     required Uri url,
@@ -132,6 +134,8 @@ class PostgrestBuilder<T, S, R> implements Future<T> {
         _headers['Content-Type'] = 'application/json';
       }
       final bodyStr = jsonEncode(_body);
+      _log.finest("Request: $uppercaseMethod $_url");
+
       if (uppercaseMethod == METHOD_GET) {
         response = await (_httpClient?.get ?? http.get)(
           _url,
@@ -203,14 +207,17 @@ class PostgrestBuilder<T, S, R> implements Future<T> {
       // Workaround for https://github.com/supabase/supabase-flutter/issues/560
       if (_maybeSingle && method.toUpperCase() == 'GET' && body is List) {
         if (body.length > 1) {
-          throw PostgrestException(
+          final exception = PostgrestException(
             // https://github.com/PostgREST/postgrest/blob/a867d79c42419af16c18c3fb019eba8df992626f/src/PostgREST/Error.hs#L553
             code: '406',
             details:
                 'Results contain ${body.length} rows, application/vnd.pgrst.object+json requires 1 row',
             hint: null,
             message: 'JSON object requested, multiple (or no) rows returned',
           );
+
+          _log.finest('$exception for request $_url');
+          throw exception;
         } else if (body.length == 1) {
           body = body.first;
         } else {
@@ -286,6 +293,9 @@ class PostgrestBuilder<T, S, R> implements Future<T> {
         );
       }
 
+      _log.finest('$error from request: $_url');
+      _log.fine('$error from request');
+
       throw error;
     }
   }

packages/postgrest/pubspec.yaml

@@ -12,6 +12,7 @@ dependencies:
   http: '>=0.13.0 <2.0.0'
   yet_another_json_isolate: 2.0.3
   meta: ^1.9.1
+  logging: ^1.2.0
 
 dev_dependencies:
   collection: ^1.16.0