From 6f0584e3b0ec37baa2fc7afe58c810ba3968aa7c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kasper=20Overg=C3=A5rd=20Nielsen?= Date: Fri, 5 Jun 2026 12:18:51 +0200 Subject: [PATCH 1/3] test: Pin Log.progress scoping and no-relabel contracts - progress_nesting_test: a log emitted inside a progress runner must be attributed to the progress scope via the Zone, and a nested progress must child under the outer scope. - progress_relabel_test: progress must never surface the runner's result as a scope label (uses a generic recording writer, no terminal rendering). --- .../test/progress_nesting_test.dart | 62 ++++++++++++++++ .../test/progress_relabel_test.dart | 74 +++++++++++++++++++ 2 files changed, 136 insertions(+) create mode 100644 packages/serverpod_logging/test/progress_nesting_test.dart create mode 100644 packages/serverpod_logging/test/progress_relabel_test.dart diff --git a/packages/serverpod_logging/test/progress_nesting_test.dart b/packages/serverpod_logging/test/progress_nesting_test.dart new file mode 100644 index 0000000..1d0a1fd --- /dev/null +++ b/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', + ); + }); + }); +} diff --git a/packages/serverpod_logging/test/progress_relabel_test.dart b/packages/serverpod_logging/test/progress_relabel_test.dart new file mode 100644 index 0000000..b1e1aa6 --- /dev/null +++ b/packages/serverpod_logging/test/progress_relabel_test.dart @@ -0,0 +1,74 @@ +import 'package:serverpod_logging/serverpod_logging.dart'; +import 'package:test/test.dart'; + +/// A writer that records every scope label it is ever asked to render, +/// regardless of which lifecycle hook delivered it. +/// +/// This is deliberately a *generic* sink (think: a JSON line writer, a DB +/// writer, an OTEL exporter) - it does not animate spinners or care about +/// terminals. It exists to pin a framework-level contract: +/// +/// `Log.progress(label, runner)` describes ONE operation called [label]. +/// The runner's *return value* is data, not a new name for the operation. +/// +class _LabelRecordingWriter extends LogWriter { + final List observedLabels = []; + + @override + Future log(LogEntry entry) async {} + + @override + Future openScope(LogScope scope) async => + observedLabels.add(scope.label); + + @override + Future closeScope( + LogScope scope, { + required bool success, + required Duration duration, + Object? error, + StackTrace? stackTrace, + }) async => + observedLabels.add(scope.label); +} + +void main() { + group('Given Log.progress with a plain (non-stream) runner', () { + late _LabelRecordingWriter writer; + late Log log; + + setUp(() { + writer = _LabelRecordingWriter(); + log = Log(writer); + }); + + test( + 'when the runner returns a value, ' + 'then no scope event is labelled with that value', () async { + await log.progress('op', () async => 'sentinel-result'); + await log.flush(); + + expect( + writer.observedLabels, + everyElement('op'), + reason: 'progress must not relabel the scope with the runner result; ' + 'the operation is called "op" from start to finish', + ); + expect( + writer.observedLabels, + isNot(contains('sentinel-result')), + reason: 'the runner return value must never surface as a scope label', + ); + }); + + test( + 'when the runner returns true, ' + 'then the scope label stays "op" (not "true")', () async { + await log.progress('op', () async => true); + await log.flush(); + + expect(writer.observedLabels, everyElement('op')); + expect(writer.observedLabels, isNot(contains('true'))); + }); + }); +} From b18540f5688564b9d8b54500e706601428fd308e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kasper=20Overg=C3=A5rd=20Nielsen?= Date: Fri, 5 Jun 2026 12:20:37 +0200 Subject: [PATCH 2/3] test: Cover Log.progress with synchronous (FutureOr) runners These fail to compile if the runner is narrowed to Future Function() --- .../test/progress_sync_runner_test.dart | 72 +++++++++++++++++++ 1 file changed, 72 insertions(+) create mode 100644 packages/serverpod_logging/test/progress_sync_runner_test.dart diff --git a/packages/serverpod_logging/test/progress_sync_runner_test.dart b/packages/serverpod_logging/test/progress_sync_runner_test.dart new file mode 100644 index 0000000..e55a601 --- /dev/null +++ b/packages/serverpod_logging/test/progress_sync_runner_test.dart @@ -0,0 +1,72 @@ +import 'package:serverpod_logging/serverpod_logging.dart'; +import 'package:test/test.dart'; + +/// [Log.progress] accepts a `FutureOr Function()` runner, so a plain +/// synchronous callback (`() => value`, not `() async => value`) is a +/// supported call shape. These tests pin that contract. +void main() { + group('Given Log.progress with a synchronous runner', () { + late TestLogWriter writer; + late Log log; + + setUp(() { + writer = TestLogWriter(); + log = Log(writer); + }); + + test( + 'when the runner returns true synchronously, ' + 'then the scope closes with success true', () async { + final result = await log.progress('op', () => true); + + expect(result, isTrue); + expect(writer.closedScopes.single.success, isTrue); + }); + + test( + 'when the runner returns false synchronously, ' + 'then the scope closes with success false', () async { + final result = await log.progress('op', () => false); + + expect(result, isFalse); + expect(writer.closedScopes.single.success, isFalse); + }); + + test( + 'when a synchronous runner returns a non-bool value, ' + 'then the value is returned and the scope closes successfully', + () async { + final result = await log.progress('op', () => 'ok'); + + expect(result, 'ok'); + expect(writer.closedScopes.single.success, isTrue); + }, + ); + + test( + 'when a synchronous runner emits a log entry, ' + 'then that entry is scoped to the progress scope', () async { + await log.progress('op', () { + log.info('inside'); + return true; + }); + await log.flush(); + + final opened = writer.openedScopes.single; + final inside = writer.entries.singleWhere((e) => e.message == 'inside'); + expect(inside.scope.id, opened.id); + }); + + test( + 'when a synchronous runner throws, ' + 'then the scope closes with success false and rethrows', () async { + await expectLater( + log.progress('op', () => throw StateError('boom')), + throwsA(isA()), + ); + + expect(writer.closedScopes.single.success, isFalse); + expect(writer.closedScopes.single.error, isA()); + }); + }); +} From b9138c688a671c0e1db4d79fc2f41c681e30bec1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kasper=20Overg=C3=A5rd=20Nielsen?= Date: Fri, 5 Jun 2026 12:51:55 +0200 Subject: [PATCH 3/3] test: Cover core Log dispatch and scoping contracts Framework-level tests (no CLI rendering): - Level gating skips the entry factory below the threshold - Runtime logLevel changes take effect; isDebugEnabled tracks it - Writer errors are swallowed (dispatch is best-effort) - Writes serialize in invocation order even when earlier ones are slower - close() drops any further dispatches - Convenience methods map to the right level; error() attaches error + stack trace - Logs emitted outside any progress attach to the synthetic root scope - progress passes metadata through to the opened scope - LogScope parent/child: root has no parent; a child keeps its own id/label/metadata --- .../test/log_dispatch_test.dart | 209 ++++++++++++++++++ .../test/log_scope_test.dart | 53 +++++ 2 files changed, 262 insertions(+) create mode 100644 packages/serverpod_logging/test/log_dispatch_test.dart create mode 100644 packages/serverpod_logging/test/log_scope_test.dart diff --git a/packages/serverpod_logging/test/log_dispatch_test.dart b/packages/serverpod_logging/test/log_dispatch_test.dart new file mode 100644 index 0000000..31596a7 --- /dev/null +++ b/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 log(LogEntry entry) async => throw StateError('writer boom'); + + @override + Future openScope(LogScope scope) async {} + + @override + Future 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 writeOrder = []; + + @override + Future log(LogEntry entry) async { + await Future.delayed(delayFor(entry.message)); + writeOrder.add(entry.message); + } + + @override + Future openScope(LogScope scope) async {} + + @override + Future 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()); + expect(entry.stackTrace, same(stackTrace)); + }); + }); +} diff --git a/packages/serverpod_logging/test/log_scope_test.dart b/packages/serverpod_logging/test/log_scope_test.dart new file mode 100644 index 0000000..e698bd0 --- /dev/null +++ b/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}); + }, + ); + }); +}