From 593816bff8a7ce6976ccebd62ede71a21e1e7fa3 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Tue, 24 Sep 2024 21:16:29 +0200 Subject: [PATCH 01/13] feat: add logging to gotrue --- packages/gotrue/lib/src/broadcast_web.dart | 3 +++ packages/gotrue/lib/src/gotrue_client.dart | 29 +++++++++++++++++++--- packages/gotrue/pubspec.yaml | 1 + 3 files changed, 30 insertions(+), 3 deletions(-) diff --git a/packages/gotrue/lib/src/broadcast_web.dart b/packages/gotrue/lib/src/broadcast_web.dart index b754666a..ffdb5218 100644 --- a/packages/gotrue/lib/src/broadcast_web.dart +++ b/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); }, diff --git a/packages/gotrue/lib/src/gotrue_client.dart b/packages/gotrue/lib/src/gotrue_client.dart index 8a2c0e2b..d077b7ef 100644 --- a/packages/gotrue/lib/src/gotrue_client.dart +++ b/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 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 signOut({ SignOutScope scope = SignOutScope.local, }) async { + _log.info('Signing out user with scope: $scope'); final accessToken = currentSession?.accessToken; if (scope != SignOutScope.others) { @@ -966,6 +974,7 @@ 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.'), @@ -973,6 +982,7 @@ class GoTrueClient { } 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 _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,7 +1253,7 @@ class GoTrueClient { _removeSession(); notifyAllSubscribers(AuthChangeEvent.signedOut); } else { - _onAuthStateChangeController.addError(error, stack); + notifyException(error, stack); } _refreshTokenCompleter?.completeError(error); @@ -1240,7 +1261,7 @@ class GoTrueClient { rethrow; } catch (error, stack) { _refreshTokenCompleter?.completeError(error); - _onAuthStateChangeController.addError(error, stack); + notifyException(error, stack); rethrow; } finally { _refreshTokenCompleter = null; @@ -1265,6 +1286,7 @@ class GoTrueClient { }); } final state = AuthState(event, session, fromBroadcast: !broadcast); + _log.fine('Notifying subscribers: $state'); _onAuthStateChangeController.add(state); _onAuthStateChangeControllerSync.add(state); } @@ -1272,6 +1294,7 @@ class GoTrueClient { /// For internal use only. @internal Object notifyException(Object exception, [StackTrace? stackTrace]) { + _log.warning('Notifying exception', exception, stackTrace); _onAuthStateChangeController.addError( exception, stackTrace ?? StackTrace.current, diff --git a/packages/gotrue/pubspec.yaml b/packages/gotrue/pubspec.yaml index 47e6eef9..f155f450 100644 --- a/packages/gotrue/pubspec.yaml +++ b/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 From 3575ac3d26474ccf9acd6f948c0ebf2b096b9e9a Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 26 Sep 2024 22:10:13 +0200 Subject: [PATCH 02/13] feat: add logging to postgrest --- packages/postgrest/lib/src/postgrest.dart | 4 ++++ packages/postgrest/lib/src/postgrest_builder.dart | 11 ++++++++++- packages/postgrest/pubspec.yaml | 1 + 3 files changed, 15 insertions(+), 1 deletion(-) diff --git a/packages/postgrest/lib/src/postgrest.dart b/packages/postgrest/lib/src/postgrest.dart index dca9b31e..a05c17d3 100644 --- a/packages/postgrest/lib/src/postgrest.dart +++ b/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. /// @@ -42,6 +44,7 @@ class PostgrestClient { } PostgrestClient setAuth(String? token) { + _log.fine("setAuth with: $token"); if (token != null) { headers['Authorization'] = 'Bearer $token'; } else { @@ -95,6 +98,7 @@ class PostgrestClient { } Future dispose() async { + _log.fine("dispose client"); if (!_hasCustomIsolate) { return _isolate.dispose(); } diff --git a/packages/postgrest/lib/src/postgrest_builder.dart b/packages/postgrest/lib/src/postgrest_builder.dart index dab11063..e3f7d64d 100644 --- a/packages/postgrest/lib/src/postgrest_builder.dart +++ b/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 implements Future { final Client? _httpClient; final YAJsonIsolate? _isolate; final CountOption? _count; + final _log = Logger('supabase.postgrest'); PostgrestBuilder({ required Uri url, @@ -132,6 +134,8 @@ class PostgrestBuilder implements Future { _headers['Content-Type'] = 'application/json'; } final bodyStr = jsonEncode(_body); + _log.finer("Request: $uppercaseMethod $_url"); + if (uppercaseMethod == METHOD_GET) { response = await (_httpClient?.get ?? http.get)( _url, @@ -203,7 +207,7 @@ class PostgrestBuilder implements Future { // 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: @@ -211,6 +215,9 @@ class PostgrestBuilder implements Future { hint: null, message: 'JSON object requested, multiple (or no) rows returned', ); + + _log.fine('$exception for request $_url'); + throw exception; } else if (body.length == 1) { body = body.first; } else { @@ -286,6 +293,8 @@ class PostgrestBuilder implements Future { ); } + _log.fine('$error for request $_url'); + throw error; } } diff --git a/packages/postgrest/pubspec.yaml b/packages/postgrest/pubspec.yaml index b1966f5d..2369fe29 100644 --- a/packages/postgrest/pubspec.yaml +++ b/packages/postgrest/pubspec.yaml @@ -12,6 +12,7 @@ dependencies: http: '>=0.13.0 <2.0.0' yet_another_json_isolate: 2.0.2 meta: ^1.9.1 + logging: ^1.2.0 dev_dependencies: collection: ^1.16.0 From 5e6e0c969ee68f1a495f32940b7c4e7cbb519f38 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 26 Sep 2024 22:11:23 +0200 Subject: [PATCH 03/13] feat: add logging to supabase package --- packages/gotrue/lib/src/gotrue_client.dart | 4 +++- packages/supabase/lib/src/auth_user.dart | 1 + .../lib/src/remove_subscription_result.dart | 1 + .../supabase/lib/src/supabase_client.dart | 19 ++++++++++++++++++- .../lib/src/supabase_event_types.dart | 2 ++ .../lib/src/supabase_realtime_error.dart | 1 + .../lib/src/supabase_stream_builder.dart | 4 ++++ packages/supabase/pubspec.yaml | 1 + 8 files changed, 31 insertions(+), 2 deletions(-) diff --git a/packages/gotrue/lib/src/gotrue_client.dart b/packages/gotrue/lib/src/gotrue_client.dart index d077b7ef..bf221a7c 100644 --- a/packages/gotrue/lib/src/gotrue_client.dart +++ b/packages/gotrue/lib/src/gotrue_client.dart @@ -18,6 +18,7 @@ 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'; @@ -111,7 +112,7 @@ class GoTrueClient { _autoRefreshToken = autoRefreshToken ?? true; _log.config( - 'GoTrueClient initialized with url: $_url, autoRefreshToken: $_autoRefreshToken, flowType: $_flowType, tickDuration: ${Constants.autoRefreshTickDuration}, tickThreshold: ${Constants.autoRefreshTickThreshold}'); + 'Initialize GoTrueClient v$version with url: $_url, autoRefreshToken: $_autoRefreshToken, flowType: $_flowType, tickDuration: ${Constants.autoRefreshTickDuration}, tickThreshold: ${Constants.autoRefreshTickThreshold}'); final gotrueUrl = url ?? Constants.defaultGotrueUrl; final gotrueHeader = { @@ -626,6 +627,7 @@ class GoTrueClient { _log.warning("Can't refresh session, no current session found."); throw AuthSessionMissingException(); } + _log.info('Refresh session'); final currentSessionRefreshToken = refreshToken ?? _currentSession?.refreshToken; diff --git a/packages/supabase/lib/src/auth_user.dart b/packages/supabase/lib/src/auth_user.dart index b915764e..f85b5d90 100644 --- a/packages/supabase/lib/src/auth_user.dart +++ b/packages/supabase/lib/src/auth_user.dart @@ -1,5 +1,6 @@ import 'package:gotrue/gotrue.dart' show User; +@Deprecated('No longer used. May be removed in the future.') class AuthUser extends User { AuthUser({ required super.id, diff --git a/packages/supabase/lib/src/remove_subscription_result.dart b/packages/supabase/lib/src/remove_subscription_result.dart index d03c747b..e72f3e2c 100644 --- a/packages/supabase/lib/src/remove_subscription_result.dart +++ b/packages/supabase/lib/src/remove_subscription_result.dart @@ -1,5 +1,6 @@ import 'package:supabase/src/supabase_realtime_error.dart'; +@Deprecated("No longer used. May be removed in the future.") class RemoveSubscriptionResult { const RemoveSubscriptionResult({required this.openSubscriptions, this.error}); final int openSubscriptions; diff --git a/packages/supabase/lib/src/supabase_client.dart b/packages/supabase/lib/src/supabase_client.dart index b51b4ca8..db4ca3b4 100644 --- a/packages/supabase/lib/src/supabase_client.dart +++ b/packages/supabase/lib/src/supabase_client.dart @@ -1,7 +1,9 @@ import 'dart:async'; import 'package:http/http.dart'; +import 'package:logging/logging.dart'; import 'package:supabase/src/constants.dart'; +import 'package:supabase/src/version.dart'; import 'package:supabase/supabase.dart'; import 'package:yet_another_json_isolate/yet_another_json_isolate.dart'; @@ -66,6 +68,8 @@ class SupabaseClient { /// Increment ID of the stream to create different realtime topic for each stream final _incrementId = Counter(); + final _log = Logger('supabase.supabase'); + /// Getter for the HTTP headers Map get headers { return _headers; @@ -145,7 +149,12 @@ class SupabaseClient { storage = _initStorageClient(storageOptions.retryAttempts); realtime = _initRealtimeClient(options: realtimeClientOptions); if (accessToken == null) { + _log.config( + 'Initialize SupabaseClient v$version with no custom access token'); _listenForAuthEvents(); + } else { + _log.config( + 'Initialize SupabaseClient v$version with custom access token'); } } @@ -223,6 +232,8 @@ class SupabaseClient { return realtime.removeAllChannels(); } + /// Get either the custom access token from [accessToken] or the supabase one + /// from [_authInstance] Future _getAccessToken() async { if (accessToken != null) { return await accessToken!(); @@ -231,7 +242,7 @@ class SupabaseClient { if (_authInstance.currentSession?.isExpired ?? false) { try { await _authInstance.refreshSession(); - } catch (error) { + } catch (error, stackTrace) { final expiresAt = _authInstance.currentSession?.expiresAt; if (expiresAt != null) { // Failed to refresh the token. @@ -239,6 +250,11 @@ class SupabaseClient { .isAfter(DateTime.fromMillisecondsSinceEpoch(expiresAt * 1000)); if (isExpiredWithoutMargin) { // Throw the error instead of making an API request with an expired token. + _log.warning( + 'Access token is expired and refreshing failed, aborting api request', + error, + stackTrace, + ); rethrow; } } @@ -248,6 +264,7 @@ class SupabaseClient { } Future dispose() async { + _log.fine('Dispose SupabaseClient'); await _authStateSubscription?.cancel(); await _isolate.dispose(); auth.dispose(); diff --git a/packages/supabase/lib/src/supabase_event_types.dart b/packages/supabase/lib/src/supabase_event_types.dart index 60c53412..72607bbb 100644 --- a/packages/supabase/lib/src/supabase_event_types.dart +++ b/packages/supabase/lib/src/supabase_event_types.dart @@ -1,5 +1,7 @@ +@Deprecated('No longer used. May be removed in the future.') enum SupabaseEventTypes { insert, update, delete, all, broadcast, presence } +// ignore: deprecated_member_use_from_same_package extension SupabaseEventTypesName on SupabaseEventTypes { String name() { final name = toString().split('.').last; diff --git a/packages/supabase/lib/src/supabase_realtime_error.dart b/packages/supabase/lib/src/supabase_realtime_error.dart index 7f271ab1..b9ddf7d2 100644 --- a/packages/supabase/lib/src/supabase_realtime_error.dart +++ b/packages/supabase/lib/src/supabase_realtime_error.dart @@ -1,3 +1,4 @@ +@Deprecated('No longer used. May be removed in the future.') class SupabaseRealtimeError extends Error { /// Creates an Unsubscribe error with the provided [message]. SupabaseRealtimeError([this.message]); diff --git a/packages/supabase/lib/src/supabase_stream_builder.dart b/packages/supabase/lib/src/supabase_stream_builder.dart index 0807c734..89c799d1 100644 --- a/packages/supabase/lib/src/supabase_stream_builder.dart +++ b/packages/supabase/lib/src/supabase_stream_builder.dart @@ -1,5 +1,6 @@ import 'dart:async'; +import 'package:logging/logging.dart'; import 'package:rxdart/rxdart.dart'; import 'package:supabase/supabase.dart'; @@ -49,6 +50,8 @@ class SupabaseStreamBuilder extends Stream { /// Used to identify which row has changed final List _uniqueColumns; + final _log = Logger('supabase.supabase'); + /// StreamController for `stream()` method. BehaviorSubject? _streamController; @@ -129,6 +132,7 @@ class SupabaseStreamBuilder extends Stream { _getStreamData(); }, onCancel: () { + _log.fine('stream controller for table: $_table got closed'); _channel?.unsubscribe(); _streamController?.close(); _streamController = null; diff --git a/packages/supabase/pubspec.yaml b/packages/supabase/pubspec.yaml index 9510e9c7..84f6150b 100644 --- a/packages/supabase/pubspec.yaml +++ b/packages/supabase/pubspec.yaml @@ -17,6 +17,7 @@ dependencies: storage_client: 2.0.3 rxdart: '>=0.27.5 <0.29.0' yet_another_json_isolate: 2.0.2 + logging: ^1.2.0 dev_dependencies: lints: ^3.0.0 From 8d5ce7e21938c874ac7118998aa0089b2041b652 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 17:05:40 +0200 Subject: [PATCH 04/13] fix: log sensitive data at level finer --- packages/gotrue/lib/src/broadcast_web.dart | 4 +++- packages/gotrue/lib/src/gotrue_client.dart | 8 +++++--- packages/postgrest/lib/src/postgrest.dart | 4 ++-- packages/postgrest/lib/src/postgrest_builder.dart | 5 +++-- 4 files changed, 13 insertions(+), 8 deletions(-) diff --git a/packages/gotrue/lib/src/broadcast_web.dart b/packages/gotrue/lib/src/broadcast_web.dart index ffdb5218..a7abd5eb 100644 --- a/packages/gotrue/lib/src/broadcast_web.dart +++ b/packages/gotrue/lib/src/broadcast_web.dart @@ -6,6 +6,7 @@ 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 ( @@ -17,7 +18,8 @@ BroadcastChannel getBroadcastChannel(String broadcastKey) { return json.decode(json.encode(dataMap)); }), postMessage: (message) { - _log.fine('Broadcasting message: $message'); + _log.finer('Broadcasting message: $message'); + _log.fine('Broadcasting event: ${message['event']}'); final jsMessage = js_util.jsify(message); broadcast.postMessage(jsMessage); }, diff --git a/packages/gotrue/lib/src/gotrue_client.dart b/packages/gotrue/lib/src/gotrue_client.dart index bf221a7c..ad6b04ae 100644 --- a/packages/gotrue/lib/src/gotrue_client.dart +++ b/packages/gotrue/lib/src/gotrue_client.dart @@ -1147,13 +1147,14 @@ class GoTrueClient { /// set currentSession and currentUser void _saveSession(Session session) { - _log.fine('Save session: $session'); + _log.finer('Saving session: $session'); + _log.fine('Saving session'); _currentSession = session; _currentUser = session.user; } void _removeSession() { - _log.fine('Remove session'); + _log.fine('Removing session'); _currentSession = null; _currentUser = null; } @@ -1170,8 +1171,9 @@ class GoTrueClient { _broadcastChannel = web.getBroadcastChannel(broadcastKey); _broadcastChannelSubscription = _broadcastChannel?.onMessage.listen((messageEvent) { - _log.info('Received broadcast message: $messageEvent'); final rawEvent = messageEvent['event']; + _log.finer('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 diff --git a/packages/postgrest/lib/src/postgrest.dart b/packages/postgrest/lib/src/postgrest.dart index a05c17d3..9580f0f0 100644 --- a/packages/postgrest/lib/src/postgrest.dart +++ b/packages/postgrest/lib/src/postgrest.dart @@ -44,7 +44,7 @@ class PostgrestClient { } PostgrestClient setAuth(String? token) { - _log.fine("setAuth with: $token"); + _log.finer("setAuth with: $token"); if (token != null) { headers['Authorization'] = 'Bearer $token'; } else { @@ -98,7 +98,7 @@ class PostgrestClient { } Future dispose() async { - _log.fine("dispose client"); + _log.fine("dispose PostgrestClient"); if (!_hasCustomIsolate) { return _isolate.dispose(); } diff --git a/packages/postgrest/lib/src/postgrest_builder.dart b/packages/postgrest/lib/src/postgrest_builder.dart index e3f7d64d..e90348d5 100644 --- a/packages/postgrest/lib/src/postgrest_builder.dart +++ b/packages/postgrest/lib/src/postgrest_builder.dart @@ -216,7 +216,7 @@ class PostgrestBuilder implements Future { message: 'JSON object requested, multiple (or no) rows returned', ); - _log.fine('$exception for request $_url'); + _log.finer('$exception for request $_url'); throw exception; } else if (body.length == 1) { body = body.first; @@ -293,7 +293,8 @@ class PostgrestBuilder implements Future { ); } - _log.fine('$error for request $_url'); + _log.finer('$error from request: $_url'); + _log.fine('$error from request'); throw error; } From 7e67afc41dfeace764bdd83d3987f44e4e62713a Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 17:41:56 +0200 Subject: [PATCH 05/13] feat: add logging to supabase_flutter --- packages/gotrue/lib/src/gotrue_client.dart | 2 +- .../supabase_flutter/lib/src/supabase.dart | 31 +++++++++----- .../lib/src/supabase_auth.dart | 40 +++++++++---------- packages/supabase_flutter/pubspec.yaml | 1 + 4 files changed, 40 insertions(+), 34 deletions(-) diff --git a/packages/gotrue/lib/src/gotrue_client.dart b/packages/gotrue/lib/src/gotrue_client.dart index ad6b04ae..33a4c7ae 100644 --- a/packages/gotrue/lib/src/gotrue_client.dart +++ b/packages/gotrue/lib/src/gotrue_client.dart @@ -1290,7 +1290,7 @@ class GoTrueClient { }); } final state = AuthState(event, session, fromBroadcast: !broadcast); - _log.fine('Notifying subscribers: $state'); + _log.fine('onAuthStateChange: $state'); _onAuthStateChangeController.add(state); _onAuthStateChangeControllerSync.add(state); } diff --git a/packages/supabase_flutter/lib/src/supabase.dart b/packages/supabase_flutter/lib/src/supabase.dart index 0608707c..3d578075 100644 --- a/packages/supabase_flutter/lib/src/supabase.dart +++ b/packages/supabase_flutter/lib/src/supabase.dart @@ -3,12 +3,17 @@ import 'dart:async'; import 'package:async/async.dart'; import 'package:flutter/foundation.dart'; import 'package:http/http.dart'; +import 'package:logging/logging.dart'; import 'package:supabase/supabase.dart'; import 'package:supabase_flutter/src/constants.dart'; import 'package:supabase_flutter/src/flutter_go_true_client_options.dart'; import 'package:supabase_flutter/src/local_storage.dart'; import 'package:supabase_flutter/src/supabase_auth.dart'; +import 'version.dart'; + +final _log = Logger('supabase.supabase_flutter'); + /// Supabase instance. /// /// It must be initialized before used, otherwise an error is thrown. @@ -82,6 +87,19 @@ class Supabase { !_instance._initialized, 'This instance is already initialized', ); + _instance._debugEnable = debug ?? kDebugMode; + + if (_instance._debugEnable) { + _log.onRecord.listen((record) { + if (record.level >= Level.INFO) { + debugPrint( + '${record.loggerName}: ${record.level.name}: ${record.message} ${record.error ?? ""}'); + } + }); + } + + _log.config("Initialize Supabase v$version"); + if (authOptions.pkceAsyncStorage == null) { authOptions = authOptions.copyWith( pkceAsyncStorage: SharedPreferencesGotrueAsyncStorage(), @@ -106,8 +124,6 @@ class Supabase { storageOptions: storageOptions, accessToken: accessToken, ); - _instance._debugEnable = debug ?? kDebugMode; - _instance.log('***** Supabase init completed *****'); _instance._supabaseAuth = SupabaseAuth(); await _instance._supabaseAuth.initialize(options: authOptions); @@ -119,6 +135,8 @@ class Supabase { _instance._supabaseAuth.recoverSession(), ); + _log.info('***** Supabase init completed *****'); + return _instance; } @@ -175,13 +193,4 @@ class Supabase { ); _initialized = true; } - - void log(String msg, [StackTrace? stackTrace]) { - if (_debugEnable) { - debugPrint(msg); - if (stackTrace != null) { - debugPrintStack(stackTrace: stackTrace); - } - } - } } diff --git a/packages/supabase_flutter/lib/src/supabase_auth.dart b/packages/supabase_flutter/lib/src/supabase_auth.dart index 80cf6248..a5964d94 100644 --- a/packages/supabase_flutter/lib/src/supabase_auth.dart +++ b/packages/supabase_flutter/lib/src/supabase_auth.dart @@ -8,6 +8,7 @@ import 'package:async/async.dart'; import 'package:flutter/foundation.dart' show kIsWeb; import 'package:flutter/material.dart'; import 'package:flutter/services.dart'; +import 'package:logging/logging.dart'; import 'package:supabase_flutter/supabase_flutter.dart'; import 'package:url_launcher/url_launcher.dart'; @@ -34,6 +35,8 @@ class SupabaseAuth with WidgetsBindingObserver { final _appLinks = AppLinks(); + final _log = Logger('supabase.supabase_flutter'); + /// - Obtains session from local storage and sets it as the current session /// - Starts a deep link observer /// - Emits an initial session if there were no session stored in local storage @@ -48,9 +51,7 @@ class SupabaseAuth with WidgetsBindingObserver { (data) { _onAuthStateChange(data.event, data.session); }, - onError: (error, stackTrace) { - Supabase.instance.log(error.toString(), stackTrace); - }, + onError: (error, stackTrace) {}, ); await _localStorage.initialize(); @@ -65,7 +66,8 @@ class SupabaseAuth with WidgetsBindingObserver { .setInitialSession(persistedSession); shouldEmitInitialSession = false; } catch (error, stackTrace) { - Supabase.instance.log(error.toString(), stackTrace); + _log.warning( + 'Error while setting initial session', error, stackTrace); } } } @@ -96,9 +98,9 @@ class SupabaseAuth with WidgetsBindingObserver { } } } on AuthException catch (error, stackTrace) { - Supabase.instance.log(error.message, stackTrace); + _log.warning(error.message, error, stackTrace); } catch (error, stackTrace) { - Supabase.instance.log(error.toString(), stackTrace); + _log.warning("Error while recovering session", error, stackTrace); } } @@ -186,9 +188,7 @@ class SupabaseAuth with WidgetsBindingObserver { } void _onAuthStateChange(AuthChangeEvent event, Session? session) { - Supabase.instance.log('**** onAuthStateChange: $event'); if (session != null) { - Supabase.instance.log(jsonEncode(session.toJson())); _localStorage.persistSession(jsonEncode(session.toJson())); } else if (event == AuthChangeEvent.signedOut) { _localStorage.removePersistedSession(); @@ -206,7 +206,7 @@ class SupabaseAuth with WidgetsBindingObserver { /// Enable deep link observer to handle deep links Future _startDeeplinkObserver() async { - Supabase.instance.log('***** SupabaseDeepLinkingMixin startAuthObserver'); + _log.fine('Starting deeplink observer'); _handleIncomingLinks(); await _handleInitialUri(); } @@ -216,7 +216,7 @@ class SupabaseAuth with WidgetsBindingObserver { /// Automatically called on dispose(). void _stopDeeplinkObserver() { if (_deeplinkSubscription != null) { - Supabase.instance.log('***** SupabaseDeepLinkingMixin stopAuthObserver'); + _log.fine('Stopping deeplink observer'); _deeplinkSubscription?.cancel(); } } @@ -234,7 +234,7 @@ class SupabaseAuth with WidgetsBindingObserver { } }, onError: (Object err, StackTrace stackTrace) { - _onErrorReceivingDeeplink(err.toString(), stackTrace); + _onErrorReceivingDeeplink(err, stackTrace); }, ); } @@ -273,12 +273,12 @@ class SupabaseAuth with WidgetsBindingObserver { await _handleDeeplink(uri); } } on PlatformException catch (err, stackTrace) { - _onErrorReceivingDeeplink(err.message ?? err.toString(), stackTrace); + _onErrorReceivingDeeplink(err.message ?? err, stackTrace); // Platform messages may fail but we ignore the exception } on FormatException catch (err, stackTrace) { _onErrorReceivingDeeplink(err.message, stackTrace); } catch (err, stackTrace) { - _onErrorReceivingDeeplink(err.toString(), stackTrace); + _onErrorReceivingDeeplink(err, stackTrace); } } @@ -286,26 +286,22 @@ class SupabaseAuth with WidgetsBindingObserver { Future _handleDeeplink(Uri uri) async { if (!_isAuthCallbackDeeplink(uri)) return; - Supabase.instance.log('***** SupabaseAuthState handleDeeplink $uri'); - - // notify auth deeplink received - Supabase.instance.log('onReceivedAuthDeeplink uri: $uri'); + _log.fine('handle deeplink uri: $uri'); + _log.info('handle deeplink uri'); try { await Supabase.instance.client.auth.getSessionFromUrl(uri); } on AuthException catch (error, stackTrace) { // ignore: invalid_use_of_internal_member Supabase.instance.client.auth.notifyException(error, stackTrace); - Supabase.instance.log(error.toString(), stackTrace); } catch (error, stackTrace) { - Supabase.instance.log(error.toString(), stackTrace); + _log.warning('Error while getSessionFromUrl', error, stackTrace); } } /// Callback when deeplink receiving throw error - void _onErrorReceivingDeeplink(String message, StackTrace stackTrace) { - Supabase.instance - .log('onErrorReceivingDeepLink message: $message', stackTrace); + void _onErrorReceivingDeeplink(Object error, StackTrace stackTrace) { + _log.warning('Error while receiving deeplink', error, stackTrace); } } diff --git a/packages/supabase_flutter/pubspec.yaml b/packages/supabase_flutter/pubspec.yaml index 34fc4c98..effb8a55 100644 --- a/packages/supabase_flutter/pubspec.yaml +++ b/packages/supabase_flutter/pubspec.yaml @@ -21,6 +21,7 @@ dependencies: url_launcher: ^6.1.2 path_provider: ^2.0.0 shared_preferences: ^2.0.0 + logging: ^1.2.0 dev_dependencies: dart_jsonwebtoken: ^2.4.1 From 729f29a033ba07684f99d404a50d1b5e3c407778 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 17:50:05 +0200 Subject: [PATCH 06/13] feat: add logging to functions_client --- .../functions_client/lib/src/functions_client.dart | 10 +++++++++- packages/functions_client/pubspec.yaml | 1 + 2 files changed, 10 insertions(+), 1 deletion(-) diff --git a/packages/functions_client/lib/src/functions_client.dart b/packages/functions_client/lib/src/functions_client.dart index e9c3b52d..4ba618e9 100644 --- a/packages/functions_client/lib/src/functions_client.dart +++ b/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,9 @@ class FunctionsClient { _headers = {...Constants.defaultHeaders, ...headers}, _isolate = isolate ?? (YAJsonIsolate()..initialize()), _hasCustomIsolate = isolate != null, - _httpClient = httpClient; + _httpClient = httpClient { + _log.config("Initialize FunctionsClient v$version"); + } /// Getter for the headers Map get headers { @@ -129,6 +134,8 @@ class FunctionsClient { request.headers[key] = value; }); + _log.finer('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 +174,7 @@ class FunctionsClient { /// /// Does nothing if you pass your own isolate Future dispose() async { + _log.fine("Dispose FunctionsClient"); if (!_hasCustomIsolate) { return _isolate.dispose(); } diff --git a/packages/functions_client/pubspec.yaml b/packages/functions_client/pubspec.yaml index 710a1220..47be4783 100644 --- a/packages/functions_client/pubspec.yaml +++ b/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.2 dev_dependencies: From d3042d501da99e671e4942f813c83da9b30d5688 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 18:14:07 +0200 Subject: [PATCH 07/13] feat: add logging to realtime_client --- .../lib/src/realtime_client.dart | 41 +++++++++++++------ packages/realtime_client/pubspec.yaml | 1 + .../lib/src/supabase_auth.dart | 2 + 3 files changed, 32 insertions(+), 12 deletions(-) diff --git a/packages/realtime_client/lib/src/realtime_client.dart b/packages/realtime_client/lib/src/realtime_client.dart index fe7eefd3..4241173c 100644 --- a/packages/realtime_client/lib/src/realtime_client.dart +++ b/packages/realtime_client/lib/src/realtime_client.dart @@ -4,6 +4,7 @@ import 'dart:core'; import 'package:collection/collection.dart'; import 'package:http/http.dart'; +import 'package:logging/logging.dart'; import 'package:meta/meta.dart'; import 'package:realtime_client/realtime_client.dart'; import 'package:realtime_client/src/constants.dart'; @@ -62,6 +63,7 @@ class RealtimeClient { final Duration timeout; final WebSocketTransport transport; final Client? httpClient; + final _log = Logger('supabase.realtime'); int heartbeatIntervalMs = 30000; Timer? heartbeatTimer; @@ -90,18 +92,29 @@ class RealtimeClient { /// Initializes the Socket /// - /// `endPoint` The string WebSocket endpoint, ie, "ws://example.com/socket", "wss://example.com", "/socket" (inherited host & protocol) - /// `httpEndpoint` The string HTTP endpoint, ie, "https://example.com", "/" (inherited host & protocol) - /// `transport` The Websocket Transport, for example WebSocket. - /// `timeout` The default timeout in milliseconds to trigger push timeouts. - /// `params` The optional params to pass when connecting. - /// `headers` The optional headers to pass when connecting. - /// `heartbeatIntervalMs` The millisec interval to send a heartbeat message. - /// `logger` The optional function for specialized logging, ie: logger: (kind, msg, data) => { console.log(`$kind: $msg`, data) } - /// `encode` The function to encode outgoing messages. Defaults to JSON: (payload, callback) => callback(JSON.stringify(payload)) - /// `decode` The function to decode incoming messages. Defaults to JSON: (payload, callback) => callback(JSON.parse(payload)) - /// `longpollerTimeout` The maximum timeout of a long poll AJAX request. Defaults to 20s (double the server long poll timer). - /// `reconnectAfterMs` The optional function that returns the millsec reconnect interval. Defaults to stepped backoff off. + /// [endPoint] The string WebSocket endpoint, ie, "ws://example.com/socket", "wss://example.com", "/socket" (inherited host & protocol + /// + /// [transport] The Websocket Transport, for example WebSocket. + /// + /// [timeout] The default timeout in milliseconds to trigger push timeouts. + /// + /// [params] The optional params to pass when connecting. + /// + /// [headers] The optional headers to pass when connecting. + /// + /// [heartbeatIntervalMs] The millisec interval to send a heartbeat message. + /// + /// [logger] The optional function for specialized logging, ie: logger: (kind, msg, data) => { console.log(`$kind: $msg`, data) } + /// + /// [encode] The function to encode outgoing messages. Defaults to JSON: (payload, callback) => callback(JSON.stringify(payload)) + /// + /// [decode] The function to decode incoming messages. Defaults to JSON: (payload, callback) => callback(JSON.parse(payload)) + /// + /// [longpollerTimeout] The maximum timeout of a long poll AJAX request. Defaults to 20s (double the server long poll timer). + /// + /// [reconnectAfterMs] The optional function that returns the millsec reconnect interval. Defaults to stepped backoff off. + /// + /// [logLevel] Specifies the log level for the connection on the server. RealtimeClient( String endPoint, { WebSocketTransport? transport, @@ -155,6 +168,7 @@ class RealtimeClient { } try { + log('transport', 'connecting to $endPointURL'); connState = SocketStates.connecting; conn = transport(endPointURL, headers); @@ -202,6 +216,7 @@ class RealtimeClient { if (conn != null) { final oldState = connState; connState = SocketStates.disconnecting; + log('transport', 'disconnecting', {'code': code, 'reason': reason}); // Connection cannot be closed while it's still connecting. Wait for connection to // be ready and then close it. @@ -218,6 +233,7 @@ class RealtimeClient { } connState = SocketStates.disconnected; reconnectTimer.reset(); + log('transport', 'disconnected'); } this.conn = null; @@ -247,6 +263,7 @@ class RealtimeClient { /// Logs the message. Override `this.logger` for specialized logging. void log([String? kind, String? msg, dynamic data]) { + _log.finer('$kind: $msg', data); logger?.call(kind, msg, data); } diff --git a/packages/realtime_client/pubspec.yaml b/packages/realtime_client/pubspec.yaml index 1138e910..33df781b 100644 --- a/packages/realtime_client/pubspec.yaml +++ b/packages/realtime_client/pubspec.yaml @@ -11,6 +11,7 @@ environment: dependencies: collection: ^1.15.0 http: '>=0.13.0 <2.0.0' + logging: ^1.2.0 meta: ^1.7.0 web_socket_channel: '>=2.3.0 <4.0.0' diff --git a/packages/supabase_flutter/lib/src/supabase_auth.dart b/packages/supabase_flutter/lib/src/supabase_auth.dart index a5964d94..fe61d42f 100644 --- a/packages/supabase_flutter/lib/src/supabase_auth.dart +++ b/packages/supabase_flutter/lib/src/supabase_auth.dart @@ -154,6 +154,7 @@ class SupabaseAuth with WidgetsBindingObserver { for (final channel in realtime.channels) { // ignore: invalid_use_of_internal_member if (channel.isJoined) { + // ignore: invalid_use_of_internal_member channel.forceRejoin(); } } @@ -180,6 +181,7 @@ class SupabaseAuth with WidgetsBindingObserver { // ignore: invalid_use_of_internal_member if (channel.isJoined) { + // ignore: invalid_use_of_internal_member channel.forceRejoin(); } } From 46e698ffadd853c88bf3f0803f0d4780edb92790 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 20:00:04 +0200 Subject: [PATCH 08/13] refactor: log sensitive data with level finest --- packages/functions_client/lib/src/functions_client.dart | 2 +- packages/gotrue/lib/src/broadcast_web.dart | 2 +- packages/gotrue/lib/src/gotrue_client.dart | 6 +++--- packages/postgrest/lib/src/postgrest.dart | 2 +- packages/postgrest/lib/src/postgrest_builder.dart | 6 +++--- packages/realtime_client/lib/src/realtime_client.dart | 2 +- 6 files changed, 10 insertions(+), 10 deletions(-) diff --git a/packages/functions_client/lib/src/functions_client.dart b/packages/functions_client/lib/src/functions_client.dart index 4ba618e9..63f76dd6 100644 --- a/packages/functions_client/lib/src/functions_client.dart +++ b/packages/functions_client/lib/src/functions_client.dart @@ -134,7 +134,7 @@ class FunctionsClient { request.headers[key] = value; }); - _log.finer('Request: ${request.method} ${request.url} ${request.headers}'); + _log.finest('Request: ${request.method} ${request.url} ${request.headers}'); final response = await (_httpClient?.send(request) ?? request.send()); final responseType = (response.headers['Content-Type'] ?? diff --git a/packages/gotrue/lib/src/broadcast_web.dart b/packages/gotrue/lib/src/broadcast_web.dart index a7abd5eb..d53be14b 100644 --- a/packages/gotrue/lib/src/broadcast_web.dart +++ b/packages/gotrue/lib/src/broadcast_web.dart @@ -18,7 +18,7 @@ BroadcastChannel getBroadcastChannel(String broadcastKey) { return json.decode(json.encode(dataMap)); }), postMessage: (message) { - _log.finer('Broadcasting message: $message'); + _log.finest('Broadcasting message: $message'); _log.fine('Broadcasting event: ${message['event']}'); final jsMessage = js_util.jsify(message); broadcast.postMessage(jsMessage); diff --git a/packages/gotrue/lib/src/gotrue_client.dart b/packages/gotrue/lib/src/gotrue_client.dart index 33a4c7ae..1235b112 100644 --- a/packages/gotrue/lib/src/gotrue_client.dart +++ b/packages/gotrue/lib/src/gotrue_client.dart @@ -1147,7 +1147,7 @@ class GoTrueClient { /// set currentSession and currentUser void _saveSession(Session session) { - _log.finer('Saving session: $session'); + _log.finest('Saving session: $session'); _log.fine('Saving session'); _currentSession = session; _currentUser = session.user; @@ -1172,7 +1172,7 @@ class GoTrueClient { _broadcastChannelSubscription = _broadcastChannel?.onMessage.listen((messageEvent) { final rawEvent = messageEvent['event']; - _log.finer('Received broadcast message: $messageEvent'); + _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 @@ -1290,7 +1290,7 @@ class GoTrueClient { }); } final state = AuthState(event, session, fromBroadcast: !broadcast); - _log.fine('onAuthStateChange: $state'); + _log.finest('onAuthStateChange: $state'); _onAuthStateChangeController.add(state); _onAuthStateChangeControllerSync.add(state); } diff --git a/packages/postgrest/lib/src/postgrest.dart b/packages/postgrest/lib/src/postgrest.dart index 9580f0f0..a705ebc0 100644 --- a/packages/postgrest/lib/src/postgrest.dart +++ b/packages/postgrest/lib/src/postgrest.dart @@ -44,7 +44,7 @@ class PostgrestClient { } PostgrestClient setAuth(String? token) { - _log.finer("setAuth with: $token"); + _log.finest("setAuth with: $token"); if (token != null) { headers['Authorization'] = 'Bearer $token'; } else { diff --git a/packages/postgrest/lib/src/postgrest_builder.dart b/packages/postgrest/lib/src/postgrest_builder.dart index e90348d5..d7ef48e3 100644 --- a/packages/postgrest/lib/src/postgrest_builder.dart +++ b/packages/postgrest/lib/src/postgrest_builder.dart @@ -134,7 +134,7 @@ class PostgrestBuilder implements Future { _headers['Content-Type'] = 'application/json'; } final bodyStr = jsonEncode(_body); - _log.finer("Request: $uppercaseMethod $_url"); + _log.finest("Request: $uppercaseMethod $_url"); if (uppercaseMethod == METHOD_GET) { response = await (_httpClient?.get ?? http.get)( @@ -216,7 +216,7 @@ class PostgrestBuilder implements Future { message: 'JSON object requested, multiple (or no) rows returned', ); - _log.finer('$exception for request $_url'); + _log.finest('$exception for request $_url'); throw exception; } else if (body.length == 1) { body = body.first; @@ -293,7 +293,7 @@ class PostgrestBuilder implements Future { ); } - _log.finer('$error from request: $_url'); + _log.finest('$error from request: $_url'); _log.fine('$error from request'); throw error; diff --git a/packages/realtime_client/lib/src/realtime_client.dart b/packages/realtime_client/lib/src/realtime_client.dart index 4241173c..08d06ac9 100644 --- a/packages/realtime_client/lib/src/realtime_client.dart +++ b/packages/realtime_client/lib/src/realtime_client.dart @@ -263,7 +263,7 @@ class RealtimeClient { /// Logs the message. Override `this.logger` for specialized logging. void log([String? kind, String? msg, dynamic data]) { - _log.finer('$kind: $msg', data); + _log.finest('$kind: $msg', data); logger?.call(kind, msg, data); } From 8ce8aa7594022241dae35d0caa6fc19e607c747b Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 20:21:42 +0200 Subject: [PATCH 09/13] feat: add logging to storage_client --- packages/storage_client/lib/src/fetch.dart | 21 ++++++++++++++++++--- packages/storage_client/pubspec.yaml | 1 + 2 files changed, 19 insertions(+), 3 deletions(-) diff --git a/packages/storage_client/lib/src/fetch.dart b/packages/storage_client/lib/src/fetch.dart index a39c136e..1d4bce5f 100644 --- a/packages/storage_client/lib/src/fetch.dart +++ b/packages/storage_client/lib/src/fetch.dart @@ -5,6 +5,7 @@ import 'dart:typed_data'; import 'package:http/http.dart' as http; import 'package:http/http.dart'; import 'package:http_parser/http_parser.dart' show MediaType; +import 'package:logging/logging.dart'; import 'package:mime/mime.dart'; import 'package:retry/retry.dart'; import 'package:storage_client/src/types.dart'; @@ -13,6 +14,7 @@ import 'file_io.dart' if (dart.library.js) './file_stub.dart'; class Fetch { final Client? httpClient; + final _log = Logger('supabase.storage'); Fetch([this.httpClient]); @@ -25,18 +27,24 @@ class Fetch { return MediaType.parse(mime ?? 'application/octet-stream'); } - StorageException _handleError(dynamic error, StackTrace stack) { + StorageException _handleError(dynamic error, StackTrace stack, Uri? url) { if (error is http.Response) { try { final data = json.decode(error.body) as Map; - return StorageException.fromJson(data, '${error.statusCode}'); + + final exception = + StorageException.fromJson(data, '${error.statusCode}'); + _log.fine('StorageException for $url', exception, stack); + return exception; } on FormatException catch (_) { + _log.fine('StorageException for $url', error.body, stack); return StorageException( error.body, statusCode: '${error.statusCode}', ); } } else { + _log.fine('StorageException for $url', error, stack); return StorageException( error.toString(), statusCode: error.runtimeType.toString(), @@ -61,6 +69,7 @@ class Fetch { request.body = json.encode(body); } + _log.finest('Request: $method $url $headers'); final http.StreamedResponse streamedResponse; if (httpClient != null) { streamedResponse = await httpClient!.send(request); @@ -97,8 +106,11 @@ class Fetch { final http.StreamedResponse streamedResponse; final r = RetryOptions(maxAttempts: (retryAttempts + 1)); + var attempts = 0; streamedResponse = await r.retry( () async { + attempts++; + _log.finest('Request: attempt: $attempts $method $url $headers'); if (httpClient != null) { return httpClient!.send(request); } else { @@ -141,8 +153,11 @@ class Fetch { final http.StreamedResponse streamedResponse; final r = RetryOptions(maxAttempts: (retryAttempts + 1)); + var attempts = 0; streamedResponse = await r.retry( () async { + attempts++; + _log.finest('Request: attempt: $attempts $method $url $headers'); if (httpClient != null) { return httpClient!.send(request); } else { @@ -170,7 +185,7 @@ class Fetch { return jsonBody; } } else { - throw _handleError(response, StackTrace.current); + throw _handleError(response, StackTrace.current, response.request?.url); } } diff --git a/packages/storage_client/pubspec.yaml b/packages/storage_client/pubspec.yaml index f1922a78..f8b41163 100644 --- a/packages/storage_client/pubspec.yaml +++ b/packages/storage_client/pubspec.yaml @@ -14,6 +14,7 @@ dependencies: mime: ^1.0.2 retry: ^3.1.0 meta: ^1.7.0 + logging: ^1.2.0 dev_dependencies: test: ^1.21.4 From 44a693aec1f2d9afb0fde89ccbd18a710dbe3d77 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 20:44:46 +0200 Subject: [PATCH 10/13] docs: add documentation to supabase_flutter readme --- packages/supabase_flutter/README.md | 30 +++++++++++++++++++ .../supabase_flutter/lib/src/supabase.dart | 2 +- 2 files changed, 31 insertions(+), 1 deletion(-) diff --git a/packages/supabase_flutter/README.md b/packages/supabase_flutter/README.md index 23acc59b..66ea479d 100644 --- a/packages/supabase_flutter/README.md +++ b/packages/supabase_flutter/README.md @@ -596,6 +596,36 @@ Supabase.initialize( ); ``` +## Logging + +All Supabase packages use the [logging](https://pub.dev/packages/logging) package to log information. Each sub-package has its own logger instance. You can listen to logs and set custom log levels for each logger. + +In debug mode, or depending on the value for `debug` from `Supabase.initialize()`, records with `Level.INFO` and above are printed to the console. + +Records containing sensitive data like access tokens and which requests are made are logged with `Level.FINEST`, so you can handle them accordingly. + +### Listen to all Supabase logs + +```dart +import 'package:logging/logging.dart'; + +final supabaseLogger = Logger('supabase'); +supabaseLogger.level = Level.ALL; // custom log level filtering, default is Level.INFO +supabaseLogger.onRecord.listen((record) { + print('${record.level.name}: ${record.time}: ${record.message}'); +}); +``` + +### Sub-package loggers + +- `supabase_flutter`: `Logger('supabase.supabase_flutter')` +- `supabase`: `Logger('supabase.supabase')` +- `postgrest`: `Logger('supabase.postgrest')` +- `gotrue`: `Logger('supabase.gotrue')` +- `realtime_client`: `Logger('supabase.realtime')` +- `storage_client`: `Logger('supabase.storage')` +- `functions_client`: `Logger('supabase.functions')` + --- ## Migrating Guide diff --git a/packages/supabase_flutter/lib/src/supabase.dart b/packages/supabase_flutter/lib/src/supabase.dart index 3d578075..e6d0902e 100644 --- a/packages/supabase_flutter/lib/src/supabase.dart +++ b/packages/supabase_flutter/lib/src/supabase.dart @@ -70,7 +70,7 @@ class Supabase { /// PKCE flow uses shared preferences for storing the code verifier by default. /// Pass a custom storage to [pkceAsyncStorage] to override the behavior. /// - /// If [debug] is set to `true`, debug logs will be printed in debug console. + /// If [debug] is set to `true`, debug logs will be printed in debug console. Default is `kDebugMode`. static Future initialize({ required String url, required String anonKey, From da66f9f89bff347db14cdf2af6fb353773b5f047 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 23:01:57 +0200 Subject: [PATCH 11/13] fix: log headers with level FINEST --- .../lib/src/functions_client.dart | 3 ++- packages/gotrue/lib/src/gotrue_client.dart | 15 +++++++-------- packages/postgrest/lib/src/postgrest.dart | 5 ++++- .../realtime_client/lib/src/realtime_client.dart | 3 +++ .../storage_client/lib/src/storage_client.dart | 9 ++++++++- 5 files changed, 24 insertions(+), 11 deletions(-) diff --git a/packages/functions_client/lib/src/functions_client.dart b/packages/functions_client/lib/src/functions_client.dart index 63f76dd6..c83cc368 100644 --- a/packages/functions_client/lib/src/functions_client.dart +++ b/packages/functions_client/lib/src/functions_client.dart @@ -28,7 +28,8 @@ class FunctionsClient { _isolate = isolate ?? (YAJsonIsolate()..initialize()), _hasCustomIsolate = isolate != null, _httpClient = httpClient { - _log.config("Initialize FunctionsClient v$version"); + _log.config("Initialize FunctionsClient v$version with url: $url"); + _log.finest("Initialize with headers: $headers"); } /// Getter for the headers diff --git a/packages/gotrue/lib/src/gotrue_client.dart b/packages/gotrue/lib/src/gotrue_client.dart index 1235b112..ba5a0afb 100644 --- a/packages/gotrue/lib/src/gotrue_client.dart +++ b/packages/gotrue/lib/src/gotrue_client.dart @@ -105,23 +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; _log.config( 'Initialize GoTrueClient v$version with url: $_url, autoRefreshToken: $_autoRefreshToken, flowType: $_flowType, tickDuration: ${Constants.autoRefreshTickDuration}, tickThreshold: ${Constants.autoRefreshTickThreshold}'); - - final gotrueUrl = url ?? Constants.defaultGotrueUrl; - final gotrueHeader = { - ...Constants.defaultHeaders, - if (headers != null) ...headers, - }; + _log.finest('Initialize with headers: $_headers'); admin = GoTrueAdminApi( gotrueUrl, - headers: gotrueHeader, + headers: _headers, httpClient: httpClient, ); mfa = GoTrueMFAApi( diff --git a/packages/postgrest/lib/src/postgrest.dart b/packages/postgrest/lib/src/postgrest.dart index a705ebc0..6bace201 100644 --- a/packages/postgrest/lib/src/postgrest.dart +++ b/packages/postgrest/lib/src/postgrest.dart @@ -34,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") diff --git a/packages/realtime_client/lib/src/realtime_client.dart b/packages/realtime_client/lib/src/realtime_client.dart index 08d06ac9..8c6de0ef 100644 --- a/packages/realtime_client/lib/src/realtime_client.dart +++ b/packages/realtime_client/lib/src/realtime_client.dart @@ -140,6 +140,9 @@ class RealtimeClient { if (headers != null) ...headers, }, transport = transport ?? createWebSocketClient { + _log.config( + 'Initialize RealtimeClient with endpoint: $endPoint, timeout: $timeout, heartbeatIntervalMs: $heartbeatIntervalMs, longpollerTimeout: $longpollerTimeout, logLevel: $logLevel'); + _log.finest('Initialize with headers: $headers, params: $params'); final customJWT = this.headers['Authorization']?.split(' ').last; accessToken = customJWT ?? params['apikey']; diff --git a/packages/storage_client/lib/src/storage_client.dart b/packages/storage_client/lib/src/storage_client.dart index e9edf4bd..b51af7e4 100644 --- a/packages/storage_client/lib/src/storage_client.dart +++ b/packages/storage_client/lib/src/storage_client.dart @@ -1,10 +1,13 @@ import 'package:http/http.dart'; +import 'package:logging/logging.dart'; import 'package:storage_client/src/constants.dart'; import 'package:storage_client/src/storage_bucket_api.dart'; import 'package:storage_client/src/storage_file_api.dart'; +import 'package:storage_client/src/version.dart'; class SupabaseStorageClient extends StorageBucketApi { final int _defaultRetryAttempts; + final _log = Logger('supabase.storage'); /// To create a [SupabaseStorageClient], you need to provide an [url] and [headers]. /// @@ -42,7 +45,11 @@ class SupabaseStorageClient extends StorageBucketApi { url, {...Constants.defaultHeaders, ...headers}, httpClient: httpClient, - ); + ) { + _log.config( + 'Initialize SupabaseStorageClient v$version with url: $url, retryAttempts: $_defaultRetryAttempts'); + _log.finest('Initialize with headers: $headers'); + } /// Perform file operation in a bucket. /// From 13d6f3a7c082a8d52bd7836a71c367cc2a28bf60 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Thu, 3 Oct 2024 23:02:18 +0200 Subject: [PATCH 12/13] fix: save log stream subscription and print all from all loggers --- packages/supabase_flutter/lib/src/supabase.dart | 6 +++++- packages/supabase_flutter/lib/src/supabase_auth.dart | 2 +- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/packages/supabase_flutter/lib/src/supabase.dart b/packages/supabase_flutter/lib/src/supabase.dart index e6d0902e..1ff4b3cb 100644 --- a/packages/supabase_flutter/lib/src/supabase.dart +++ b/packages/supabase_flutter/lib/src/supabase.dart @@ -1,4 +1,5 @@ import 'dart:async'; +import 'dart:developer' as dev; import 'package:async/async.dart'; import 'package:flutter/foundation.dart'; @@ -90,7 +91,7 @@ class Supabase { _instance._debugEnable = debug ?? kDebugMode; if (_instance._debugEnable) { - _log.onRecord.listen((record) { + _instance._logSubscription = Logger('supabase').onRecord.listen((record) { if (record.level >= Level.INFO) { debugPrint( '${record.loggerName}: ${record.level.name}: ${record.message} ${record.error ?? ""}'); @@ -157,9 +158,12 @@ class Supabase { /// Wraps the `recoverSession()` call so that it can be terminated when `dispose()` is called late CancelableOperation _restoreSessionCancellableOperation; + StreamSubscription? _logSubscription; + /// Dispose the instance to free up resources. Future dispose() async { await _restoreSessionCancellableOperation.cancel(); + _logSubscription?.cancel(); client.dispose(); _instance._supabaseAuth.dispose(); _initialized = false; diff --git a/packages/supabase_flutter/lib/src/supabase_auth.dart b/packages/supabase_flutter/lib/src/supabase_auth.dart index fe61d42f..221a6ed9 100644 --- a/packages/supabase_flutter/lib/src/supabase_auth.dart +++ b/packages/supabase_flutter/lib/src/supabase_auth.dart @@ -288,7 +288,7 @@ class SupabaseAuth with WidgetsBindingObserver { Future _handleDeeplink(Uri uri) async { if (!_isAuthCallbackDeeplink(uri)) return; - _log.fine('handle deeplink uri: $uri'); + _log.finest('handle deeplink uri: $uri'); _log.info('handle deeplink uri'); try { From f508ef464271eac3421eca97b99f1cc9e0415931 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Fri, 4 Oct 2024 14:45:24 +0200 Subject: [PATCH 13/13] fix: log some realtime records with level FINE --- .../lib/src/realtime_client.dart | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/packages/realtime_client/lib/src/realtime_client.dart b/packages/realtime_client/lib/src/realtime_client.dart index 8c6de0ef..f5e6f5fa 100644 --- a/packages/realtime_client/lib/src/realtime_client.dart +++ b/packages/realtime_client/lib/src/realtime_client.dart @@ -171,7 +171,8 @@ class RealtimeClient { } try { - log('transport', 'connecting to $endPointURL'); + log('transport', 'connecting to $endPointURL', null); + log('transport', 'connecting', null, Level.FINE); connState = SocketStates.connecting; conn = transport(endPointURL, headers); @@ -219,7 +220,8 @@ class RealtimeClient { if (conn != null) { final oldState = connState; connState = SocketStates.disconnecting; - log('transport', 'disconnecting', {'code': code, 'reason': reason}); + log('transport', 'disconnecting', {'code': code, 'reason': reason}, + Level.FINE); // Connection cannot be closed while it's still connecting. Wait for connection to // be ready and then close it. @@ -236,7 +238,7 @@ class RealtimeClient { } connState = SocketStates.disconnected; reconnectTimer.reset(); - log('transport', 'disconnected'); + log('transport', 'disconnected', null, Level.FINE); } this.conn = null; @@ -265,8 +267,11 @@ class RealtimeClient { } /// Logs the message. Override `this.logger` for specialized logging. - void log([String? kind, String? msg, dynamic data]) { - _log.finest('$kind: $msg', data); + /// + /// [level] must be [Level.FINEST] for senitive data + void log( + [String? kind, String? msg, dynamic data, Level level = Level.FINEST]) { + _log.log(level, '$kind: $msg', data); logger?.call(kind, msg, data); } @@ -425,6 +430,7 @@ class RealtimeClient { void _onConnOpen() { log('transport', 'connected to $endPointURL'); + log('transport', 'connected', null, Level.FINE); _flushSendBuffer(); reconnectTimer.reset(); if (heartbeatTimer != null) heartbeatTimer!.cancel(); @@ -444,7 +450,7 @@ class RealtimeClient { if (statusCode != null) { event = RealtimeCloseEvent(code: statusCode, reason: conn?.closeReason); } - log('transport', 'close', event); + log('transport', 'close', event, Level.FINE); /// SocketStates.disconnected: by user with socket.disconnect() /// SocketStates.closed: NOT by user, should try to reconnect