feat(serverpod_logging): Add isolate-backed IsolatedLogWriter

packages/serverpod_logging/CHANGELOG.md

@@ -1,3 +1,9 @@
+## 0.1.0
+
+- Add `IsolatedLogWriter`, a `LogWriter` that runs a wrapped writer on a
+  dedicated isolate (via `package:isolated_object`).
+- Lower the SDK constraint to `^3.6.0`.
+
 ## 0.0.1
 
 - Initial version.

packages/serverpod_logging/lib/serverpod_logging.dart

@@ -1,4 +1,5 @@
 export 'src/global_log.dart';
+export 'src/isolated_log_writer.dart';
 export 'src/log.dart';
 export 'src/log_types.dart';
 export 'src/spinner_log_writer.dart';

packages/serverpod_logging/lib/src/isolated_log_writer.dart

@@ -0,0 +1,42 @@
+import 'package:isolated_object/isolated_object.dart';
+
+import 'log_types.dart';
+
+/// A [LogWriter] that runs a wrapped writer on a dedicated isolate.
+///
+/// Not a high-throughput sink. Every operation is copied across the isolate
+/// boundary, so payloads must be sendable.
+class IsolatedLogWriter extends IsolatedObject<LogWriter> implements LogWriter {
+  /// Creates an [IsolatedLogWriter] that runs the writer produced by
+  /// [factory] on a dedicated isolate.
+  IsolatedLogWriter(super.factory);
+
+  @override
+  Future<void> log(LogEntry entry) async {
+    try {
+      await evaluate((w) => w.log(entry));
+    } catch (_) {} // best effort
+  }
+
+  @override
+  Future<void> openScope(LogScope scope) => evaluate((w) => w.openScope(scope));
+
+  @override
+  Future<void> closeScope(
+    LogScope scope, {
+    required bool success,
+    required Duration duration,
+    Object? error,
+    StackTrace? stackTrace,
+  }) async {
+    await evaluate(
+      (w) => w.closeScope(
+        scope,
+        success: success,
+        duration: duration,
+        error: error,
+        stackTrace: stackTrace,
+      ),
+    );
+  }
+}

packages/serverpod_logging/test/isolated_log_writer_test.dart

