test: Add contract tests for Log/LogWriter

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));
+    });
+  });
+}

packages/serverpod_logging/test/log_scope_test.dart

@@ -0,0 +1,53 @@
+import 'package:serverpod_logging/serverpod_logging.dart';
+import 'package:test/test.dart';
+
+void main() {
+  group('Given a Log with no active progress scope', () {
+    late TestLogWriter writer;
+    late Log log;
+
+    setUp(() {
+      writer = TestLogWriter();
+      log = Log(writer);
+    });
+
+    test(
+        'when a log is emitted, '
+        'then it attaches to the synthetic root scope', () async {
+      log.info('orphan');
+      await log.flush();
+
+      expect(writer.entries.single.scope.label, 'unknown');
+    });
+
+    test(
+        'when progress is given metadata, '
+        'then the opened scope carries it', () async {
+      await log.progress('op', () async => true, metadata: {'k': 'v'});
+
+      expect(writer.openedScopes.single.metadata, {'k': 'v'});
+    });
+  });
+
+  group('Given a root LogScope', () {
+    test('when it is created, then it has no parent', () {
+      expect(LogScope.root('root').parent, isNull);
+    });
+  });
+
+  group('Given a child LogScope', () {
+    test(
+      'when it is created, '
+      'then it references its parent and keeps its own id, label and metadata',
+      () {
+        final root = LogScope.root('root');
+        final child = root.child(id: 'c1', label: 'child', metadata: {'a': 1});
+
+        expect(child.parent, same(root));
+        expect(child.id, 'c1');
+        expect(child.label, 'child');
+        expect(child.metadata, {'a': 1});
+      },
+    );
+  });
+}

packages/serverpod_logging/test/progress_nesting_test.dart

@@ -0,0 +1,62 @@
+import 'package:serverpod_logging/serverpod_logging.dart';
+import 'package:test/test.dart';
+
+/// Regression guard for the Zone-based scoping contract of [Log.progress].
+///
+/// The whole point of [Log.progress] is documented as:
+///   "Log calls inside the runner are automatically scoped via the Zone."
+///
+/// A `log.info(...)` emitted from within the runner must be attributed
+/// to the progress scope, not to the enclosing/root scope. This is a pure
+/// framework property and has nothing to do with how (or whether) the scope
+/// is rendered.
+void main() {
+  group('Given Log.progress with a runner that logs', () {
+    late TestLogWriter writer;
+    late Log log;
+
+    setUp(() {
+      writer = TestLogWriter();
+      log = Log(writer);
+    });
+
+    test(
+        'when the runner emits a log entry, '
+        'then that entry is scoped to the progress scope', () async {
+      await log.progress('outer', () async {
+        log.info('inside');
+      });
+      await log.flush();
+
+      final opened = writer.openedScopes.single;
+      expect(opened.label, 'outer');
+
+      final inside = writer.entries.singleWhere((e) => e.message == 'inside');
+      expect(
+        inside.scope.id,
+        opened.id,
+        reason: 'a log emitted inside the runner must reference the '
+            'progress scope, via the Zone',
+      );
+      expect(inside.scope.label, 'outer');
+    });
+
+    test(
+        'when the runner opens a nested progress scope, '
+        'then the inner scope is a child of the outer scope', () async {
+      await log.progress('outer', () async {
+        await log.progress('inner', () async => true);
+      });
+      await log.flush();
+
+      final outer = writer.openedScopes.firstWhere((s) => s.label == 'outer');
+      final inner = writer.openedScopes.firstWhere((s) => s.label == 'inner');
+      expect(
+        inner.parent?.id,
+        outer.id,
+        reason: 'the inner progress scope must nest under the outer one, '
+            'which only works if the runner executes inside the outer Zone',
+      );
+    });
+  });
+}