diff --git a/packages/stream_core/CHANGELOG.md b/packages/stream_core/CHANGELOG.md index 391270dd..87a0b6a3 100644 --- a/packages/stream_core/CHANGELOG.md +++ b/packages/stream_core/CHANGELOG.md @@ -15,14 +15,18 @@ - `WebSocketConnectionState.isAutomaticReconnectionEnabled` is now `true` for an expired token, and remains `false` for token errors a fresh token cannot fix - `StreamApiError.isTokenExpiredError` now means code 40 only; the other token codes and a wrong API key are `isInvalidTokenError`. `isClientError` compares the HTTP `statusCode` against 400..499, rather than the Stream error `code`, which never falls in that range - `Result.getOrElse`, `getOrDefault`, `recover` and `recoverCatching` return the result's own type and no longer take a type parameter. To widen, widen the result (`Result widened = intResult`) or use `fold` +- Replaced the logger: `StreamLogger` is the handle you write with and a `StreamLogHandler` is where records go, so `Priority`, `MessageBuilder`, `Tag`, `IsLoggableValidator` and `Finder` are renamed or gone +- `LoggingInterceptor` writes through the logger rather than printing, so it is silent until an app asks for records. Its `logPrint` is now optional, and it takes a `tag` ### ✨ Features +- Added a logger the SDK now reports itself through, silent until an app names both a destination and a priority on `StreamLogger`, or hands a product client a `StreamLogConfig` carrying both - Added `TokenManager.setTokenProvider`, which points an existing manager at another user and expires the cached token; handed the identity it already has, it does nothing - Added optional `onTokenUpdated` callback to `TokenManager`, invoked after every successful token load - Added optional `rawValue` to `UserToken.anonymous`, so an anonymous token can carry a JWT granting restricted access; its `user_id` claim must be `!anon` - Added `UserToken.expiresAt`, from the token's `exp` claim, and `UserToken.isExpired`, which takes an optional `leeway` - Added `User.anonymousUserId`, the id every anonymous user has +- `User.guest` takes an `image`, which it previously dropped - Added `TokenManager.unconfigured`, for a client that exists before its user does, and `TokenManager.reset`, which drops the configured identity and its cached token - Added `teams` field to `User` class - Added `DioException.apiError`, the Stream API error a response carried, or `null` for anything else diff --git a/packages/stream_core/analysis_options.yaml b/packages/stream_core/analysis_options.yaml new file mode 100644 index 00000000..5f9579f3 --- /dev/null +++ b/packages/stream_core/analysis_options.yaml @@ -0,0 +1,14 @@ +include: ../../analysis_options.yaml + +analyzer: + exclude: + # The repository excludes generated files by a path relative to its own options file, which + # stops matching once that file is included from here. + - lib/**/*.*.dart + +linter: + rules: + # Dangling dartdoc links are invisible to the analyzer everywhere else in the repo, so a rename + # leaves references pointing at members that no longer exist. Kept on here, where the public + # API is documented heavily enough for that to matter. + comment_references: true diff --git a/packages/stream_core/lib/src/api/interceptors/auth_interceptor.dart b/packages/stream_core/lib/src/api/interceptors/auth_interceptor.dart index 4e5697fb..664d55ec 100644 --- a/packages/stream_core/lib/src/api/interceptors/auth_interceptor.dart +++ b/packages/stream_core/lib/src/api/interceptors/auth_interceptor.dart @@ -1,18 +1,23 @@ import 'package:dio/dio.dart'; import '../../errors.dart'; +import '../../logger.dart'; import '../../user.dart'; import '../stream_core_dio_error.dart'; /// Interceptor that signs every request with the caller's token. /// /// A request the server refuses for an expired token is retried once, carrying a replacement. +/// +/// Reports what it decided under `SC:HttpAuth`, including every reason it left a refused request +/// refused. Nothing is written until an app installs a [StreamLogHandler]. class AuthInterceptor extends Interceptor { /// Creates a new [AuthInterceptor]. - AuthInterceptor(this._dio, this._tokenManager); + AuthInterceptor(this._dio, this._tokenManager, {String tag = 'SC:HttpAuth'}) : _logger = StreamLogger(tag); final Dio _dio; final TokenManager _tokenManager; + final StreamLogger _logger; // Not a `QueuedInterceptor`: it frees a slot only once a handler completes, so the retry sent from // `onError` would wait behind the request holding it. `TokenManager` serialises the token loads. @@ -33,6 +38,8 @@ class AuthInterceptor extends Interceptor { return handler.next(options); } catch (e, stackTrace) { + _logger.w(() => 'no token to sign ${options.uri} with', error: e, stackTrace: stackTrace); + final error = ClientException( message: 'Failed to load auth token', stackTrace: stackTrace, @@ -62,9 +69,23 @@ class AuthInterceptor extends Interceptor { // A retry after a user switch would perform this request as the new user. final signedFor = options.queryParameters['user_id']; final canRefresh = signedFor == _tokenManager.userId && !_tokenManager.usesStaticProvider; - if (!canRefresh) return handler.next(err); + if (!canRefresh) { + _logger.d(() { + final reason = switch (_tokenManager.usesStaticProvider) { + true => 'the token provider is static and has nothing fresher to give', + false => 'it was signed for $signedFor, and the user is now ${_tokenManager.userId}', + }; - if (options.extra[_retriedKey] == true) return handler.next(err); + return 'not refreshing the token behind ${options.uri}: $reason'; + }); + + return handler.next(err); + } + + if (options.extra[_retriedKey] == true) { + _logger.w(() => 'the replacement token was refused too, leaving ${options.uri} failed'); + return handler.next(err); + } // Another request may have replaced it already, and expiring that would discard a valid token. if (options.headers['Authorization'] == _tokenManager.peekToken()?.rawValue) { @@ -78,11 +99,14 @@ class AuthInterceptor extends Interceptor { data: data is FormData ? data.clone() : data, ); + _logger.d(() => 'retrying ${options.uri} with a replacement token'); + try { // ignore: inference_failure_on_function_invocation final response = await _dio.fetch(retry); return handler.resolve(response); } on DioException catch (exception) { + _logger.w(() => 'the retry of ${options.uri} failed too', error: exception); return handler.reject(exception); } } diff --git a/packages/stream_core/lib/src/api/interceptors/logging_interceptor.dart b/packages/stream_core/lib/src/api/interceptors/logging_interceptor.dart index 46d14e98..bcbda632 100644 --- a/packages/stream_core/lib/src/api/interceptors/logging_interceptor.dart +++ b/packages/stream_core/lib/src/api/interceptors/logging_interceptor.dart @@ -4,24 +4,31 @@ import 'dart:math' as math; import 'package:dio/dio.dart'; -/// Step where we're logging +import '../../logger.dart'; + +/// The stage of a request a record came from. enum InterceptStep { - /// Request + /// A request on its way out. request, - /// Response + /// A response that came back. response, - /// Error + /// A request that failed. error, } -/// Function used to print the log +/// Takes one line of the log, in place of the logger. typedef LogPrint = void Function(InterceptStep step, Object object); -void _defaultLogPrint(InterceptStep step, Object object) => print(object); - -/// Interceptor dedicated to logging +/// An interceptor that reports each request and the response it gets. +/// +/// Records go out under `SC:Http`, at [StreamLogPriority.debug], or [StreamLogPriority.warning] +/// for a request that failed. Nothing is written, or even formatted, until an app installs a +/// [StreamLogHandler]. +/// +/// [requestHeader] puts the `Authorization` header in the record along with the rest, so consider +/// what reads these before turning it on. class LoggingInterceptor extends Interceptor { /// Creates a new [LoggingInterceptor]. LoggingInterceptor({ @@ -33,46 +40,67 @@ class LoggingInterceptor extends Interceptor { this.error = true, this.maxWidth = 120, this.compact = true, - this.logPrint = _defaultLogPrint, - }); + this.logPrint, + String tag = 'SC:Http', + }) : _logger = StreamLogger(tag); + + final StreamLogger _logger; - /// Print request [Options] + /// Whether to report the request line. final bool request; - /// Print request header [Options.headers] + /// Whether to report the request's headers, query parameters and extras. final bool requestHeader; - /// Print request data [RequestOptions.data] + /// Whether to report the request body. final bool requestBody; - /// Print [Response.data] + /// Whether to report the response body. final bool responseBody; - /// Print [Response.headers] + /// Whether to report the response headers. final bool responseHeader; - /// Print error message + /// Whether to report a request that failed. final bool error; - /// InitialTab count to logPrint json response + /// The indent a nested value starts at. static const initialTab = 1; - /// 1 tab length + /// One level of indent. static const tabStep = ' '; - /// Print compact json response + /// Whether to report a nested map on one line, rather than one key per line. final bool compact; - /// Width size per logPrint + /// The width a line is wrapped at. final int maxWidth; - /// Log printer; defaults logPrint log to console. - /// In flutter, you'd better use debugPrint. - /// you can also write log in a file. - void Function(InterceptStep step, Object object) logPrint; + /// Takes each line instead of the logger, for a caller routing them somewhere of its own. + final LogPrint? logPrint; + + // Consulted before a line is formatted, so a request costs nothing while nothing wants it. + bool _wants(InterceptStep step) { + if (logPrint != null) return true; + return _logger.isLoggable(_priorityOf(step)); + } + + StreamLogPriority _priorityOf(InterceptStep step) { + return switch (step) { + InterceptStep.error => StreamLogPriority.warning, + InterceptStep.request || InterceptStep.response => StreamLogPriority.debug, + }; + } + + void _write(InterceptStep step, Object object) { + if (logPrint case final logPrint?) return logPrint(step, object); + return _logger.log(_priorityOf(step), () => '$object'); + } @override void onRequest(RequestOptions options, RequestInterceptorHandler handler) { + if (!_wants(InterceptStep.request)) return super.onRequest(options, handler); + if (request) { _printRequestHeader(_logPrintRequest, options); } @@ -119,6 +147,8 @@ class LoggingInterceptor extends Interceptor { @override void onError(DioException err, ErrorInterceptorHandler handler) { + if (!_wants(InterceptStep.error)) return super.onError(err, handler); + if (error) { if (err.type == DioExceptionType.badResponse) { final uri = err.response?.requestOptions.uri; @@ -150,6 +180,8 @@ class LoggingInterceptor extends Interceptor { Response response, ResponseInterceptorHandler handler, ) { + if (!_wants(InterceptStep.response)) return super.onResponse(response, handler); + _printResponseHeader(_logPrintResponse, response); if (responseHeader) { final responseHeaders = {}; @@ -348,9 +380,9 @@ class LoggingInterceptor extends Interceptor { _printLine(logPrint, '╚'); } - void _logPrintRequest(Object object) => logPrint(InterceptStep.request, object); + void _logPrintRequest(Object object) => _write(InterceptStep.request, object); - void _logPrintResponse(Object object) => logPrint(InterceptStep.response, object); + void _logPrintResponse(Object object) => _write(InterceptStep.response, object); - void _logPrintError(Object object) => logPrint(InterceptStep.error, object); + void _logPrintError(Object object) => _write(InterceptStep.error, object); } diff --git a/packages/stream_core/lib/src/attachment/uploader/attachment_uploader.dart b/packages/stream_core/lib/src/attachment/uploader/attachment_uploader.dart index a02b1182..dc4724e9 100644 --- a/packages/stream_core/lib/src/attachment/uploader/attachment_uploader.dart +++ b/packages/stream_core/lib/src/attachment/uploader/attachment_uploader.dart @@ -51,7 +51,7 @@ class AttachmentUploadException implements Exception { /// ); /// ``` class StreamAttachmentUploader { - /// Creates a [StreamAttachmentUploader] with the specified [cdn] client. + /// Creates a [StreamAttachmentUploader] uploading through the given [CdnClient]. const StreamAttachmentUploader({ required this._cdn, }); diff --git a/packages/stream_core/lib/src/logger.dart b/packages/stream_core/lib/src/logger.dart index 3b79d90a..2e0e220d 100644 --- a/packages/stream_core/lib/src/logger.dart +++ b/packages/stream_core/lib/src/logger.dart @@ -1 +1,6 @@ +export 'logger/stream_log_config.dart'; +export 'logger/stream_log_filter.dart'; +export 'logger/stream_log_handler.dart'; +export 'logger/stream_log_priority.dart'; +export 'logger/stream_log_record.dart'; export 'logger/stream_logger.dart'; diff --git a/packages/stream_core/lib/src/logger/impl/external_logger.dart b/packages/stream_core/lib/src/logger/impl/external_logger.dart deleted file mode 100644 index 56a749f9..00000000 --- a/packages/stream_core/lib/src/logger/impl/external_logger.dart +++ /dev/null @@ -1,27 +0,0 @@ -import '../stream_logger.dart'; - -typedef ExternalFunction = - void Function( - Priority priority, - String tag, - MessageBuilder message, [ - Object? error, - StackTrace? stk, - ]); - -class ExternalStreamLogger extends StreamLogger { - const ExternalStreamLogger(this.external); - - final ExternalFunction external; - - @override - void log( - Priority priority, - String tag, - MessageBuilder message, [ - Object? error, - StackTrace? stk, - ]) { - return external.call(priority, tag, message, error, stk); - } -} diff --git a/packages/stream_core/lib/src/logger/impl/file_logger.dart b/packages/stream_core/lib/src/logger/impl/file_logger.dart deleted file mode 100644 index 880142e1..00000000 --- a/packages/stream_core/lib/src/logger/impl/file_logger.dart +++ /dev/null @@ -1,313 +0,0 @@ -import 'dart:async'; -import 'dart:io'; - -import 'package:collection/collection.dart'; -import 'package:intl/intl.dart'; - -import '../../utils/standard.dart'; -import '../stream_logger.dart'; - -const _tag = 'SV:FileLogger'; -const int _defaultSize = 12 * 1024 * 1024; - -const _shareableFilePrefix = 'stream_log_'; -const _internalFile0 = 'internal_0.txt'; -const _internalFile1 = 'internal_1.txt'; - -typedef FileLogSender = Future Function(File); - -final _timeFormat = DateFormat("yyyy-MM-dd HH:mm:ss''SSS"); -final _dateFormat = DateFormat('yyMMddHHmm_ss'); - -class FileStreamLogger extends StreamLogger { - FileStreamLogger( - this.config, { - this.sender, - this.console, - }); - - static final Finalizer _finalizer = Finalizer((ioSink) => ioSink.close()); - - final FileLogConfig config; - final FileLogSender? sender; - final StreamLogger? console; - - String get pathSeparator => Platform.pathSeparator; - - late final Directory _filesDir; - late final Directory _tempsDir; - late final File _file0; - late final File _file1; - - File? _currentFile; - IOSink? _currentIO; - - @override - Future log( - Priority priority, - String tag, - MessageBuilder message, [ - Object? error, - StackTrace? stk, - ]) async { - await _initIfNeeded(); - await _swapFiles(); - try { - _currentIO?.log(priority, tag, message, error, stk); - } catch (e, stk) { - _logE(() => '[log] failed: $e; $stk'); - } - } - - Future _initIfNeeded() async { - try { - if (_currentFile == null) { - _logD(() => '[initIfNeeded] no args'); - _filesDir = await config.filesDir; - _tempsDir = await config.tempsDir; - _file0 = File('${_filesDir.path}$pathSeparator$_internalFile0')..createSync(recursive: true); - _file1 = File('${_filesDir.path}$pathSeparator$_internalFile1')..createSync(recursive: true); - final File currentFile; - if (!_file0.existsSync() || !_file1.existsSync()) { - currentFile = _file0; - } else if (_file0.lastModifiedSync().isAfter(_file1.lastModifiedSync())) { - currentFile = _file0; - } else { - currentFile = _file1; - } - _currentFile = currentFile; - _currentIO = currentFile.openWrite(mode: FileMode.append).also((it) { - _finalizer.attach(this, it, detach: this); - }); - } - // ignore: empty_catches - } catch (e) {} - } - - Future _swapFiles() async { - try { - final curLen = _currentFile?.lengthSync() ?? 0; - final maxLogSize = config.maxLogSize; - if (curLen >= maxLogSize / 2) { - _logD(() => '[swapFiles] no args'); - final currentIO = _currentIO; - _currentIO = null; - await currentIO?.close(); - File currentFile; - if (_currentFile == _file0) { - currentFile = _file1; - } else { - currentFile = _file0; - } - currentFile - ..deleteSync() - ..createSync(recursive: true); - _currentFile = currentFile; - _currentIO = currentFile.openWrite(mode: FileMode.append).also((it) { - _finalizer.attach(this, it, detach: this); - }); - } - } catch (e, stk) { - _logE(() => '[swapFiles] failed: $e; $stk'); - } - } - - Future clear() async { - try { - _logD( - () => - '[clear] before; file0: ${_file0.lengthSync()}, ' - 'file1: ${_file1.lengthSync()}', - ); - final currentIO = _currentIO; - _currentIO = null; - await currentIO?.close(); - - _file0 - ..deleteSync() - ..createSync(recursive: true); - _file1 - ..deleteSync() - ..createSync(recursive: true); - - _currentFile = _file0; - _currentIO = _currentFile?.openWrite(mode: FileMode.append).also((it) { - _finalizer.attach(this, it, detach: this); - }); - _logV( - () => - '[clear] after; file0: ${_file0.lengthSync()}, ' - 'file1: ${_file1.lengthSync()}', - ); - } catch (e, stk) { - _logE(() => '[clear] failed: $e; $stk'); - rethrow; - } - } - - Future share() async { - _logD(() => '[share] no args'); - final sender = this.sender; - if (sender == null) { - _logW(() => '[share] rejected (sender is not provided)'); - throw const FileLoggerException('Sender is not provided'); - } - try { - final shareable = await prepareShareable(); - _logV(() => '[share] shareable: $shareable(${shareable.existsSync()})'); - return await sender.call(shareable); - } catch (e, stk) { - _logE(() => '[share] failed: $e; $stk'); - rethrow; - } - } - - Future prepareShareable() async { - final filename = - '$_shareableFilePrefix' - '${_dateFormat.format(DateTime.now())}.txt'; - final out = File('${_tempsDir.path}$pathSeparator$filename')..createSync(recursive: true); - _logD(() => '[prepareShareable] out: $out'); - - IOSink? writer; - try { - writer = out.openWrite(mode: FileMode.append); - writer.writeln(await _buildHeader()); - final filtered = [ - _file0, - _file1, - ].where((file) => file.existsSync()).sortedBy((file) => file.lastModifiedSync()); - for (final file in filtered) { - if (file.existsSync()) { - await writer.addStream(file.openRead()); - } - } - await writer.flush(); - } catch (e, stk) { - _logE(() => '[prepareShareable] failed: $e; $stk'); - } finally { - await writer?.close(); - } - return out; - } - - Future _buildHeader() async { - final buffer = StringBuffer(); - buffer - ..write('|=============================================================') - ..write('\n') - ..write('|Logs Collected: ') - ..write(_timeFormat.format(DateTime.now())) - ..write('\n') - ..write('|App Version: ') - ..write(await config.appVersion) - ..write('\n') - ..write('|Device Info: '); - - final deviceInfo = await config.deviceInfo; - if (deviceInfo is Map) { - buffer.write('\n'); - deviceInfo.forEach((key, value) { - buffer - ..write('| ') - ..write(key) - ..write(': ') - ..write(value) - ..write('\n'); - }); - } else { - buffer - ..write(deviceInfo) - ..write('\n'); - } - - buffer - ..write('|=============================================================') - ..write('\n') - ..write('|'); - - return buffer.toString(); - } - - void _logV(MessageBuilder message) { - console?.log(Priority.verbose, _tag, message); - } - - void _logD(MessageBuilder message) { - console?.log(Priority.debug, _tag, message); - } - - // ignore: unused_element - void _logI(MessageBuilder message) { - console?.log(Priority.info, _tag, message); - } - - void _logW(MessageBuilder message) { - console?.log(Priority.warning, _tag, message); - } - - void _logE(MessageBuilder message) { - console?.log(Priority.error, _tag, message); - } -} - -abstract class FileLogConfig { - int get maxLogSize => _defaultSize; - - Future get filesDir; - - Future get tempsDir; - - Future get appVersion; - - Future get deviceInfo; -} - -extension on IOSink { - void log( - Priority priority, - String tag, - MessageBuilder message, [ - Object? error, - StackTrace? stk, - ]) { - final formattedDateTime = _timeFormat.format(DateTime.now()); - final formattedPriority = priority.stringify(); - final formatterPrefix = '$formattedDateTime $formattedPriority [$tag]: '; - - write(formatterPrefix); - writeln(message()); - } -} - -extension on Priority { - String stringify() { - switch (this) { - case Priority.verbose: - return 'V'; - case Priority.debug: - return 'D'; - case Priority.info: - return 'I'; - case Priority.warning: - return 'W'; - case Priority.error: - return 'E'; - case Priority.none: - return 'X'; - } - } -} - -class FileLoggerException implements Exception { - const FileLoggerException([this.message]); - - final dynamic message; - - @override - String toString() { - final message = this.message; - if (message == null) return 'FileLoggerException'; - return 'FileLoggerException: $message'; - } -} diff --git a/packages/stream_core/lib/src/logger/impl/tagged_logger.dart b/packages/stream_core/lib/src/logger/impl/tagged_logger.dart deleted file mode 100644 index 5b9bb926..00000000 --- a/packages/stream_core/lib/src/logger/impl/tagged_logger.dart +++ /dev/null @@ -1,40 +0,0 @@ -import '../stream_log.dart'; -import '../stream_logger.dart'; - -TaggedLogger taggedLogger({required Tag tag}) { - return TaggedLogger(tag); -} - -class TaggedLogger { - const TaggedLogger(this.tag); - - final Tag tag; - - void v(MessageBuilder message) { - streamLog.v(tag, message); - } - - void d(MessageBuilder message) { - streamLog.d(tag, message); - } - - void i(MessageBuilder message) { - streamLog.i(tag, message); - } - - void w(MessageBuilder message) { - streamLog.w(tag, message); - } - - void e(MessageBuilder message) { - streamLog.e(tag, message); - } - - void log(Priority priority, MessageBuilder message) { - streamLog.log(priority, tag, message); - } - - void logConditional(String? Function(Priority priority) messageBuilder) { - streamLog.logConditional(tag, messageBuilder); - } -} diff --git a/packages/stream_core/lib/src/logger/logger.dart b/packages/stream_core/lib/src/logger/logger.dart deleted file mode 100644 index 3f614f87..00000000 --- a/packages/stream_core/lib/src/logger/logger.dart +++ /dev/null @@ -1,3 +0,0 @@ -export 'impl/tagged_logger.dart'; -export 'stream_log.dart'; -export 'stream_logger.dart'; diff --git a/packages/stream_core/lib/src/logger/stream_log.dart b/packages/stream_core/lib/src/logger/stream_log.dart deleted file mode 100644 index f4709d12..00000000 --- a/packages/stream_core/lib/src/logger/stream_log.dart +++ /dev/null @@ -1,151 +0,0 @@ -// ignore_for_file: omit_obvious_property_types - -import 'stream_logger.dart'; - -StreamLog get streamLog => StreamLog(); - -class StreamLog { - factory StreamLog() { - return _instance; - } - - StreamLog._(); - - static final _instance = StreamLog._(); - - StreamLogger _logger = const SilentStreamLogger(); - IsLoggableValidator _validator = (Priority priority, Tag tag) => false; - Finder _finder = _defaultFinder; - Priority _priority = Priority.none; - - static StreamLog get instance => _instance; - static List excludeTags = []; - static List includeOnlyTags = []; - - set logger(StreamLogger logger) { - _logger = logger; - } - - set priority(Priority priority) { - _priority = priority; - _validator = (logPriority, tag) { - if (excludeTags.isNotEmpty && excludeTags.contains(tag)) { - return false; - } - - if (includeOnlyTags.isNotEmpty && !includeOnlyTags.contains(tag)) { - return false; - } - - return logPriority.index >= priority.index; - }; - } - - set validator(IsLoggableValidator validator) { - _validator = validator; - } - - set finder(Finder finder) { - _finder = finder; - } - - T? find([dynamic criteria]) { - return _finder.call(criteria); - } - - void v(Tag tag, MessageBuilder message) { - if (_validator.call(Priority.verbose, tag)) { - _logger.log(Priority.verbose, tag, message); - } - } - - void d(Tag tag, MessageBuilder message) { - if (_validator.call(Priority.debug, tag)) { - _logger.log(Priority.debug, tag, message); - } - } - - void i(Tag tag, MessageBuilder message) { - if (_validator.call(Priority.info, tag)) { - _logger.log(Priority.info, tag, message); - } - } - - void w(Tag tag, MessageBuilder message) { - if (_validator.call(Priority.warning, tag)) { - _logger.log(Priority.warning, tag, message); - } - } - - void e(Tag tag, MessageBuilder message) { - if (_validator.call(Priority.error, tag)) { - _logger.log(Priority.error, tag, message); - } - } - - void log(Priority priority, Tag tag, MessageBuilder message) { - if (_validator.call(priority, tag)) { - _logger.log(priority, tag, message); - } - } - - void logConditional( - Tag tag, - String? Function(Priority priority) messageBuilder, - ) { - final message = messageBuilder(_priority); - if (message != null && message.isNotEmpty) { - _logger.log( - _priority, - tag, - () => message, - ); - } - } - - static T? _defaultFinder([dynamic criteria]) { - final logger = _instance._logger; - if (logger is T) return logger; - - if (logger is CompositeStreamLogger) { - for (final child in logger.children) { - if (child is T) return child; - } - } - return null; - } -} - -class SilentStreamLogger extends StreamLogger { - const SilentStreamLogger(); - - @override - void log( - Priority priority, - String tag, - MessageBuilder message, [ - Object? error, - StackTrace? stk, - ]) { - /* no-op */ - } -} - -class CompositeStreamLogger extends StreamLogger { - const CompositeStreamLogger(this.children); - - final List children; - - @override - void log( - Priority priority, - String tag, - MessageBuilder message, [ - Object? error, - StackTrace? stk, - ]) { - for (final child in children) { - child.log(priority, tag, message, error, stk); - } - } -} diff --git a/packages/stream_core/lib/src/logger/stream_log_config.dart b/packages/stream_core/lib/src/logger/stream_log_config.dart new file mode 100644 index 00000000..acedd2a1 --- /dev/null +++ b/packages/stream_core/lib/src/logger/stream_log_config.dart @@ -0,0 +1,66 @@ +import 'stream_log_filter.dart'; +import 'stream_log_handler.dart'; +import 'stream_log_priority.dart'; +import 'stream_logger.dart'; + +/// How much a Stream SDK reports, and where those records go. +/// +/// What a product client takes in place of setting [StreamLogger.handler] and its neighbours +/// itself, so that every Stream SDK asks for logging the same way and settles it in one step: +/// +/// ```dart +/// StreamFeedsClient( +/// apiKey: 'your-api-key', +/// user: user, +/// config: const FeedsConfig( +/// logging: StreamLogConfig(priority: StreamLogPriority.debug), +/// ), +/// ); +/// ``` +/// +/// The logger is shared by every Stream SDK in a process, so a client that is given no config +/// installs nothing at all rather than deciding for the others. +class StreamLogConfig { + /// Creates a [StreamLogConfig]. + const StreamLogConfig({ + this.priority = StreamLogPriority.warning, + this.handler = defaultHandler, + this.filter, + }); + + /// Where records go when a config names no handler of its own. + static const defaultHandler = StreamLogHandler.console(); + + /// The lowest priority worth reporting. + /// + /// [StreamLogPriority.none] silences a logger another SDK configured. Ignored where [filter] is + /// given, which decides the same thing in more detail. + final StreamLogPriority priority; + + /// Where records go. + /// + /// Compose with [defaultHandler] to keep the console alongside a handler of your own, and leave + /// it out of the build your users run by naming it only where the app says it is developing: + /// + /// ```dart + /// handler: StreamLogHandler.composite([ + /// if (kDebugMode) StreamLogConfig.defaultHandler, + /// myCrashReporterHandler, + /// ]), + /// ``` + final StreamLogHandler handler; + + /// Which records are built at all, for a rule [priority] cannot express. + /// + /// Holds one subsystem to a different threshold than the rest: + /// + /// ```dart + /// StreamLogConfig( + /// filter: StreamLogFilter.prefix( + /// {'SF:Ws': StreamLogPriority.verbose}, + /// otherwise: StreamLogPriority.warning, + /// ), + /// ) + /// ``` + final StreamLogFilter? filter; +} diff --git a/packages/stream_core/lib/src/logger/stream_log_filter.dart b/packages/stream_core/lib/src/logger/stream_log_filter.dart new file mode 100644 index 00000000..3e27f7cf --- /dev/null +++ b/packages/stream_core/lib/src/logger/stream_log_filter.dart @@ -0,0 +1,86 @@ +import 'stream_log_priority.dart'; + +/// Decides which records are worth building, independently of where they end up. +/// +/// A filter answers the question a handler cannot answer cheaply: whether a record is wanted at +/// all. It is consulted before the message is built, so a record it rejects costs nothing. +/// +/// The default admits everything and leaves the decision to the handler, which is enough until an +/// app wants one subsystem louder than the rest: +/// +/// ```dart +/// StreamLogger.filter = const StreamLogFilter.prefix( +/// {'SC:Ws': StreamLogPriority.verbose}, +/// otherwise: StreamLogPriority.warning, +/// ); +/// ``` +abstract class StreamLogFilter { + /// Creates a [StreamLogFilter]. + const StreamLogFilter(); + + /// A filter admitting every record, leaving the decision to the handler. + const factory StreamLogFilter.always() = _AlwaysFilter; + + /// A filter admitting records at [priority] or above, whatever their tag. + const factory StreamLogFilter.minPriority(StreamLogPriority priority) = _MinPriorityFilter; + + /// A filter admitting records by the prefix of their tag. + /// + /// The longest prefix in [priorities] matching a tag decides it, so a broad rule can be narrowed by + /// a longer one. A tag matching no prefix is held to [otherwise]. + /// + /// What a record costs grows with the number of rules, so consider keeping [priorities] to the + /// subsystems actually being tuned. + const factory StreamLogFilter.prefix( + Map priorities, { + StreamLogPriority otherwise, + }) = _PrefixFilter; + + /// Whether a record at [priority] from [tag] is worth building. + bool isLoggable(StreamLogPriority priority, String tag); +} + +final class _AlwaysFilter extends StreamLogFilter { + const _AlwaysFilter(); + + @override + bool isLoggable(StreamLogPriority priority, String tag) => true; +} + +final class _MinPriorityFilter extends StreamLogFilter { + const _MinPriorityFilter(this.priority); + + final StreamLogPriority priority; + + @override + bool isLoggable(StreamLogPriority priority, String tag) { + // `none` outranks every severity, so comparing against it would admit the records a threshold + // of `none` exists to reject. + if (this.priority == StreamLogPriority.none) return false; + return priority >= this.priority; + } +} + +final class _PrefixFilter extends StreamLogFilter { + const _PrefixFilter(this.priorities, {this.otherwise = StreamLogPriority.warning}); + + final Map priorities; + final StreamLogPriority otherwise; + + @override + bool isLoggable(StreamLogPriority priority, String tag) { + var matched = otherwise; + var matchedLength = -1; + + for (final MapEntry(key: prefix, value: threshold) in priorities.entries) { + if (prefix.length <= matchedLength) continue; + if (!tag.startsWith(prefix)) continue; + + matched = threshold; + matchedLength = prefix.length; + } + + if (matched == StreamLogPriority.none) return false; + return priority >= matched; + } +} diff --git a/packages/stream_core/lib/src/logger/stream_log_handler.dart b/packages/stream_core/lib/src/logger/stream_log_handler.dart new file mode 100644 index 00000000..45a6559d --- /dev/null +++ b/packages/stream_core/lib/src/logger/stream_log_handler.dart @@ -0,0 +1,145 @@ +import 'stream_log_filter.dart'; +import 'stream_log_record.dart'; +import 'stream_logger.dart'; + +/// Receives a log record on behalf of a [StreamLogHandler.from] handler. +typedef StreamLogCallback = void Function(StreamLogRecord record); + +/// Where log records go. +/// +/// An app installs one on [StreamLogger.handler], or passes one to a single component. Nothing is +/// installed by default, so an SDK stays silent until asked. +/// +/// [StreamLogHandler.console] covers the common case. Subclass to send records somewhere else, +/// such as a crash reporter: +/// +/// ```dart +/// final class CrashReporterHandler extends StreamLogHandler { +/// const CrashReporterHandler(); +/// +/// @override +/// void handle(StreamLogRecord record) => Crashlytics.instance.log('$record'); +/// } +/// ``` +/// +/// Wrap it in [StreamLogHandler.filtered] to hold it to a threshold, rather than comparing +/// priorities inside it. +abstract class StreamLogHandler { + /// Creates a [StreamLogHandler]. + const StreamLogHandler(); + + /// A handler writing records to the console. + /// + /// Reaches the console of whatever runs the SDK — stdout under the Dart VM, the device log + /// under Flutter, the browser console on the web — without depending on Flutter. + /// + /// Android discards console output that arrives in a burst of hundreds of lines. A connection + /// reporting itself comes nowhere near that, but a product logging heavily can, so consider + /// handing records to `debugPrint`, which paces them to stay under the limit: + /// + /// ```dart + /// StreamLogger.handler = StreamLogHandler.from((record) => debugPrint('$record')); + /// ``` + /// + /// Emits whatever [StreamLogger.priority] admits. Wrap in [StreamLogHandler.filtered] to hold + /// this destination quieter than the rest. + const factory StreamLogHandler.console() = _ConsoleHandler; + + /// A handler giving every record to each of [handlers], in order. + /// + /// Every record reaches every one of them, so wrap any that should see less in + /// [StreamLogHandler.filtered] — that is how one composite serves a verbose console during + /// development and a crash reporter that only wants failures. + const factory StreamLogHandler.composite(List handlers) = _CompositeHandler; + + /// A handler giving [handler] only the records [filter] admits. + /// + /// The way one destination is held to a threshold of its own, which is the only direction a + /// handler can move: a filter here narrows what `StreamLogger.filter` already admitted, and + /// cannot widen it. + /// + /// ```dart + /// StreamLogHandler.composite([ + /// fileLogger, + /// StreamLogHandler.filtered( + /// const StreamLogFilter.minPriority(StreamLogPriority.error), + /// const StreamLogHandler.console(), + /// ), + /// ]); + /// ``` + /// + /// [StreamLogFilter.prefix] narrows by tag rather than priority, which is how one SDK's records + /// are sent somewhere the rest are not. + const factory StreamLogHandler.filtered(StreamLogFilter filter, StreamLogHandler handler) = _FilteredHandler; + + /// A handler passing every record to [callback]. + /// + /// The shortest route into a logging facility an app already has. + const factory StreamLogHandler.from(StreamLogCallback callback) = _CallbackHandler; + + /// A handler that discards every record. + /// + /// What [StreamLogger.handler] is until an app installs something else. + static const StreamLogHandler silent = _SilentHandler(); + + /// Takes a record the filter admitted. + /// + /// Whether a record is worth building at all is `StreamLogger.filter`'s decision, so a handler + /// receives whatever that admitted and discards here what it does not want. See + /// [StreamLogHandler.filtered] for holding one destination to less than the rest. + void handle(StreamLogRecord record); +} + +final class _SilentHandler extends StreamLogHandler { + const _SilentHandler(); + + @override + void handle(StreamLogRecord record) { + /* no-op */ + } +} + +final class _ConsoleHandler extends StreamLogHandler { + const _ConsoleHandler(); + + @override + void handle(StreamLogRecord record) { + print('${record.time} $record'); + if (record.error case final error?) print(error); + if (record.stackTrace case final stackTrace?) print(stackTrace); + } +} + +final class _CompositeHandler extends StreamLogHandler { + const _CompositeHandler(this.handlers); + + final List handlers; + + @override + void handle(StreamLogRecord record) { + for (final handler in handlers) { + handler.handle(record); + } + } +} + +final class _FilteredHandler extends StreamLogHandler { + const _FilteredHandler(this.filter, this.handler); + + final StreamLogFilter filter; + final StreamLogHandler handler; + + @override + void handle(StreamLogRecord record) { + if (filter.isLoggable(record.priority, record.tag)) handler.handle(record); + } +} + +final class _CallbackHandler extends StreamLogHandler { + const _CallbackHandler(this.callback); + + final StreamLogCallback callback; + + @override + void handle(StreamLogRecord record) => callback(record); +} diff --git a/packages/stream_core/lib/src/logger/stream_log_priority.dart b/packages/stream_core/lib/src/logger/stream_log_priority.dart new file mode 100644 index 00000000..b89baa88 --- /dev/null +++ b/packages/stream_core/lib/src/logger/stream_log_priority.dart @@ -0,0 +1,54 @@ +/// The severity of a log record. +/// +/// Ordered from least to most severe, so a threshold can be expressed by comparing a record's +/// priority against it. [none] outranks every real severity, and so admits nothing. +enum StreamLogPriority implements Comparable { + /// Fine-grained detail on a hot path, such as an individual heartbeat. + verbose(level: 2, emoji: '🔍', label: 'V'), + + /// The steps a subsystem takes, such as a connection changing state. + debug(level: 3, emoji: '🔧', label: 'D'), + + /// A milestone worth seeing without opting into the full trace. + info(level: 4, emoji: 'ℹ️', label: 'I'), + + /// Something recoverable that the caller may still want to act on. + warning(level: 5, emoji: '⚠️', label: 'W'), + + /// A failure. + error(level: 6, emoji: '🚨', label: 'E'), + + /// A threshold that admits nothing, not a severity a record can carry. + /// + /// A filter held to it rejects every record, whatever its severity. + none(level: 7, emoji: '📣', label: '*'); + + const StreamLogPriority({required this.level, required this.emoji, required this.label}); + + /// The rank of this priority, where a higher number is more severe. + final int level; + + /// A glyph identifying this priority at a glance, for handlers that render one. + final String emoji; + + /// A single-letter abbreviation of this priority, for handlers that render one. + final String label; + + @override + String toString() => name; + + @override + int compareTo(StreamLogPriority other) => level.compareTo(other.level); + + /// Whether this priority is less severe than [other]. + bool operator <(StreamLogPriority other) => level < other.level; + + /// Whether this priority is no more severe than [other]. + bool operator <=(StreamLogPriority other) => level <= other.level; + + /// Whether this priority is more severe than [other]. + bool operator >(StreamLogPriority other) => level > other.level; + + /// Whether this priority is at least as severe as [other]. + bool operator >=(StreamLogPriority other) => level >= other.level; +} diff --git a/packages/stream_core/lib/src/logger/stream_log_record.dart b/packages/stream_core/lib/src/logger/stream_log_record.dart new file mode 100644 index 00000000..68667b4a --- /dev/null +++ b/packages/stream_core/lib/src/logger/stream_log_record.dart @@ -0,0 +1,54 @@ +import 'package:clock/clock.dart'; + +import 'stream_log_priority.dart'; + +/// A single log record, as a handler receives it. +/// +/// Built only once a record has passed every gate, so nothing here is paid for by a record that +/// is filtered out. +/// +/// Fields may be added over time. Consider implementing `StreamLogHandler` rather than depending +/// on this constructor, which is called by the SDK and not by handlers. +final class StreamLogRecord { + /// Creates a [StreamLogRecord], stamping it with the current [time] and the next + /// [sequenceNumber]. + StreamLogRecord({ + required this.priority, + required this.tag, + required this.message, + this.error, + this.stackTrace, + }) : time = clock.now(), + sequenceNumber = _sequence++; + + static var _sequence = 0; + + /// The severity of this record. + final StreamLogPriority priority; + + /// The component this record came from. + final String tag; + + /// What happened. + final String message; + + /// When this record was created. + /// + /// The same instant for every handler that receives it, so one record does not turn up at two + /// slightly different times in two destinations. + final DateTime time; + + /// The position of this record in the order they were created, counting from zero. + /// + /// Records reaching a handler out of order, or with a gap, were reordered or dropped on the way. + final int sequenceNumber; + + /// The cause, when this record describes a failure. + final Object? error; + + /// Where the [error] was thrown, when it is known. + final StackTrace? stackTrace; + + @override + String toString() => '${priority.emoji} ${priority.label}/$tag: $message'; +} diff --git a/packages/stream_core/lib/src/logger/stream_logger.dart b/packages/stream_core/lib/src/logger/stream_logger.dart index e0c9f4fb..222bc003 100644 --- a/packages/stream_core/lib/src/logger/stream_logger.dart +++ b/packages/stream_core/lib/src/logger/stream_logger.dart @@ -1,63 +1,266 @@ -final _priorityEmojiMapper = { - Priority.error: '🚨', - Priority.warning: '⚠️', - Priority.info: 'ℹ️', - Priority.debug: '🔧', - Priority.verbose: '🔍', -}; +import 'package:meta/meta.dart'; -final _priorityNameMapper = { - Priority.error: 'E', - Priority.warning: 'W', - Priority.info: 'I', - Priority.debug: 'D', - Priority.verbose: 'V', -}; +import 'stream_log_config.dart'; +import 'stream_log_filter.dart'; +import 'stream_log_handler.dart'; +import 'stream_log_priority.dart'; +import 'stream_log_record.dart'; -abstract class StreamLogger { - const StreamLogger(); +/// Builds a log message on demand. +/// +/// Called only once a record is known to be wanted, so an interpolation this expensive is never +/// paid for by a record that is dropped. +typedef StreamLogMessage = String Function(); - String emoji(Priority priority) => _priorityEmojiMapper[priority] ?? '📣'; +/// Writes log records under a tag. +/// +/// Holding one costs nothing and it can be created anywhere — a field, a constructor, or a +/// top-level `final` in a file with no class at all: +/// +/// ```dart +/// final _log = StreamLogger('SF:SdpEditor'); +/// +/// String editSdp(String sdp) { +/// _log.d(() => 'rewriting $sdp'); +/// ... +/// } +/// ``` +/// +/// Where records go is resolved when a record is written, not when the logger is created, so a +/// logger built at class-load picks up whatever the app installs later: +/// +/// ```dart +/// StreamLogger.handler = const StreamLogHandler.console(); +/// StreamLogger.priority = StreamLogPriority.debug; +/// ``` +/// +/// Records go to one place, so routing two SDKs apart is a matter of a [StreamLogHandler] reading +/// [StreamLogRecord.tag] rather than of finding every component that had to be handed something. +/// For the exception, see [StreamLogger.detached]. +final class StreamLogger { + /// Creates a [StreamLogger] writing under [tag] to whatever the app has installed. + const StreamLogger(this.tag) : _handler = null, _filter = null; - String name(Priority priority) => _priorityNameMapper[priority] ?? '*'; + /// Creates a [StreamLogger] that ignores what the app has installed. + /// + /// Records go to the given handler and are gated by the given filter alone, so a detached logger + /// neither reads nor disturbs [StreamLogger.handler]. Use one to capture a component's records in + /// a test, or to hold a subsystem to its own threshold and destination: + /// + /// ```dart + /// final _log = StreamLogger.detached( + /// 'SF:Upload', + /// handler: const StreamLogHandler.console(), + /// filter: const StreamLogFilter.minPriority(StreamLogPriority.debug), + /// ); + /// ``` + /// + /// A priority of its own is a [StreamLogFilter.minPriority], which is why there is no separate one. + /// [filter] defaults to admitting [StreamLogPriority.warning] and above, so a detached logger + /// reports without an app naming a priority for it. Pass [StreamLogFilter.always] to leave the + /// decision entirely to the handler. + const StreamLogger.detached( + this.tag, { + required StreamLogHandler this._handler, + StreamLogFilter this._filter = const .minPriority(.warning), + }); - void log( - Priority priority, - String tag, - MessageBuilder message, [ - Object? error, - StackTrace? stk, - ]); -} + final StreamLogFilter? _filter; + final StreamLogHandler? _handler; + + /// The name records from this logger carry. + /// + /// Conventionally an SDK prefix and a component, such as `SC:WsClient`, so records from several + /// Stream SDKs stay apart in one log and a prefix can select a subsystem. + /// + /// See also: + /// + /// * [StreamLogFilter.prefix], which turns this convention into a threshold per subsystem. + final String tag; + + static StreamLogFilter _filterOrDefault = const .minPriority(.none); + static StreamLogHandler _handlerOrDefault = StreamLogHandler.silent; + + StreamLogFilter get _effectiveFilter => _filter ?? _filterOrDefault; + StreamLogHandler get _effectiveHandler => _handler ?? _handlerOrDefault; + + /// Installs where every record goes, other than those from a [StreamLogger.detached] logger. + /// + /// A destination on its own reports nothing: name a [priority] beside it, or hand both to + /// [configure] at once. Setting it applies to loggers that already exist, including any built at + /// class-load, because a logger resolves this when it writes rather than when it was created. + /// + /// ```dart + /// StreamLogger.handler = const StreamLogHandler.console(); + /// StreamLogger.priority = StreamLogPriority.warning; + /// ``` + /// + /// Write-only, so nothing can come to depend on what happens to be installed. Consider + /// [StreamLogHandler.composite] to send records to more than one place. + static set handler(StreamLogHandler handler) => _handlerOrDefault = handler; + + /// Installs the lowest priority worth building a record for. + /// + /// Nothing is admitted until this is named, so an SDK stays silent in an app that has not asked + /// for records, and a record it rejects is never built: + /// + /// ```dart + /// StreamLogger.priority = StreamLogPriority.debug; + /// ``` + /// + /// Shorthand for a [StreamLogFilter.minPriority], so this and [filter] are one setting: whichever + /// is written last decides. + static set priority(StreamLogPriority priority) => filter = .minPriority(priority); + + /// Installs which records are built at all, for a rule [priority] cannot express. + /// + /// ```dart + /// StreamLogger.filter = const StreamLogFilter.prefix( + /// {'SC:Ws': StreamLogPriority.verbose}, + /// otherwise: StreamLogPriority.warning, + /// ); + /// ``` + static set filter(StreamLogFilter filter) => _filterOrDefault = filter; -typedef MessageBuilder = String Function(); -typedef Tag = String; -typedef IsLoggableValidator = bool Function(Priority, Tag); -typedef Finder = T? Function([dynamic criteria]); + /// Installs [config] in one step, or leaves the logger untouched where it is null. + /// + /// What a product client calls with whatever its own config was given, so that an app running + /// two Stream SDKs gets the same answer from both, and neither decides logging for an app that + /// never asked: + /// + /// ```dart + /// StreamLogger.configure(config.logging); + /// ``` + /// + /// A config replaces both settings outright, so anything installed through [filter] before this + /// is lost — including to a config that named only a [priority]. Put the rule in + /// [StreamLogConfig.filter] instead, where a client carries it rather than flattening it. + /// + /// One logger serves the process, so this decides logging for every Stream SDK in it, not only + /// the one whose config it came from, and two clients configured differently settle on whichever + /// was constructed last. An app wanting one SDK's records and not another's says so by the prefix + /// their tags carry: + /// + /// ```dart + /// StreamLogConfig( + /// filter: StreamLogFilter.prefix( + /// {'SF:': StreamLogPriority.debug}, + /// otherwise: StreamLogPriority.none, + /// ), + /// ) + /// ``` + static void configure(StreamLogConfig? config) { + if (config == null) return; -enum Priority implements Comparable { - verbose(level: 2), - debug(level: 3), - info(level: 4), - warning(level: 5), - error(level: 6), - none(level: 7); + _handlerOrDefault = config.handler; + _filterOrDefault = config.filter ?? .minPriority(config.priority); + } - const Priority({required this.level}); + /// Puts [handler] and [priority] back to what they were before anything was installed. + /// + /// What an app installs is process-wide, so a test that installs a handler and leaves it there + /// changes what every later test sees. Restoring by hand means naming the defaults, which a + /// write-only setter gives no way to read: + /// + /// ```dart + /// tearDown(StreamLogger.reset); + /// ``` + @visibleForTesting + static void reset() { + _handlerOrDefault = StreamLogHandler.silent; + _filterOrDefault = const .minPriority(.none); + } - final int level; + /// Whether a record at [priority] would be kept by both the filter and the handler. + /// + /// Records are already gated, so this is only worth calling to guard a message that is + /// expensive to build beyond its interpolation: + /// + /// ```dart + /// if (_log.isLoggable(StreamLogPriority.verbose)) _log.v(() => describe(everyParticipant)); + /// ``` + bool isLoggable(StreamLogPriority priority) => _effectiveFilter.isLoggable(priority, tag); - @override - String toString() => name; + /// Writes a [StreamLogPriority.verbose] record. + void v( + StreamLogMessage message, { + Object? error, + StackTrace? stackTrace, + }) => log( + .verbose, + message, + error: error, + stackTrace: stackTrace, + ); - @override - int compareTo(Priority other) => level.compareTo(other.level); + /// Writes a [StreamLogPriority.debug] record. + void d( + StreamLogMessage message, { + Object? error, + StackTrace? stackTrace, + }) => log( + .debug, + message, + error: error, + stackTrace: stackTrace, + ); - bool operator <(Priority other) => level < other.level; + /// Writes a [StreamLogPriority.info] record. + void i( + StreamLogMessage message, { + Object? error, + StackTrace? stackTrace, + }) => log( + .info, + message, + error: error, + stackTrace: stackTrace, + ); + + /// Writes a [StreamLogPriority.warning] record. + void w( + StreamLogMessage message, { + Object? error, + StackTrace? stackTrace, + }) => log( + .warning, + message, + error: error, + stackTrace: stackTrace, + ); - bool operator <=(Priority other) => level <= other.level; + /// Writes a [StreamLogPriority.error] record. + void e( + StreamLogMessage message, { + Object? error, + StackTrace? stackTrace, + }) => log( + .error, + message, + error: error, + stackTrace: stackTrace, + ); + + /// Writes a record at [priority]. + /// + /// [message] is called only if the record is kept. [error] and [stackTrace] carry the cause + /// when the record describes a failure. + void log( + StreamLogPriority priority, + StreamLogMessage message, { + Object? error, + StackTrace? stackTrace, + }) { + if (!isLoggable(priority)) return; - bool operator >(Priority other) => level > other.level; + final record = StreamLogRecord( + priority: priority, + tag: tag, + message: message(), + error: error, + stackTrace: stackTrace, + ); - bool operator >=(Priority other) => level >= other.level; + return _effectiveHandler.handle(record); + } } diff --git a/packages/stream_core/lib/src/user/token_manager.dart b/packages/stream_core/lib/src/user/token_manager.dart index 6ff19bc8..39bdb8d8 100644 --- a/packages/stream_core/lib/src/user/token_manager.dart +++ b/packages/stream_core/lib/src/user/token_manager.dart @@ -36,7 +36,7 @@ class TokenManager { /// Creates a [TokenManager] for the specified [userId] with the given /// [tokenProvider]. /// - /// An optional [onTokenUpdated] callback is invoked whenever a loaded token is cached. Not for a + /// An optional `onTokenUpdated` callback is invoked whenever a loaded token is cached. Not for a /// caller served from the cache, and not for a load that [expireToken] or [setTokenProvider] /// invalidated while it ran: that token reaches its caller but is never cached. TokenManager({ diff --git a/packages/stream_core/lib/src/user/user.dart b/packages/stream_core/lib/src/user/user.dart index 53eed28d..434a6043 100644 --- a/packages/stream_core/lib/src/user/user.dart +++ b/packages/stream_core/lib/src/user/user.dart @@ -27,8 +27,14 @@ class User extends Equatable { /// Creates a guest user with the provided id and an optional display name. /// - Parameter userId: the id of the user. /// - Parameter name: the display name of the user. Defaults to [userId] when not provided. + /// - Parameter image: the avatar of the user. /// - Returns: a guest `User`. - const User.guest(String userId, {String? name}) : this(id: userId, name: name, type: UserType.guest); + /// + /// The server assigns a guest its own id during `connect`, of the form `guest--`, + /// so [userId] survives only as the tail of it. Read `client.user` afterwards for the id that + /// identifies the session. + const User.guest(String userId, {String? name, String? image}) + : this(id: userId, name: name, image: image, type: UserType.guest); /// Creates an anonymous user. /// - Returns: an anonymous `User`. diff --git a/packages/stream_core/lib/src/ws/client/engine/stream_web_socket_engine.dart b/packages/stream_core/lib/src/ws/client/engine/stream_web_socket_engine.dart index a908bdc8..74bb429f 100644 --- a/packages/stream_core/lib/src/ws/client/engine/stream_web_socket_engine.dart +++ b/packages/stream_core/lib/src/ws/client/engine/stream_web_socket_engine.dart @@ -2,6 +2,7 @@ import 'dart:async'; import 'package:web_socket_channel/web_socket_channel.dart'; +import '../../../logger.dart'; import '../../../utils.dart'; import 'web_socket_engine.dart'; @@ -36,8 +37,11 @@ class StreamWebSocketEngine implements WebSocketEngine { WebSocketProvider? wsProvider, this._listener, required this._messageCodec, - }) : _wsProvider = wsProvider ?? _createWebSocket; + String tag = 'SC:WsEngine', + }) : _logger = StreamLogger(tag), + _wsProvider = wsProvider ?? _createWebSocket; + final StreamLogger _logger; final WebSocketProvider _wsProvider; final WebSocketMessageCodec _messageCodec; @@ -88,6 +92,10 @@ class StreamWebSocketEngine implements WebSocketEngine { if (data == null) return; final result = runSafelySync(() => _messageCodec.decode(data)); + if (result case Failure(:final error, :final stackTrace)) { + return _logger.w(() => 'dropped an undecodable message', error: error, stackTrace: stackTrace); + } + final message = result.getOrNull(); // If decoding failed, we ignore the message. diff --git a/packages/stream_core/lib/src/ws/client/reconnect/connection_recovery_handler.dart b/packages/stream_core/lib/src/ws/client/reconnect/connection_recovery_handler.dart index 714fa916..6dc268ae 100644 --- a/packages/stream_core/lib/src/ws/client/reconnect/connection_recovery_handler.dart +++ b/packages/stream_core/lib/src/ws/client/reconnect/connection_recovery_handler.dart @@ -2,6 +2,7 @@ import 'dart:async'; import 'package:rxdart/utils.dart'; +import '../../../logger.dart'; import '../../../utils.dart'; import '../stream_web_socket_client.dart'; import '../web_socket_connection_state.dart'; @@ -47,7 +48,9 @@ class ConnectionRecoveryHandler extends Disposable { this._keepConnectionAliveInBackground = false, List? policies, RetryStrategy? retryStrategy, + String tag = 'SC:WsRecovery', }) : _client = client, + _logger = StreamLogger(tag), _reconnectStrategy = retryStrategy ?? RetryStrategy(), _policies = [ ...?policies, @@ -78,6 +81,7 @@ class ConnectionRecoveryHandler extends Disposable { } final StreamWebSocketClient _client; + final StreamLogger _logger; final RetryStrategy _reconnectStrategy; final bool _keepConnectionAliveInBackground; final List _policies; @@ -114,6 +118,9 @@ class ConnectionRecoveryHandler extends Disposable { Timer? _reconnectionTimer; void _scheduleReconnection() { final delay = _reconnectStrategy.getDelayAfterTheFailure(); + _logger.d( + () => 'reconnect #${_reconnectStrategy.consecutiveFailuresCount} scheduled in ${delay.inMilliseconds}ms', + ); _reconnectionTimer?.cancel(); _reconnectionTimer = Timer(delay, reconnectIfNeeded); diff --git a/packages/stream_core/lib/src/ws/client/stream_web_socket_client.dart b/packages/stream_core/lib/src/ws/client/stream_web_socket_client.dart index a10b61a4..accc23f8 100644 --- a/packages/stream_core/lib/src/ws/client/stream_web_socket_client.dart +++ b/packages/stream_core/lib/src/ws/client/stream_web_socket_client.dart @@ -1,5 +1,6 @@ import 'dart:async'; +import '../../logger.dart'; import '../../utils.dart'; import '../events/ws_event.dart'; import '../events/ws_request.dart'; @@ -48,6 +49,22 @@ typedef WebSocketOptionsBuilder = WebSocketOptions Function(); /// /// await client.connect(); /// ``` +/// +/// This client reports what it is doing under `SC:WsClient`, and the engine, health monitor and +/// authentication handler it owns under `SC:WsClient:Engine`, `:Health` and `:Auth`. Nothing is +/// written until an app installs a [StreamLogHandler]: +/// +/// ```dart +/// StreamLogger.handler = const StreamLogHandler.filtered(StreamLogFilter.minPriority(StreamLogPriority.debug), StreamLogHandler.console()); +/// ``` +/// +/// Give a second client its own `tag` to tell the two apart. Its collaborators are tagged from +/// it, so one prefix still selects the whole family: +/// +/// ```dart +/// StreamWebSocketClient(tag: 'SC:Ws2', ...); +/// StreamLogger.filter = const StreamLogFilter.prefix({'SC:Ws2': StreamLogPriority.verbose}); +/// ``` class StreamWebSocketClient with Disposable implements WebSocketHealthListener, WebSocketEngineListener { /// Creates a new instance of [StreamWebSocketClient]. StreamWebSocketClient({ @@ -57,17 +74,22 @@ class StreamWebSocketClient with Disposable implements WebSocketHealthListener, this.pingRequestBuilder = _defaultPingRequestBuilder, required WebSocketMessageCodec messageCodec, Iterable>? eventResolvers, - }) { + String tag = 'SC:WsClient', + }) : _logger = StreamLogger(tag) { _events = MutableEventEmitter(resolvers: eventResolvers); _engine = StreamWebSocketEngine( listener: this, wsProvider: wsProvider, messageCodec: messageCodec, + tag: '$tag:Engine', ); + _healthMonitor = WebSocketHealthMonitor(listener: this, tag: '$tag:Health'); + _authenticationHandler = WebSocketAuthenticationHandler( send: send, authenticator: onAuthenticate, + tag: '$tag:Auth', onFailure: (error) => disconnect( source: .authenticationFailed(error: error), ), @@ -80,9 +102,11 @@ class StreamWebSocketClient with Disposable implements WebSocketHealthListener, /// The function used to build ping requests for health checks. final PingRequestBuilder pingRequestBuilder; + final StreamLogger _logger; + late final StreamWebSocketEngine _engine; late final WebSocketAuthenticationHandler _authenticationHandler; - late final _healthMonitor = WebSocketHealthMonitor(listener: this); + late final WebSocketHealthMonitor _healthMonitor; // Bounds an attempt while `Connecting` or `Authenticating`; the health monitor takes over after. Timer? _connectTimeoutTimer; @@ -118,7 +142,10 @@ class StreamWebSocketClient with Disposable implements WebSocketHealthListener, // Return early if the state hasn't changed. if (_connectionStateEmitter.value == connectionState) return; + final previous = _connectionStateEmitter.value; _connectionStateEmitter.value = connectionState; + _logger.d(() => 'state: $previous -> $connectionState'); + _healthMonitor.onConnectionStateChanged(connectionState); _authenticationHandler.onConnectionStateChanged(connectionState); } @@ -157,6 +184,7 @@ class StreamWebSocketClient with Disposable implements WebSocketHealthListener, // Open the connection using the engine, with options built for this attempt. final options = optionsBuilder.call(); + _logger.d(() => 'connect to ${options.url}'); // Bound the attempt, so one that never becomes usable is not waited on forever. _startConnectTimeout(options.connectTimeout); @@ -195,6 +223,8 @@ class StreamWebSocketClient with Disposable implements WebSocketHealthListener, if (connectionState.value case Disconnecting() when !forceDisconnect) return; if (connectionState.value case Disconnected() when !forceDisconnect) return; + _logger.d(() => 'disconnect with $closeCode, source: $source'); + // Update the connection state to 'disconnecting'. _connectionState = WebSocketConnectionState.disconnecting(source: source); @@ -238,6 +268,8 @@ class StreamWebSocketClient with Disposable implements WebSocketHealthListener, @override void onError(Object error, [StackTrace? stackTrace]) { + _logger.e(() => 'socket failed', error: error, stackTrace: stackTrace); + final source = ServerInitiated( error: WebSocketEngineException(error: error), ); @@ -265,6 +297,8 @@ class StreamWebSocketClient with Disposable implements WebSocketHealthListener, } void _handleErrorEvent(WsEvent event, Object error) { + _logger.w(() => 'server sent an error event', error: error); + final source = ServerInitiated( error: WebSocketEngineException(error: error), ); diff --git a/packages/stream_core/lib/src/ws/client/web_socket_authentication_handler.dart b/packages/stream_core/lib/src/ws/client/web_socket_authentication_handler.dart index 7d073d85..6f4270ec 100644 --- a/packages/stream_core/lib/src/ws/client/web_socket_authentication_handler.dart +++ b/packages/stream_core/lib/src/ws/client/web_socket_authentication_handler.dart @@ -1,4 +1,5 @@ import '../../errors.dart' show StreamApiError; +import '../../logger.dart'; import '../../utils.dart'; import '../events/ws_request.dart'; import 'web_socket_connection_state.dart'; @@ -34,7 +35,10 @@ class WebSocketAuthenticationHandler { required this._authenticator, required this._send, required this._onFailure, - }); + String tag = 'SC:WsAuth', + }) : _logger = StreamLogger(tag); + + final StreamLogger _logger; final WebSocketAuthenticator? _authenticator; final WsRequestSender _send; @@ -83,18 +87,24 @@ class WebSocketAuthenticationHandler { final attempt = _attempt; final previousError = _previousError; + _logger.d(() => 'authenticate attempt #$attempt, previousError: $previousError'); // Guarded because nothing awaits this: an error thrown here would go unhandled. final result = await runSafely(() => authenticate(_senderFor(attempt), previousError)); // Stale: its failure would close the connection that replaced it, and never be reconnected. - if (attempt != _attempt) return; + if (attempt != _attempt) { + return _logger.d(() => 'attempt #$attempt is stale, dropping its outcome: $result'); + } // Spent, unless the server refused something newer while the authenticator ran. By identity, // not equality: a newer refusal of the same kind compares equal to this one. if (identical(_previousError, previousError)) _previousError = null; - if (result case Failure(:final error)) return _onFailure(error); + if (result case Failure(:final error, :final stackTrace)) { + _logger.w(() => 'attempt #$attempt could not be authenticated', error: error, stackTrace: stackTrace); + return _onFailure(error); + } } // The sender is held across the authenticator's own awaits, so the attempt is checked on each send. diff --git a/packages/stream_core/lib/src/ws/client/web_socket_health_monitor.dart b/packages/stream_core/lib/src/ws/client/web_socket_health_monitor.dart index f4299c32..a6fb4722 100644 --- a/packages/stream_core/lib/src/ws/client/web_socket_health_monitor.dart +++ b/packages/stream_core/lib/src/ws/client/web_socket_health_monitor.dart @@ -1,5 +1,6 @@ import 'dart:async'; +import '../../logger.dart'; import 'web_socket_connection_state.dart'; /// Interface for receiving WebSocket health monitoring events. @@ -44,7 +45,10 @@ class WebSocketHealthMonitor { required this._listener, this.pingInterval = const Duration(seconds: 25), this.timeoutThreshold = const Duration(seconds: 3), - }); + String tag = 'SC:WsHealth', + }) : _logger = StreamLogger(tag); + + final StreamLogger _logger; /// The interval between ping requests for health checking. final Duration pingInterval; @@ -72,7 +76,10 @@ class WebSocketHealthMonitor { /// /// Cancels the current pong timeout timer, indicating the connection is healthy. /// Called automatically when pong events are received from the WebSocket. - void onPongReceived() => _pongTimer?.cancel(); + void onPongReceived() { + _logger.v(() => 'pong'); + return _pongTimer?.cancel(); + } /// Handles connection state changes. /// @@ -91,10 +98,16 @@ class WebSocketHealthMonitor { void _sendPing(Timer pingTimer) { if (!pingTimer.isActive) return; + _logger.v(() => 'ping'); _listener.onPingRequested(); _pongTimer?.cancel(); - _pongTimer = Timer(timeoutThreshold, _listener.onUnhealthy); + _pongTimer = Timer(timeoutThreshold, _onPongTimeout); + } + + void _onPongTimeout() { + _logger.w(() => 'no pong within $timeoutThreshold, connection is unhealthy'); + return _listener.onUnhealthy(); } /// Stops health monitoring and cancels all timers. diff --git a/packages/stream_core/test/api/interceptors/auth_interceptor_test.dart b/packages/stream_core/test/api/interceptors/auth_interceptor_test.dart index 72725aa1..f2758bd7 100644 --- a/packages/stream_core/test/api/interceptors/auth_interceptor_test.dart +++ b/packages/stream_core/test/api/interceptors/auth_interceptor_test.dart @@ -4,6 +4,7 @@ import 'dart:convert'; import 'package:stream_core/stream_core.dart'; import 'package:test/test.dart'; +import '../../helpers/logger.dart'; import '../../helpers/user_token.dart'; /// The body the API returns when the token it was given has run out. @@ -545,5 +546,55 @@ void main() { expect(loads(), 1); }); }); + + group('what the logger sees', () { + test('reports the retry and the token behind it', () async { + final handler = RecordingLogHandler(); + final (:dio, api: _, tokens: _, loads: _) = _subject(api: _FakeApi(refusals: 1)); + + await withStreamLogger(handler: handler, () => dio.get('/test')); + + expect(handler.tags, everyElement('SC:HttpAuth')); + expect(handler.messages.join(), contains('retrying')); + }); + + test('reports a refusal it will not retry, and why', () async { + final handler = RecordingLogHandler(); + final (:dio, api: _, tokens: _, loads: _) = _subject( + tokenProvider: TokenProvider.static(generateTestUserToken('user-1')), + api: _FakeApi(refusals: 1), + ); + + await withStreamLogger( + handler: handler, + () => expectLater(dio.get('/test'), throwsA(_expiredTokenError)), + ); + + // A refused request left refused is what someone debugging a stuck login is looking at, so + // the reason it was not retried has to be somewhere. + expect(handler.messages.join(), contains('static')); + }); + + test('reports a replacement that was refused too', () async { + final handler = RecordingLogHandler(); + final (:dio, api: _, tokens: _, loads: _) = _subject(api: _FakeApi(refusals: 2)); + + await withStreamLogger( + handler: handler, + () => expectLater(dio.get('/test'), throwsA(_expiredTokenError)), + ); + + expect(handler.messages.join(), contains('refused too')); + }); + + test('says nothing when no handler is installed', () async { + final (:dio, api: _, tokens: _, loads: _) = _subject(api: _FakeApi(refusals: 1)); + + final printed = capturePrints(() => dio.get('/test')); + await pumpEventQueue(); + + expect(printed, isEmpty); + }); + }); }); } diff --git a/packages/stream_core/test/api/interceptors/logging_interceptor_test.dart b/packages/stream_core/test/api/interceptors/logging_interceptor_test.dart new file mode 100644 index 00000000..7eed8dfb --- /dev/null +++ b/packages/stream_core/test/api/interceptors/logging_interceptor_test.dart @@ -0,0 +1,137 @@ +import 'dart:convert'; + +import 'package:stream_core/stream_core.dart'; +import 'package:test/test.dart'; + +import '../../helpers/logger.dart'; +import '../../helpers/user_token.dart'; + +class _FakeApi implements HttpClientAdapter { + @override + Future fetch(RequestOptions o, Stream? s, Future? c) async { + return ResponseBody.fromString( + jsonEncode(const {'ok': true}), + 200, + headers: { + Headers.contentTypeHeader: [Headers.jsonContentType], + }, + ); + } + + @override + void close({bool force = false}) {} +} + +/// Builds the interceptor stack a Stream SDK puts on its client, in the same order. +Dio _subject({LogPrint? logPrint, bool requestHeader = true}) { + final tokens = TokenManager( + userId: 'user-1', + tokenProvider: TokenProvider.static(generateTestUserToken('user-1')), + ); + + final dio = Dio(BaseOptions(baseUrl: 'https://example.com'))..httpClientAdapter = _FakeApi(); + return dio + ..interceptors.addAll([ + AuthInterceptor(dio, tokens), + LoggingInterceptor(requestHeader: requestHeader, logPrint: logPrint), + ]); +} + +void main() { + group('LoggingInterceptor', () { + test('writes nothing until an app installs a handler', () async { + final dio = _subject(); + + final printed = capturePrints(() => dio.get('/test')); + await pumpEventQueue(); + + // It used to print every request, headers and all, in every build. + expect(printed, isEmpty); + }); + + test('leaves the credentials out of a log nobody asked for', () async { + final dio = _subject(); + final token = generateTestUserToken('user-1').rawValue; + + final printed = capturePrints(() => dio.get('/test')); + await pumpEventQueue(); + + // `requestHeader` puts `Authorization` in the record, and the request is signed before this + // interceptor sees it, so a log written unasked carries the user's token. + expect(printed.join(), isNot(contains(token))); + }); + + test('keeps the credentials out of a log that was asked for, left at its defaults', () async { + final handler = RecordingLogHandler(); + final dio = _subject(requestHeader: false); + final token = generateTestUserToken('user-1').rawValue; + + await withStreamLogger( + handler: handler, + filter: const StreamLogFilter.always(), + () async { + await dio.get('/test'); + await pumpEventQueue(); + }, + ); + + // What a product gets by constructing the interceptor without arguments: turning `requestHeader` + // on is what puts the signed `Authorization` in a record, and nothing else does. + expect(handler.records, isNotEmpty, reason: 'the request was reported'); + expect(handler.messages.join(), isNot(contains(token))); + }); + + test('reports the request once a handler wants it', () async { + final handler = RecordingLogHandler(); + final dio = _subject(); + + await withStreamLogger( + handler: handler, + filter: const StreamLogFilter.minPriority(StreamLogPriority.debug), + () async { + await dio.get('/test'); + await pumpEventQueue(); + }, + ); + + expect(handler.tags, everyElement('SC:Http')); + expect(handler.messages.join(), contains('https://example.com/test')); + }); + + test('writes through the logger rather than printing, when given no printer', () async { + final handler = RecordingLogHandler(); + final dio = _subject(); + + final printed = await withStreamLogger( + handler: handler, + filter: const StreamLogFilter.always(), + () async { + final lines = capturePrints(() => dio.get('/test').ignore()); + await pumpEventQueue(); + return lines; + }, + ); + + expect(handler.records, isNotEmpty, reason: 'the records reached the handler'); + expect(printed, isEmpty, reason: 'and none of them went to the console'); + }); + + test('hands the lines to a printer a caller supplied, leaving the logger out of it', () async { + final handler = RecordingLogHandler(); + var lines = 0; + final dio = _subject(logPrint: (_, _) => lines++); + + await withStreamLogger( + handler: handler, + filter: const StreamLogFilter.always(), + () async { + await dio.get('/test'); + await pumpEventQueue(); + }, + ); + + expect(lines, greaterThan(0)); + expect(handler.records, isEmpty, reason: 'a supplied printer replaces the logger'); + }); + }); +} diff --git a/packages/stream_core/test/helpers/logger.dart b/packages/stream_core/test/helpers/logger.dart new file mode 100644 index 00000000..896f4c01 --- /dev/null +++ b/packages/stream_core/test/helpers/logger.dart @@ -0,0 +1,60 @@ +import 'dart:async'; + +import 'package:stream_core/stream_core.dart'; + +/// A [StreamLogHandler] that keeps every record it is given, for a test to assert on. +final class RecordingLogHandler extends StreamLogHandler { + RecordingLogHandler(); + + final records = []; + + Iterable get messages => records.map((it) => it.message); + + Iterable get tags => records.map((it) => it.tag); + + @override + void handle(StreamLogRecord record) => records.add(record); +} + +/// Runs [body] with [handler] and [filter] installed as the ambient ones, restoring both after. +/// +/// What an app installs is process-wide, so a test that sets it without clearing up changes what +/// every later test sees. The defaults are put back rather than whatever was there before, which +/// a write-only setter cannot read. +/// +/// An asynchronous [body] is awaited before either is put back, so a handler stays installed for +/// the work it was meant to capture rather than only up to the first `await`. +/// +/// Consider [StreamLogger.detached] for a component that can be handed its own logger, which +/// needs no clearing up at all. +T withStreamLogger( + T Function() body, { + StreamLogHandler? handler, + StreamLogFilter? filter, +}) { + if (handler != null) StreamLogger.handler = handler; + // A test installing a handler wants to see what reached it, so nothing is held back unless the + // test says so. + StreamLogger.filter = filter ?? const StreamLogFilter.always(); + + final T result; + try { + result = body(); + } catch (_) { + StreamLogger.reset(); + rethrow; + } + + if (result is Future) return result.whenComplete(StreamLogger.reset) as T; + + StreamLogger.reset(); + return result; +} + +/// Runs [body] and returns everything it printed. +List capturePrints(void Function() body) { + final lines = []; + final spec = ZoneSpecification(print: (_, _, _, line) => lines.add(line)); + runZoned(body, zoneSpecification: spec); + return lines; +} diff --git a/packages/stream_core/test/helpers/ws_client_tester.dart b/packages/stream_core/test/helpers/ws_client_tester.dart index 57709269..19fb2641 100644 --- a/packages/stream_core/test/helpers/ws_client_tester.dart +++ b/packages/stream_core/test/helpers/ws_client_tester.dart @@ -209,6 +209,7 @@ WsClientTester buildTester({ bool handshakeHangs = false, bool holdClose = false, Object? closeError, + String tag = 'SC:WsClient', }) { final server = FakeServer(user: user); @@ -244,6 +245,7 @@ WsClientTester buildTester({ false => null, }, messageCodec: const JsonCodec(), + tag: tag, ); final network = TestNetworkStateProvider(); diff --git a/packages/stream_core/test/logger/stream_log_config_test.dart b/packages/stream_core/test/logger/stream_log_config_test.dart new file mode 100644 index 00000000..d79bc17b --- /dev/null +++ b/packages/stream_core/test/logger/stream_log_config_test.dart @@ -0,0 +1,133 @@ +import 'package:stream_core/stream_core.dart'; +import 'package:test/test.dart'; + +import '../helpers/logger.dart'; + +const _logger = StreamLogger('SF:Component'); + +void main() { + group('StreamLogger.configure', () { + tearDown(StreamLogger.reset); + + test('leaves the logger alone when there is no config', () { + final installed = RecordingLogHandler(); + StreamLogger.handler = installed; + StreamLogger.priority = StreamLogPriority.verbose; + + StreamLogger.configure(null); + _logger.d(() => 'another SDK, still heard'); + + // A client the app gave no logging must not decide it for the SDK beside it. + expect(installed.messages, ['another SDK, still heard']); + }); + + test('writes to the console, given a priority and nowhere to put it', () { + final printed = capturePrints(() { + StreamLogger.configure(const StreamLogConfig(priority: StreamLogPriority.debug)); + _logger.d(() => 'to the console'); + }); + + expect(printed.single, contains('to the console')); + }); + + test('hears warnings, given a handler and no priority', () { + final mine = RecordingLogHandler(); + + StreamLogger.configure(StreamLogConfig(handler: mine)); + _logger + ..d(() => 'commentary') + ..w(() => 'worth acting on'); + + expect(mine.messages, ['worth acting on']); + }); + + test('silences everything when asked for none', () { + final mine = RecordingLogHandler(); + + StreamLogger.configure( + StreamLogConfig(priority: StreamLogPriority.none, handler: mine), + ); + _logger.e(() => 'not even an error'); + + expect(mine.records, isEmpty); + }); + + test('holds one subsystem apart from the rest, given a filter', () { + final mine = RecordingLogHandler(); + + StreamLogger.configure( + StreamLogConfig( + handler: mine, + filter: const StreamLogFilter.prefix({'SF:Ws': StreamLogPriority.verbose}), + ), + ); + const StreamLogger('SF:Ws').v(() => 'the subsystem I turned up'); + _logger.d(() => 'the commentary I did not'); + + // The filter has to survive the config that carries it: `priority` sets the same field, so a + // config applying both would flatten the rule it was given. + expect(mine.messages, ['the subsystem I turned up']); + }); + test('replaces a filter installed before it, even naming only a priority', () { + final mine = RecordingLogHandler(); + StreamLogger.filter = const StreamLogFilter.prefix({'SF:Ws': StreamLogPriority.verbose}); + + StreamLogger.configure(StreamLogConfig(priority: StreamLogPriority.debug, handler: mine)); + const StreamLogger('SF:Ws').v(() => 'below what the config asked for'); + + // A config is the whole story: its priority and filter are one field underneath, so there is + // no reading of it that keeps an earlier rule and the new threshold both. + expect(mine.records, isEmpty); + }); + }); + + group('two Stream SDKs in one app', () { + const feeds = StreamLogger('SF:Ws'); + const video = StreamLogger('SV:Call'); + + tearDown(StreamLogger.reset); + + test('report together once either of them is configured', () { + final mine = RecordingLogHandler(); + + StreamLogger.configure(StreamLogConfig(priority: StreamLogPriority.debug, handler: mine)); + feeds.d(() => 'feeds'); + video.d(() => 'video'); + + // One logger serves the process, so configuring a client turns logging on for the SDK beside + // it too. The tags are what tell them apart afterwards. + expect(mine.messages, ['feeds', 'video']); + }); + + test('settle on whichever was configured last, rather than merging', () { + final first = RecordingLogHandler(); + final second = RecordingLogHandler(); + + StreamLogger.configure(StreamLogConfig(handler: first)); + StreamLogger.configure(StreamLogConfig(handler: second)); + feeds.w(() => 'a warning'); + + expect(first.records, isEmpty); + expect(second.messages, ['a warning']); + }); + + test('can be held to one SDK by the prefix its tags carry', () { + final mine = RecordingLogHandler(); + + StreamLogger.configure( + StreamLogConfig( + handler: mine, + filter: const StreamLogFilter.prefix( + {'SF:': StreamLogPriority.debug}, + otherwise: StreamLogPriority.none, + ), + ), + ); + feeds.d(() => 'feeds'); + video.e(() => 'video, not asked for'); + + // What an app reaches for when it wants one SDK's records and not the other's. + expect(mine.messages, ['feeds']); + }); + }); +} diff --git a/packages/stream_core/test/logger/stream_log_filter_test.dart b/packages/stream_core/test/logger/stream_log_filter_test.dart new file mode 100644 index 00000000..0a3d02b6 --- /dev/null +++ b/packages/stream_core/test/logger/stream_log_filter_test.dart @@ -0,0 +1,85 @@ +import 'package:stream_core/stream_core.dart'; +import 'package:test/test.dart'; + +import '../helpers/logger.dart'; + +void main() { + group('StreamLogFilter.minPriority', () { + test('admits records at the level or above, whatever the tag', () { + const filter = StreamLogFilter.minPriority(StreamLogPriority.warning); + + expect(filter.isLoggable(StreamLogPriority.debug, 'SC:Anything'), isFalse); + expect(filter.isLoggable(StreamLogPriority.warning, 'SC:Anything'), isTrue); + expect(filter.isLoggable(StreamLogPriority.error, 'SF:Something'), isTrue); + }); + }); + + group('StreamLogFilter.prefix', () { + test('holds a matching tag to its own threshold', () { + const filter = StreamLogFilter.prefix({'SC:Ws': StreamLogPriority.verbose}); + + expect(filter.isLoggable(StreamLogPriority.verbose, 'SC:WsClient'), isTrue); + expect(filter.isLoggable(StreamLogPriority.verbose, 'SC:Http'), isFalse); + }); + + test('holds everything else to `otherwise`', () { + const filter = StreamLogFilter.prefix( + {'SC:Ws': StreamLogPriority.verbose}, + otherwise: StreamLogPriority.error, + ); + + expect(filter.isLoggable(StreamLogPriority.warning, 'SC:Http'), isFalse); + expect(filter.isLoggable(StreamLogPriority.error, 'SC:Http'), isTrue); + }); + + test('lets the longest prefix win, so a broad rule can be narrowed', () { + const filter = StreamLogFilter.prefix({ + 'SC:': StreamLogPriority.verbose, + 'SC:WsHealth': StreamLogPriority.warning, + }); + + expect(filter.isLoggable(StreamLogPriority.verbose, 'SC:WsClient'), isTrue); + expect(filter.isLoggable(StreamLogPriority.verbose, 'SC:WsHealth'), isFalse); + expect(filter.isLoggable(StreamLogPriority.warning, 'SC:WsHealth'), isTrue); + }); + + test('is independent of the order the rules were written in', () { + const broadFirst = StreamLogFilter.prefix({ + 'SC:': StreamLogPriority.verbose, + 'SC:WsHealth': StreamLogPriority.warning, + }); + const narrowFirst = StreamLogFilter.prefix({ + 'SC:WsHealth': StreamLogPriority.warning, + 'SC:': StreamLogPriority.verbose, + }); + + expect( + broadFirst.isLoggable(StreamLogPriority.verbose, 'SC:WsHealth'), + narrowFirst.isLoggable(StreamLogPriority.verbose, 'SC:WsHealth'), + ); + }); + + test('gates a logger before its message is built', () { + var built = 0; + final handler = RecordingLogHandler(); + const logger = StreamLogger('SC:WsHealth'); + + withStreamLogger( + handler: handler, + filter: const StreamLogFilter.prefix({'SC:WsHealth': StreamLogPriority.warning}), + () => logger.v(() => 'ping ${built++}'), + ); + + expect(built, 0); + expect(handler.records, isEmpty); + }); + }); + + group('StreamLogFilter.always', () { + test('leaves the decision to the handler', () { + const filter = StreamLogFilter.always(); + + expect(filter.isLoggable(StreamLogPriority.verbose, 'SC:Anything'), isTrue); + }); + }); +} diff --git a/packages/stream_core/test/logger/stream_log_handler_test.dart b/packages/stream_core/test/logger/stream_log_handler_test.dart new file mode 100644 index 00000000..01aa531b --- /dev/null +++ b/packages/stream_core/test/logger/stream_log_handler_test.dart @@ -0,0 +1,176 @@ +import 'package:stream_core/stream_core.dart'; +import 'package:test/test.dart'; + +import '../helpers/logger.dart'; + +const _logger = StreamLogger('SC:Component'); + +void main() { + group('StreamLogHandler.console', () { + test('reaches the console, rather than only a service listener', () { + final printed = withStreamLogger( + handler: const StreamLogHandler.console(), + () => capturePrints(() => _logger.e(() => 'a visible line')), + ); + + expect(printed.single, allOf(contains('a visible line'), contains('SC:Component'))); + }); + + test('stays quiet until a level is named beside it', () { + // Deliberately not `withStreamLogger`, which opens the level up: this is about what an app + // gets from installing a handler and nothing else. + StreamLogger.handler = const StreamLogHandler.console(); + addTearDown(StreamLogger.reset); + + // A destination with no level is as silent as a level with no destination: records need both. + expect(capturePrints(() => _logger.e(() => 'error')), isEmpty); + + StreamLogger.priority = StreamLogPriority.warning; + final printed = capturePrints(() { + _logger + ..v(() => 'verbose') + ..d(() => 'debug') + ..i(() => 'info') + ..w(() => 'warning') + ..e(() => 'error'); + }); + + expect(printed, hasLength(2)); + expect(printed.join(), allOf(contains('warning'), contains('error'), isNot(contains('info')))); + }); + + test('writes whatever the level admits, once it has been opened up', () { + // The setup every migration guide shows, which silently dropped debug when the handler + // carried a competing threshold of its own. + StreamLogger.handler = const StreamLogHandler.console(); + StreamLogger.priority = StreamLogPriority.debug; + addTearDown(() { + StreamLogger.handler = StreamLogHandler.silent; + StreamLogger.priority = StreamLogPriority.warning; + }); + + final printed = capturePrints(() => _logger.d(() => 'a debug line')); + + expect(printed.single, contains('a debug line')); + }); + + test('can be held quieter than the level, but never louder', () { + final printed = withStreamLogger( + handler: const StreamLogHandler.filtered( + StreamLogFilter.minPriority(StreamLogPriority.error), + StreamLogHandler.console(), + ), + filter: const StreamLogFilter.minPriority(StreamLogPriority.debug), + () => capturePrints(() { + _logger + ..d(() => 'debug') + ..e(() => 'error'); + }), + ); + + expect(printed.single, contains('error')); + }); + + test('prints the cause of a failure after the message', () { + final printed = withStreamLogger( + handler: const StreamLogHandler.console(), + () => capturePrints( + () => _logger.e(() => 'failed', error: StateError('boom'), stackTrace: StackTrace.current), + ), + ); + + expect(printed, hasLength(3)); + expect(printed[0], contains('failed')); + expect(printed[1], contains('boom')); + }); + }); + + group('StreamLogHandler.composite', () { + test('gives every handler the same record', () { + final console = RecordingLogHandler(); + final crashReporter = RecordingLogHandler(); + + withStreamLogger( + handler: StreamLogHandler.composite([console, crashReporter]), + () => _logger.w(() => 'seen by both'), + ); + + expect(console.messages, ['seen by both']); + expect(crashReporter.messages, ['seen by both']); + }); + + test('lets each handler keep only what it wants', () { + final everything = RecordingLogHandler(); + + final printed = withStreamLogger( + handler: StreamLogHandler.composite([ + everything, + const StreamLogHandler.filtered( + StreamLogFilter.minPriority(StreamLogPriority.error), + StreamLogHandler.console(), + ), + ]), + () => capturePrints(() { + _logger + ..d(() => 'debug') + ..e(() => 'error'); + }), + ); + + expect(everything.messages, ['debug', 'error']); + expect(printed, hasLength(1)); + }); + + test('builds a record any one of them wants', () { + withStreamLogger( + handler: StreamLogHandler.composite([ + const StreamLogHandler.filtered( + StreamLogFilter.minPriority(StreamLogPriority.none), + StreamLogHandler.console(), + ), + RecordingLogHandler(), + ]), + () => expect(_logger.isLoggable(StreamLogPriority.verbose), isTrue), + ); + }); + + test('does nothing when it has no handlers', () { + withStreamLogger( + handler: const StreamLogHandler.composite([]), + () { + expect(() => _logger.e(() => 'nowhere to go'), returnsNormally); + expect(capturePrints(() => _logger.e(() => 'nowhere to go')), isEmpty); + }, + ); + }); + }); + + group('StreamLogHandler.from', () { + test('hands each record to the callback', () { + final seen = []; + + withStreamLogger( + handler: StreamLogHandler.from((it) => seen.add('${it.priority} ${it.tag} ${it.message}')), + () => _logger + ..v(() => 'verbose') + ..e(() => 'error'), + ); + + expect(seen, ['verbose SC:Component verbose', 'error SC:Component error']); + }); + }); + + group('StreamLogHandler.silent', () { + test('discards every record it is given', () { + withStreamLogger( + handler: StreamLogHandler.silent, + () { + expect(capturePrints(() => _logger.e(() => 'discarded')), isEmpty); + // The filter decides what is built; where it goes afterwards is this handler's business, + // so it no longer has a say in what `isLoggable` answers. + expect(_logger.isLoggable(StreamLogPriority.error), isTrue); + }, + ); + }); + }); +} diff --git a/packages/stream_core/test/logger/stream_log_priority_test.dart b/packages/stream_core/test/logger/stream_log_priority_test.dart new file mode 100644 index 00000000..c1195bde --- /dev/null +++ b/packages/stream_core/test/logger/stream_log_priority_test.dart @@ -0,0 +1,60 @@ +import 'package:stream_core/stream_core.dart'; +import 'package:test/test.dart'; + +void main() { + group('StreamLogPriority', () { + test('runs from least to most severe', () { + // Every threshold in the logger is a comparison against one of these, so the order they sit + // in is what decides which records a filter admits. + expect(StreamLogPriority.values, [ + StreamLogPriority.verbose, + StreamLogPriority.debug, + StreamLogPriority.info, + StreamLogPriority.warning, + StreamLogPriority.error, + StreamLogPriority.none, + ]); + }); + + test('compares consistently in every direction', () { + for (var i = 1; i < StreamLogPriority.values.length; i++) { + final lower = StreamLogPriority.values[i - 1]; + final higher = StreamLogPriority.values[i]; + + expect(lower < higher, isTrue, reason: '$lower < $higher'); + expect(lower <= higher, isTrue, reason: '$lower <= $higher'); + expect(higher > lower, isTrue, reason: '$higher > $lower'); + expect(higher >= lower, isTrue, reason: '$higher >= $lower'); + expect(lower.compareTo(higher), isNegative, reason: '$lower before $higher'); + } + }); + + test('is neither above nor below itself', () { + expect(StreamLogPriority.info < StreamLogPriority.info, isFalse); + expect(StreamLogPriority.info > StreamLogPriority.info, isFalse); + expect(StreamLogPriority.info <= StreamLogPriority.info, isTrue); + expect(StreamLogPriority.info >= StreamLogPriority.info, isTrue); + expect(StreamLogPriority.info.compareTo(StreamLogPriority.info), isZero); + }); + + test('sorts by severity', () { + final shuffled = [ + StreamLogPriority.error, + StreamLogPriority.verbose, + StreamLogPriority.none, + StreamLogPriority.warning, + StreamLogPriority.debug, + StreamLogPriority.info, + ]; + expect(shuffled, isNot(orderedEquals(StreamLogPriority.values))); + + shuffled.sort(); + + expect(shuffled, orderedEquals(StreamLogPriority.values)); + }); + + test('admits nothing as a threshold, being the most severe there is', () { + expect(StreamLogPriority.values.every((it) => it <= StreamLogPriority.none), isTrue); + }); + }); +} diff --git a/packages/stream_core/test/logger/stream_logger_defaults_test.dart b/packages/stream_core/test/logger/stream_logger_defaults_test.dart new file mode 100644 index 00000000..4184ec46 --- /dev/null +++ b/packages/stream_core/test/logger/stream_logger_defaults_test.dart @@ -0,0 +1,31 @@ +import 'dart:async'; + +import 'package:stream_core/stream_core.dart'; +import 'package:test/test.dart'; + +/// What a process that has never touched the logger starts with. +/// +/// Deliberately the only test in this file, and it neither installs anything nor calls +/// `StreamLogger.reset`: every other suite restores the defaults rather than observing them, so a +/// change to the field initialisers would otherwise go unnoticed. `dart test` gives each file its +/// own isolate, which is what keeps these statics pristine. +void main() { + test('an untouched logger admits nothing, at any priority', () { + const logger = StreamLogger('SC:Component'); + + for (final priority in StreamLogPriority.values) { + expect(logger.isLoggable(priority), isFalse, reason: '$priority'); + } + + expect( + capturePrints(() => logger.e(() => 'nobody asked for this', error: StateError('boom'))), + isEmpty, + ); + }); +} + +List capturePrints(void Function() body) { + final lines = []; + runZoned(body, zoneSpecification: ZoneSpecification(print: (_, _, _, line) => lines.add(line))); + return lines; +} diff --git a/packages/stream_core/test/logger/stream_logger_test.dart b/packages/stream_core/test/logger/stream_logger_test.dart new file mode 100644 index 00000000..8f70f1f1 --- /dev/null +++ b/packages/stream_core/test/logger/stream_logger_test.dart @@ -0,0 +1,372 @@ +import 'package:clock/clock.dart'; +import 'package:stream_core/stream_core.dart'; +import 'package:test/test.dart'; + +import '../helpers/logger.dart'; + +const _logger = StreamLogger('SC:Component'); + +void main() { + group('StreamLogger', () { + test('writes every record under its own tag', () { + final handler = RecordingLogHandler(); + + withStreamLogger(handler: handler, () { + _logger + ..v(() => 'v') + ..d(() => 'd') + ..i(() => 'i') + ..w(() => 'w') + ..e(() => 'e'); + }); + + expect(handler.tags, everyElement('SC:Component')); + expect(handler.records.map((it) => it.priority), [ + StreamLogPriority.verbose, + StreamLogPriority.debug, + StreamLogPriority.info, + StreamLogPriority.warning, + StreamLogPriority.error, + ]); + }); + + test('is silent until an app installs a handler', () { + var built = 0; + + final printed = capturePrints(() => _logger.e(() => 'nobody is listening ${built++}')); + + expect(printed, isEmpty); + expect(built, 0, reason: 'a message no handler wants is never built'); + }); + + test('is const constructible, so a component can hold one as a static field', () { + // A logger needing construction would cost an allocation per component, and could not be + // held by a top-level function. + expect(_logger.tag, 'SC:Component'); + }); + + test('resolves the handler when it writes, not when it was created', () { + // `_logger` is a top-level const, created long before this handler existed. + final handler = RecordingLogHandler(); + + withStreamLogger(handler: handler, () => _logger.e(() => 'after configuration')); + + expect(handler.messages, ['after configuration']); + }); + + test('stops writing to a handler that has been replaced', () { + final first = RecordingLogHandler(); + + withStreamLogger(handler: first, () {}); + _logger.e(() => 'after the handler went away'); + + expect(first.records, isEmpty); + }); + + test('carries the cause of a failure, whichever level reports it', () { + final handler = RecordingLogHandler(); + final error = StateError('boom'); + final stackTrace = StackTrace.current; + + withStreamLogger(handler: handler, () { + _logger + ..v(() => 'v', error: error, stackTrace: stackTrace) + ..d(() => 'd', error: error, stackTrace: stackTrace) + ..i(() => 'i', error: error, stackTrace: stackTrace) + ..w(() => 'w', error: error, stackTrace: stackTrace) + ..e(() => 'e', error: error, stackTrace: stackTrace) + ..log(StreamLogPriority.error, () => 'log', error: error, stackTrace: stackTrace); + }); + + // Each of these forwards to `log` separately, so one that dropped an argument would go + // unnoticed if only the level it was most obviously needed for were checked. + expect(handler.records, hasLength(6)); + expect(handler.records.map((it) => it.error), everyElement(error)); + expect(handler.records.map((it) => it.stackTrace), everyElement(stackTrace)); + }); + + test('leaves the cause empty when a record describes no failure', () { + final handler = RecordingLogHandler(); + + withStreamLogger(handler: handler, () { + _logger + ..v(() => 'v') + ..d(() => 'd') + ..i(() => 'i') + ..w(() => 'w') + ..e(() => 'e') + ..log(StreamLogPriority.error, () => 'log'); + }); + + // A handler forwarding to a crash reporter decides what to report on whether there is a + // cause, so a record inventing one would file an incident for a routine line. + expect(handler.records, hasLength(6)); + expect(handler.records.map((it) => it.error), everyElement(isNull)); + expect(handler.records.map((it) => it.stackTrace), everyElement(isNull)); + }); + + test('never builds a message while nothing is installed to receive one', () { + var built = 0; + + // Deliberately not `withStreamLogger`, which installs a handler: this is what an app that + // has not asked for logging pays. + capturePrints(() => _logger.e(() => 'expensive ${built++}')); + + expect(built, isZero); + }); + + test('builds a message a narrower destination goes on to discard', () { + var built = 0; + + final printed = withStreamLogger( + handler: const StreamLogHandler.filtered( + StreamLogFilter.minPriority(StreamLogPriority.error), + StreamLogHandler.console(), + ), + () => capturePrints(() => _logger.v(() => 'expensive ${built++}')), + ); + + // The filter is the only gate, so a destination narrower than it declines on delivery rather + // than before the message was built. + expect(built, 1); + expect(printed, isEmpty); + }); + + test('isLoggable answers for the filter, whatever the destination goes on to keep', () { + withStreamLogger( + handler: const StreamLogHandler.filtered( + StreamLogFilter.minPriority(StreamLogPriority.warning), + StreamLogHandler.console(), + ), + filter: const StreamLogFilter.minPriority(StreamLogPriority.debug), + () { + expect(_logger.isLoggable(StreamLogPriority.verbose), isFalse, reason: 'the filter rejects it'); + expect(_logger.isLoggable(StreamLogPriority.debug), isTrue, reason: 'the filter admits it'); + expect(_logger.isLoggable(StreamLogPriority.warning), isTrue); + }, + ); + }); + }); + + group('StreamLogger.reset', () { + test('puts back both the handler and the priority', () { + final installed = RecordingLogHandler(); + StreamLogger.handler = installed; + StreamLogger.priority = StreamLogPriority.verbose; + + StreamLogger.reset(); + + // A consumer restoring by hand would have to name defaults a write-only setter gives no way + // to read, so both have to come back together. + final printed = capturePrints(() { + _logger + ..d(() => 'below the default threshold') + ..e(() => 'nowhere to go'); + }); + + expect(installed.records, isEmpty, reason: 'the handler was put back'); + expect(printed, isEmpty, reason: 'nothing is installed to print with'); + expect(_logger.isLoggable(StreamLogPriority.debug), isFalse, reason: 'the priority was put back'); + }); + }); + + group('StreamLogger.detached', () { + test('writes to its own handler, ignoring what the app installed', () { + final mine = RecordingLogHandler(); + final installed = RecordingLogHandler(); + final logger = StreamLogger.detached('SC:Detached', handler: mine); + + withStreamLogger(handler: installed, () => logger.e(() => 'to mine only')); + + expect(mine.messages, ['to mine only']); + expect(installed.records, isEmpty); + }); + + test('writes even when the app installed nothing', () { + final mine = RecordingLogHandler(); + final logger = StreamLogger.detached('SC:Detached', handler: mine); + + logger.e(() => 'nothing ambient is needed'); + + expect(mine.messages, ['nothing ambient is needed']); + }); + + test('is held to its own threshold, not the installed one', () { + final mine = RecordingLogHandler(); + final logger = StreamLogger.detached( + 'SC:Detached', + handler: mine, + filter: const StreamLogFilter.minPriority(StreamLogPriority.error), + ); + + withStreamLogger(filter: const StreamLogFilter.always(), () { + logger + ..w(() => 'below its own threshold, though the installed one admits it') + ..e(() => 'at it'); + }); + + expect(mine.messages, ['at it']); + }); + + test('leaves what the app installed alone', () { + final installed = RecordingLogHandler(); + final logger = StreamLogger.detached('SC:Detached', handler: RecordingLogHandler()); + + withStreamLogger(handler: installed, () { + logger.e(() => 'mine'); + const StreamLogger('SC:Component').e(() => 'theirs'); + }); + + expect(installed.messages, ['theirs']); + }); + + test('starts at the threshold an attached logger starts at', () { + final mine = RecordingLogHandler(); + final logger = StreamLogger.detached('SC:Detached', handler: mine); + + logger + ..d(() => 'below the default threshold') + ..w(() => 'at it'); + + // Detaching changes where a logger's records go. Left to admit everything, it would also + // quietly change how many there are. + expect(mine.messages, ['at it']); + }); + + test('admits everything when asked to', () { + final mine = RecordingLogHandler(); + final logger = StreamLogger.detached( + 'SC:Detached', + handler: mine, + filter: const StreamLogFilter.always(), + ); + + logger.v(() => 'the quietest record there is'); + + expect(mine.messages, ['the quietest record there is']); + }); + + test('is unmoved by the installed handler and priority changing after it was built', () { + final mine = RecordingLogHandler(); + final logger = StreamLogger.detached('SC:Detached', handler: mine); + + addTearDown(() { + StreamLogger.handler = StreamLogHandler.silent; + StreamLogger.priority = StreamLogPriority.warning; + }); + + // An attached logger resolves both of these every time it writes, so a detached one reading + // either would drift as an app reconfigured itself. + for (final installed in [RecordingLogHandler(), RecordingLogHandler()]) { + StreamLogger.handler = installed; + StreamLogger.priority = StreamLogPriority.verbose; + + logger + ..d(() => 'still below its own threshold') + ..e(() => 'still its own handler'); + + expect(installed.records, isEmpty, reason: 'a detached logger writes nowhere else'); + } + + expect(mine.messages, ['still its own handler', 'still its own handler']); + }); + + test('is const constructible', () { + const logger = StreamLogger.detached('SC:Detached', handler: StreamLogHandler.console()); + + expect(logger.tag, 'SC:Detached'); + }); + }); + + group('StreamLogRecord', () { + test('reads its time from the clock, so a test can pin it', () { + final handler = RecordingLogHandler(); + final instant = DateTime.utc(2026, 8, 24, 12); + + withStreamLogger( + handler: handler, + () => withClock(Clock.fixed(instant), () => _logger.e(() => 'at a known time')), + ); + + expect(handler.records.single.time, instant); + }); + + test('gives every handler in a composite the same instant', () { + final console = RecordingLogHandler(); + final crashReporter = RecordingLogHandler(); + + withStreamLogger( + handler: StreamLogHandler.composite([console, crashReporter]), + () => _logger.e(() => 'seen by both'), + ); + + expect(console.records.single.time, crashReporter.records.single.time); + }); + + test('numbers records in the order they were created', () { + final handler = RecordingLogHandler(); + + withStreamLogger(handler: handler, () { + _logger + ..e(() => 'first') + ..e(() => 'second'); + }); + + final [first, second] = handler.records; + expect(second.sequenceNumber, first.sequenceNumber + 1); + }); + }); + group('StreamLogPriority.none', () { + test('admits nothing when a filter is held to it', () { + final handler = RecordingLogHandler(); + + withStreamLogger( + handler: handler, + filter: const StreamLogFilter.minPriority(StreamLogPriority.none), + () { + for (final priority in StreamLogPriority.values) { + expect(const StreamLogger('SC:Component').isLoggable(priority), isFalse, reason: '$priority'); + } + const StreamLogger('SC:Component').e(() => 'a failure, while shut down'); + }, + ); + + // `none` outranks every severity, so a threshold comparing against it would admit the records + // it exists to reject. + expect(handler.records, isEmpty); + }); + + test('admits nothing on the branch of a prefix rule held to it', () { + final handler = RecordingLogHandler(); + + withStreamLogger( + handler: handler, + filter: const StreamLogFilter.prefix( + {'SV:': StreamLogPriority.none}, + otherwise: StreamLogPriority.debug, + ), + () { + const StreamLogger('SV:Call').e(() => 'silenced'); + const StreamLogger('SF:Ws').d(() => 'still heard'); + }, + ); + + expect(handler.messages, ['still heard']); + }); + + test('does not build a message the threshold rejects', () { + var built = 0; + + withStreamLogger( + handler: RecordingLogHandler(), + filter: const StreamLogFilter.minPriority(StreamLogPriority.none), + () => const StreamLogger('SC:Component').e(() { + built++; + return 'never built'; + }), + ); + + expect(built, isZero); + }); + }); +} diff --git a/packages/stream_core/test/ws/client/engine/stream_web_socket_engine_test.dart b/packages/stream_core/test/ws/client/engine/stream_web_socket_engine_test.dart index b409f049..67f4ba44 100644 --- a/packages/stream_core/test/ws/client/engine/stream_web_socket_engine_test.dart +++ b/packages/stream_core/test/ws/client/engine/stream_web_socket_engine_test.dart @@ -1,6 +1,7 @@ import 'package:stream_core/stream_core.dart'; import 'package:test/test.dart'; +import '../../../helpers/logger.dart'; import '../../../helpers/web_socket.dart'; /// A codec that passes strings through untouched. @@ -287,6 +288,45 @@ void main() { expect(listener.messages, isEmpty); expect(listener.closures, isEmpty); }); + + test('reports a message it cannot decode to the logger, which is the only trace it arrived', () async { + final socket = FakeWebSocketChannel(); + addTearDown(socket.endStream); + + final handler = RecordingLogHandler(); + final engine = StreamWebSocketEngine( + wsProvider: (_) => socket, + listener: _RecordingListener(), + messageCodec: const _ThrowingCodec(), + ); + await engine.open(_options); + + await withStreamLogger(handler: handler, () async { + socket.emit('garbage'); + await pumpEventQueue(); + }); + + expect(handler.records.single.priority, StreamLogPriority.warning); + expect(handler.records.single.tag, 'SC:WsEngine'); + expect(handler.records.single.error, isA()); + }); + + test('says nothing when no handler is installed', () async { + final socket = FakeWebSocketChannel(); + addTearDown(socket.endStream); + + final engine = StreamWebSocketEngine( + wsProvider: (_) => socket, + listener: _RecordingListener(), + messageCodec: const _ThrowingCodec(), + ); + await engine.open(_options); + + final printed = capturePrints(() => socket.emit('garbage')); + await pumpEventQueue(); + + expect(printed, isEmpty); + }); } /// A codec that cannot decode anything, as one meeting an unknown frame cannot. diff --git a/packages/stream_core/test/ws/client/stream_web_socket_client_test.dart b/packages/stream_core/test/ws/client/stream_web_socket_client_test.dart index 2e1cef04..100893f9 100644 --- a/packages/stream_core/test/ws/client/stream_web_socket_client_test.dart +++ b/packages/stream_core/test/ws/client/stream_web_socket_client_test.dart @@ -5,6 +5,7 @@ import 'package:stream_core/stream_core.dart'; import 'package:test/test.dart'; import '../../helpers/fake_server.dart'; +import '../../helpers/logger.dart'; import '../../helpers/user_token.dart'; import '../../helpers/ws_client_tester.dart'; @@ -1301,4 +1302,75 @@ void main() { }); }); }); + + group('what the logger sees', () { + test('reaches every collaborator the client owns, each under its own tag', () { + fakeAsync((async) { + final handler = RecordingLogHandler(); + final tester = buildTester(recover: true); + + withStreamLogger(handler: handler, () { + tester.client.connect().ignore(); + async.flushMicrotasks(); + // Far enough for the health monitor to ping at least once. + async.elapse(const Duration(minutes: 1)); + }); + + // Every collaborator holds its own logger, so a tag missing here means one of them is not + // reporting what it does. + expect( + handler.records.map((it) => it.tag).toSet(), + containsAll(['SC:WsClient', 'SC:WsClient:Auth', 'SC:WsClient:Health']), + ); + }); + }); + + test('tags a client and everything it owns from the tag it was given', () { + fakeAsync((async) { + final handler = RecordingLogHandler(); + final tester = buildTester(tag: 'SC:Ws2'); + + withStreamLogger(handler: handler, () { + tester.client.connect().ignore(); + async.flushMicrotasks(); + }); + + // A second client is otherwise indistinguishable from the first in one log, and its + // collaborators are tagged from it so one prefix still selects the whole family. + expect(handler.tags, everyElement(startsWith('SC:Ws2'))); + expect(handler.tags, contains('SC:Ws2:Auth')); + }); + }); + + test('records the connection reaching Connected', () { + fakeAsync((async) { + final handler = RecordingLogHandler(); + final tester = buildTester(); + + withStreamLogger(handler: handler, () { + tester.client.connect().ignore(); + async.flushMicrotasks(); + }); + + expect(tester.connectionState, isA()); + expect( + handler.records.where((it) => it.tag == 'SC:WsClient').map((it) => it.message), + contains(contains('-> Connected')), + ); + }); + }); + + test('says nothing at all when no handler is installed', () { + fakeAsync((async) { + final tester = buildTester(); + + final printed = capturePrints(() { + tester.client.connect().ignore(); + async.flushMicrotasks(); + }); + + expect(printed, isEmpty); + }); + }); + }); }