@@ -0,0 +1,128 @@
+import 'package:serverpod_logging/serverpod_logging.dart';
+import 'package:test/test.dart';
+
+LogEntry _entry(String message) => LogEntry(
+      time: DateTime.now(),
+      level: LogLevel.info,
+      message: message,
+      scope: LogScope.root('r'),
+    );
+
+/// A writer whose [log] is slow, so a write is reliably in-flight when the
+/// isolate is asked to close.
+class SlowWriter extends LogWriter {
+  @override
+  Future<void> log(LogEntry entry) async =>
+      Future<void>.delayed(const Duration(milliseconds: 100));
+
+  @override
+  Future<void> openScope(LogScope scope) async {}
+
+  @override
+  Future<void> closeScope(
+    LogScope scope, {
+    required bool success,
+    required Duration duration,
+    Object? error,
+    StackTrace? stackTrace,
+  }) async {}
+}
+
+/// A writer whose [log] fails after a delay, so a rejecting write is reliably
+/// in-flight when the isolate is asked to close.
+class SlowFailingWriter extends LogWriter {
+  @override
+  Future<void> log(LogEntry entry) async {
+    await Future<void>.delayed(const Duration(milliseconds: 100));
+    throw StateError('write failed');
+  }
+
+  @override
+  Future<void> openScope(LogScope scope) async {}
+
+  @override
+  Future<void> closeScope(
+    LogScope scope, {
+    required bool success,
+    required Duration duration,
+    Object? error,
+    StackTrace? stackTrace,
+  }) async {}
+}
+
+void main() {
+  group('Given an IsolatedLogWriter wrapping a TestLogWriter', () {
+    test(
+      'when an entry is logged, '
+      'then it is forwarded to the writer running in the isolate',
+      () async {
+        final writer = IsolatedLogWriter(() => TestLogWriter());
+
+        await writer.log(_entry('hi'));
+
+        // Read the isolate-local writer's state back across the boundary.
+        final messages = await writer.evaluate(
+          (w) => (w as TestLogWriter).entries.map((e) => e.message).toList(),
+        );
+        expect(messages, ['hi']);
+
+        await writer.close();
+      },
+    );
+
+    test(
+        'when a scope is opened and closed, '
+        'then both are forwarded to the writer running in the isolate',
+        () async {
+      final writer = IsolatedLogWriter(() => TestLogWriter());
+      final scope = LogScope.root('op');
+
+      await writer.openScope(scope);
+      await writer.closeScope(scope, success: true, duration: Duration.zero);
+
+      final opened = await writer.evaluate(
+        (w) => (w as TestLogWriter).openedScopes.length,
+      );
+      final closed = await writer.evaluate(
+        (w) => (w as TestLogWriter).closedScopes.length,
+      );
+      expect(opened, 1);
+      expect(closed, 1);
+
+      await writer.close();
+    });
+  });
+
+  group('Given an IsolatedLogWriter lifecycle', () {
+    test(
+        'when closed with a write in flight, '
+        'then the in-flight write is swallowed and its log future completes',
+        () async {
+      final writer = IsolatedLogWriter(() => SlowWriter());
+
+      final pending = writer.log(_entry('slow')); // intentionally not awaited
+      await writer.close();
+
+      await expectLater(pending, completes);
+    });
+
+    test(
+      'when a wrapped write fails while in flight, '
+      'then close() still completes (does not rethrow the failure)',
+      () async {
+        final writer = IsolatedLogWriter(() => SlowFailingWriter());
+
+        // ignore: unawaited_futures - fire-and-forget, like Log.call.
+        writer.log(_entry('boom')).catchError((_) {});
+        await expectLater(writer.close(), completes);
+      },
+    );
+
+    test('when log is called after close, then it is a no-op', () async {
+      final writer = IsolatedLogWriter(() => TestLogWriter());
+      await writer.close();
+
+      await expectLater(writer.log(_entry('x')), completes);
+    });
+  });
+}

packages/serverpod_logging/test/log_dispatch_test.dart

