From d1ecabd77881a0488d2d4b41ea5ee5abda6c5c35 Mon Sep 17 00:00:00 2001 From: Vinzent Date: Sat, 5 Oct 2024 00:55:44 +0200 Subject: [PATCH] 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 --- .../lib/src/functions_client.dart | 11 +++- packages/functions_client/pubspec.yaml | 1 + packages/gotrue/lib/src/broadcast_web.dart | 5 ++ packages/gotrue/lib/src/gotrue_client.dart | 44 +++++++++++---- packages/gotrue/pubspec.yaml | 1 + packages/postgrest/lib/src/postgrest.dart | 9 +++- .../postgrest/lib/src/postgrest_builder.dart | 12 ++++- packages/postgrest/pubspec.yaml | 1 + .../lib/src/realtime_client.dart | 54 ++++++++++++++----- packages/realtime_client/pubspec.yaml | 1 + packages/storage_client/lib/src/fetch.dart | 21 ++++++-- .../lib/src/storage_client.dart | 9 +++- packages/storage_client/pubspec.yaml | 1 + 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 + packages/supabase_flutter/README.md | 30 +++++++++++ .../supabase_flutter/lib/src/supabase.dart | 37 ++++++++----- .../lib/src/supabase_auth.dart | 42 +++++++-------- packages/supabase_flutter/pubspec.yaml | 1 + 24 files changed, 244 insertions(+), 65 deletions(-) diff --git a/packages/functions_client/lib/src/functions_client.dart b/packages/functions_client/lib/src/functions_client.dart index e9c3b52d..c83cc368 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,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 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 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 547fe631..338e294e 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.3 dev_dependencies: diff --git a/packages/gotrue/lib/src/broadcast_web.dart b/packages/gotrue/lib/src/broadcast_web.dart index b754666a..d53be14b 100644 --- a/packages/gotrue/lib/src/broadcast_web.dart +++ b/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); }, diff --git a/packages/gotrue/lib/src/gotrue_client.dart b/packages/gotrue/lib/src/gotrue_client.dart index 8a2c0e2b..ba5a0afb 100644 --- a/packages/gotrue/lib/src/gotrue_client.dart +++ b/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 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 signOut({ SignOutScope scope = SignOutScope.local, }) async { + _log.info('Signing out user with scope: $scope'); final accessToken = currentSession?.accessToken; if (scope != SignOutScope.others) { @@ -966,6 +975,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 +983,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 +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 _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,7 +1256,7 @@ class GoTrueClient { _removeSession(); notifyAllSubscribers(AuthChangeEvent.signedOut); } else { - _onAuthStateChangeController.addError(error, stack); + notifyException(error, stack); } _refreshTokenCompleter?.completeError(error); @@ -1240,7 +1264,7 @@ class GoTrueClient { rethrow; } catch (error, stack) { _refreshTokenCompleter?.completeError(error); - _onAuthStateChangeController.addError(error, stack); + notifyException(error, stack); rethrow; } finally { _refreshTokenCompleter = null; @@ -1265,6 +1289,7 @@ class GoTrueClient { }); } final state = AuthState(event, session, fromBroadcast: !broadcast); + _log.finest('onAuthStateChange: $state'); _onAuthStateChangeController.add(state); _onAuthStateChangeControllerSync.add(state); } @@ -1272,6 +1297,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 ed4b9889..89e8a7d7 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 diff --git a/packages/postgrest/lib/src/postgrest.dart b/packages/postgrest/lib/src/postgrest.dart index dca9b31e..6bace201 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. /// @@ -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 dispose() async { + _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 dab11063..d7ef48e3 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.finest("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.finest('$exception for request $_url'); + throw exception; } else if (body.length == 1) { body = body.first; } else { @@ -286,6 +293,9 @@ class PostgrestBuilder implements Future { ); } + _log.finest('$error from request: $_url'); + _log.fine('$error from request'); + throw error; } } diff --git a/packages/postgrest/pubspec.yaml b/packages/postgrest/pubspec.yaml index be5903aa..ade23ef1 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.3 meta: ^1.9.1 + logging: ^1.2.0 dev_dependencies: collection: ^1.16.0 diff --git a/packages/realtime_client/lib/src/realtime_client.dart b/packages/realtime_client/lib/src/realtime_client.dart index fe7eefd3..f5e6f5fa 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, @@ -127,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']; @@ -155,6 +171,8 @@ class RealtimeClient { } try { + log('transport', 'connecting to $endPointURL', null); + log('transport', 'connecting', null, Level.FINE); connState = SocketStates.connecting; conn = transport(endPointURL, headers); @@ -202,6 +220,8 @@ class RealtimeClient { if (conn != null) { final oldState = connState; connState = SocketStates.disconnecting; + 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. @@ -218,6 +238,7 @@ class RealtimeClient { } connState = SocketStates.disconnected; reconnectTimer.reset(); + log('transport', 'disconnected', null, Level.FINE); } this.conn = null; @@ -246,7 +267,11 @@ class RealtimeClient { } /// Logs the message. Override `this.logger` for specialized logging. - void log([String? kind, String? msg, dynamic 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); } @@ -405,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(); @@ -424,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 diff --git a/packages/realtime_client/pubspec.yaml b/packages/realtime_client/pubspec.yaml index 7e85cad6..3c67055c 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/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/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. /// 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 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 5e0aac6a..c27d9bd5 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'; @@ -61,6 +62,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; @@ -144,6 +147,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 24d21302..8932b4e9 100644 --- a/packages/supabase/pubspec.yaml +++ b/packages/supabase/pubspec.yaml @@ -17,6 +17,7 @@ dependencies: storage_client: 2.1.0 rxdart: '>=0.27.5 <0.29.0' yet_another_json_isolate: 2.0.3 + logging: ^1.2.0 dev_dependencies: lints: ^3.0.0 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 0608707c..1ff4b3cb 100644 --- a/packages/supabase_flutter/lib/src/supabase.dart +++ b/packages/supabase_flutter/lib/src/supabase.dart @@ -1,14 +1,20 @@ import 'dart:async'; +import 'dart:developer' as dev; 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. @@ -65,7 +71,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, @@ -82,6 +88,19 @@ class Supabase { !_instance._initialized, 'This instance is already initialized', ); + _instance._debugEnable = debug ?? kDebugMode; + + if (_instance._debugEnable) { + _instance._logSubscription = Logger('supabase').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 +125,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 +136,8 @@ class Supabase { _instance._supabaseAuth.recoverSession(), ); + _log.info('***** Supabase init completed *****'); + return _instance; } @@ -139,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; @@ -175,13 +197,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..221a6ed9 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); } } @@ -152,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(); } } @@ -178,6 +181,7 @@ class SupabaseAuth with WidgetsBindingObserver { // ignore: invalid_use_of_internal_member if (channel.isJoined) { + // ignore: invalid_use_of_internal_member channel.forceRejoin(); } } @@ -186,9 +190,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 +208,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 +218,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 +236,7 @@ class SupabaseAuth with WidgetsBindingObserver { } }, onError: (Object err, StackTrace stackTrace) { - _onErrorReceivingDeeplink(err.toString(), stackTrace); + _onErrorReceivingDeeplink(err, stackTrace); }, ); } @@ -273,12 +275,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 +288,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.finest('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 c5c26cea..fd48b230 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