@@ -0,0 +1,209 @@
+import 'package:serverpod_logging/serverpod_logging.dart';
+import 'package:test/test.dart';
+
+/// A writer whose [log] always throws, to exercise the best-effort contract.
+class _ThrowingWriter extends LogWriter {
+  @override
+  Future<void> log(LogEntry entry) async => throw StateError('writer boom');
+
+  @override
+  Future<void> openScope(LogScope scope) async {}
+
+  @override
+  Future<void> closeScope(
+    LogScope scope, {
+    required bool success,
+    required Duration duration,
+    Object? error,
+    StackTrace? stackTrace,
+  }) async {}
+}
+
+/// A writer that records the order in which entries are actually written,
+/// after an artificial per-message delay.
+class _DelayedOrderWriter extends LogWriter {
+  _DelayedOrderWriter(this.delayFor);
+
+  final Duration Function(String message) delayFor;
+  final List<String> writeOrder = [];
+
+  @override
+  Future<void> log(LogEntry entry) async {
+    await Future<void>.delayed(delayFor(entry.message));
+    writeOrder.add(entry.message);
+  }
+
+  @override
+  Future<void> openScope(LogScope scope) async {}
+
+  @override
+  Future<void> closeScope(
+    LogScope scope, {
+    required bool success,
+    required Duration duration,
+    Object? error,
+    StackTrace? stackTrace,
+  }) async {}
+}
+
+LogEntry _entry(LogLevel level, String message) => LogEntry(
+      time: DateTime.now(),
+      level: level,
+      message: message,
+      scope: LogScope.root('r'),
+    );
+
+void main() {
+  group('Given a Log with a warning threshold', () {
+    late TestLogWriter writer;
+    late Log log;
+
+    setUp(() {
+      writer = TestLogWriter();
+      log = Log(writer, logLevel: LogLevel.warning);
+    });
+
+    test(
+        'when a below-threshold entry is dispatched, '
+        'then it is dropped and the factory is never invoked', () async {
+      var factoryInvoked = false;
+      log(LogLevel.info, () {
+        factoryInvoked = true;
+        return _entry(LogLevel.info, 'x');
+      });
+      await log.flush();
+
+      expect(
+        factoryInvoked,
+        isFalse,
+        reason: 'gated calls must short-circuit before the factory runs',
+      );
+      expect(writer.entries, isEmpty);
+    });
+
+    test(
+        'when an at-threshold entry is dispatched, '
+        'then it is forwarded', () async {
+      log.warning('warn');
+      await log.flush();
+
+      expect(writer.entries.single.message, 'warn');
+    });
+
+    test(
+        'when the threshold is lowered at runtime, '
+        'then newly-enabled levels start being forwarded', () async {
+      log.info('dropped');
+      log.logLevel = LogLevel.info;
+      log.info('kept');
+      await log.flush();
+
+      expect(writer.entries.map((e) => e.message), ['kept']);
+    });
+  });
+
+  group('Given a Log whose writer throws', () {
+    test(
+        'when an entry is dispatched, '
+        'then dispatch is best-effort and the error is not surfaced', () async {
+      final log = Log(_ThrowingWriter());
+
+      log.info('x');
+
+      await expectLater(log.flush(), completes);
+    });
+  });
+
+  group('Given a Log with out-of-order write timing', () {
+    test(
+        'when earlier writes are slower than later ones, '
+        'then writes still complete in invocation order', () async {
+      final writer = _DelayedOrderWriter(
+        (m) => m == '1' ? const Duration(milliseconds: 40) : Duration.zero,
+      );
+      final log = Log(writer);
+
+      log.info('1');
+      log.info('2');
+      log.info('3');
+      await log.flush();
+
+      expect(
+        writer.writeOrder,
+        ['1', '2', '3'],
+        reason: 'the _latest chain serializes writes in call order',
+      );
+    });
+  });
+
+  group('Given a closed Log', () {
+    test(
+        'when an entry is dispatched after close, '
+        'then it is dropped', () async {
+      final writer = TestLogWriter();
+      final log = Log(writer);
+
+      log.info('before');
+      await log.close();
+      log.info('after');
+      await log.flush();
+
+      expect(writer.entries.map((e) => e.message), ['before']);
+    });
+  });
+
+  group("Given a Log's debug gate (isDebugEnabled)", () {
+    test('when the level is debug, then it is enabled', () {
+      expect(
+        Log(TestLogWriter(), logLevel: LogLevel.debug).isDebugEnabled,
+        isTrue,
+      );
+    });
+
+    test('when the level is above debug, then it is disabled', () {
+      expect(
+        Log(TestLogWriter(), logLevel: LogLevel.info).isDebugEnabled,
+        isFalse,
+      );
+    });
+  });
+
+  group('Given a Log at debug level', () {
+    test(
+        'when each convenience method is called, '
+        'then the entry carries the matching LogLevel', () async {
+      final writer = TestLogWriter();
+      final log = Log(writer, logLevel: LogLevel.debug);
+
+      log.debug('d');
+      log.info('i');
+      log.warning('w');
+      log.error('e');
+      await log.flush();
+
+      expect(writer.entries.map((e) => e.level), [
+        LogLevel.debug,
+        LogLevel.info,
+        LogLevel.warning,
+        LogLevel.error,
+      ]);
+    });
+  });
+
+  group('Given the error() convenience method', () {
+    test(
+        'when it is given an error and stack trace, '
+        'then both are attached to the entry', () async {
+      final writer = TestLogWriter();
+      final log = Log(writer);
+      final stackTrace = StackTrace.current;
+
+      log.error('boom', error: StateError('x'), stackTrace: stackTrace);
+      await log.flush();
+
+      final entry = writer.entries.single;
+      expect(entry.error, isA<StateError>());
+      expect(entry.stackTrace, same(stackTrace));
+    });
+  });
+}