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/5] 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/5] 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/5] 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}); + }, + ); + }); +} From 74ec85694e2aa46998ae14a24551fac93250a2e7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kasper=20Overg=C3=A5rd=20Nielsen?= Date: Fri, 5 Jun 2026 13:55:21 +0200 Subject: [PATCH 4/5] feat(serverpod_logging): Add isolate-backed IsolatedLogWriter A LogWriter that runs any wrapped writer on a dedicated isolate (via IsolatedObject), so timer-driven spinners keep animating even when the calling isolate is blocked. --- packages/serverpod_logging/CHANGELOG.md | 6 + .../lib/serverpod_logging.dart | 1 + .../lib/src/isolated_log_writer.dart | 42 ++++++ .../test/isolated_log_writer_test.dart | 128 ++++++++++++++++++ 4 files changed, 177 insertions(+) create mode 100644 packages/serverpod_logging/lib/src/isolated_log_writer.dart create mode 100644 packages/serverpod_logging/test/isolated_log_writer_test.dart diff --git a/packages/serverpod_logging/CHANGELOG.md b/packages/serverpod_logging/CHANGELOG.md index b78d64c..477f1e8 100644 --- a/packages/serverpod_logging/CHANGELOG.md +++ b/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. diff --git a/packages/serverpod_logging/lib/serverpod_logging.dart b/packages/serverpod_logging/lib/serverpod_logging.dart index c1bfb71..81e55d6 100644 --- a/packages/serverpod_logging/lib/serverpod_logging.dart +++ b/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'; diff --git a/packages/serverpod_logging/lib/src/isolated_log_writer.dart b/packages/serverpod_logging/lib/src/isolated_log_writer.dart new file mode 100644 index 0000000..4f84fca --- /dev/null +++ b/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 implements LogWriter { + /// Creates an [IsolatedLogWriter] that runs the writer produced by + /// [factory] on a dedicated isolate. + IsolatedLogWriter(super.factory); + + @override + Future log(LogEntry entry) async { + try { + await evaluate((w) => w.log(entry)); + } catch (_) {} // best effort + } + + @override + Future openScope(LogScope scope) => evaluate((w) => w.openScope(scope)); + + @override + Future 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, + ), + ); + } +} diff --git a/packages/serverpod_logging/test/isolated_log_writer_test.dart b/packages/serverpod_logging/test/isolated_log_writer_test.dart new file mode 100644 index 0000000..8d6fee9 --- /dev/null +++ b/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 log(LogEntry entry) async => + Future.delayed(const Duration(milliseconds: 100)); + + @override + Future openScope(LogScope scope) async {} + + @override + Future 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 log(LogEntry entry) async { + await Future.delayed(const Duration(milliseconds: 100)); + throw StateError('write failed'); + } + + @override + Future openScope(LogScope scope) async {} + + @override + Future 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); + }); + }); +} From c223e7bc4bf5f1afe604b748e47f6fd438ed3c7a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kasper=20Overg=C3=A5rd=20Nielsen?= Date: Fri, 5 Jun 2026 13:55:42 +0200 Subject: [PATCH 5/5] feat: Add serverpod_logging_cli bridge package A cli_tools.Logger implementation (ServerpodCliLogger) backed by the serverpod_logging LogWriter architecture, plus StdOutLogWriter (a TextLogWriter that renders LogType-aware output via cli_tools' StdOutLogger). --- .github/workflows/ci.yml | 14 +- .../publish-serverpod_logging_cli.yaml | 16 ++ packages/serverpod_logging_cli/CHANGELOG.md | 3 + packages/serverpod_logging_cli/LICENSE | 28 +++ packages/serverpod_logging_cli/README.md | 25 ++ .../analysis_options.yaml | 14 ++ .../lib/serverpod_logging_cli.dart | 10 + .../lib/src/serverpod_cli_logger.dart | 218 ++++++++++++++++++ .../lib/src/std_out_log_writer.dart | 40 ++++ packages/serverpod_logging_cli/pubspec.yaml | 21 ++ .../test/serverpod_cli_logger_test.dart | 209 +++++++++++++++++ pubspec.yaml | 1 + 12 files changed, 597 insertions(+), 2 deletions(-) create mode 100644 .github/workflows/publish-serverpod_logging_cli.yaml create mode 100644 packages/serverpod_logging_cli/CHANGELOG.md create mode 100644 packages/serverpod_logging_cli/LICENSE create mode 100644 packages/serverpod_logging_cli/README.md create mode 100644 packages/serverpod_logging_cli/analysis_options.yaml create mode 100644 packages/serverpod_logging_cli/lib/serverpod_logging_cli.dart create mode 100644 packages/serverpod_logging_cli/lib/src/serverpod_cli_logger.dart create mode 100644 packages/serverpod_logging_cli/lib/src/std_out_log_writer.dart create mode 100644 packages/serverpod_logging_cli/pubspec.yaml create mode 100644 packages/serverpod_logging_cli/test/serverpod_cli_logger_test.dart diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index f365e55..62f33da 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -15,7 +15,12 @@ jobs: fail-fast: false matrix: dart: [3.6, 3.12] - package: [cli_tools, config, isolated_object, serverpod_logging] + package: + - cli_tools + - config + - isolated_object + - serverpod_logging + - serverpod_logging_cli runs-on: ubuntu-latest defaults: run: @@ -35,7 +40,12 @@ jobs: fail-fast: false matrix: dart: [3.6, 3.12] - package: [cli_tools, config, isolated_object, serverpod_logging] + package: + - cli_tools + - config + - isolated_object + - serverpod_logging + - serverpod_logging_cli platform: [ubuntu-latest] include: - package: cli_tools diff --git a/.github/workflows/publish-serverpod_logging_cli.yaml b/.github/workflows/publish-serverpod_logging_cli.yaml new file mode 100644 index 0000000..fae0c5b --- /dev/null +++ b/.github/workflows/publish-serverpod_logging_cli.yaml @@ -0,0 +1,16 @@ +name: Publish serverpod_logging_cli package + +on: + push: + tags: + # Matches tags like serverpod_logging_cli-v1.2.3 and serverpod_logging_cli-v1.2.3-pre.1 + - 'serverpod_logging_cli-v[0-9]+.[0-9]+.[0-9]+' + - 'serverpod_logging_cli-v[0-9]+.[0-9]+.[0-9]+-*' + +jobs: + publish: + permissions: + id-token: write + uses: dart-lang/setup-dart/.github/workflows/publish.yml@v1 + with: + working-directory: packages/serverpod_logging_cli diff --git a/packages/serverpod_logging_cli/CHANGELOG.md b/packages/serverpod_logging_cli/CHANGELOG.md new file mode 100644 index 0000000..a0712a7 --- /dev/null +++ b/packages/serverpod_logging_cli/CHANGELOG.md @@ -0,0 +1,3 @@ +## 0.1.0 + +- Initial version. diff --git a/packages/serverpod_logging_cli/LICENSE b/packages/serverpod_logging_cli/LICENSE new file mode 100644 index 0000000..dcdffe5 --- /dev/null +++ b/packages/serverpod_logging_cli/LICENSE @@ -0,0 +1,28 @@ +BSD 3-Clause License + +Copyright (c) 2024, Serverpod + +Redistribution and use in source and binary forms, with or without +modification, are permitted provided that the following conditions are met: + +1. Redistributions of source code must retain the above copyright notice, this + list of conditions and the following disclaimer. + +2. Redistributions in binary form must reproduce the above copyright notice, + this list of conditions and the following disclaimer in the documentation + and/or other materials provided with the distribution. + +3. Neither the name of the copyright holder nor the names of its + contributors may be used to endorse or promote products derived from + this software without specific prior written permission. + +THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" +AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE +IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE +DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE +FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL +DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR +SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER +CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, +OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. diff --git a/packages/serverpod_logging_cli/README.md b/packages/serverpod_logging_cli/README.md new file mode 100644 index 0000000..29e8897 --- /dev/null +++ b/packages/serverpod_logging_cli/README.md @@ -0,0 +1,25 @@ +# serverpod_logging_cli + +A [`cli_tools`](https://pub.dev/packages/cli_tools) `Logger` implementation +backed by the [`serverpod_logging`](https://pub.dev/packages/serverpod_logging) +`LogWriter` architecture. It renders scoped logs and progress to the terminal +while letting output fan out to any number of backends (terminal, file, +database, …) via `LogWriter` / `MultiLogWriter`. + +## Usage + +```dart +import 'package:serverpod_logging_cli/serverpod_logging_cli.dart'; + +final logger = ServerpodCliLogger(StdOutLogWriter()); + +logger.info('Server starting'); +await logger.progress('Migrating', () async => true); + +await logger.flush(); +``` + +`progressStream` is modelled as a parent operation with one nested +sub-operation per stream event - each a real, independently-timed scope - so +the structure stays meaningful for non-terminal writers (a database writer +records the parent span plus a child span per event). diff --git a/packages/serverpod_logging_cli/analysis_options.yaml b/packages/serverpod_logging_cli/analysis_options.yaml new file mode 100644 index 0000000..c249a90 --- /dev/null +++ b/packages/serverpod_logging_cli/analysis_options.yaml @@ -0,0 +1,14 @@ +include: package:serverpod_lints/cli.yaml + +analyzer: + language: + strict-raw-types: false + errors: + inference_failure_on_instance_creation: ignore + inference_failure_on_function_invocation: ignore + inference_failure_on_untyped_parameter: ignore + prefer_final_parameters: ignore + +linter: + rules: + prefer_relative_imports: true diff --git a/packages/serverpod_logging_cli/lib/serverpod_logging_cli.dart b/packages/serverpod_logging_cli/lib/serverpod_logging_cli.dart new file mode 100644 index 0000000..f75cac7 --- /dev/null +++ b/packages/serverpod_logging_cli/lib/serverpod_logging_cli.dart @@ -0,0 +1,10 @@ +/// A cli_tools `Logger` bridge for the serverpod_logging architecture. +/// +/// This package sits on top of `serverpod_logging` (the dependency-free core) +/// and `cli_tools` (the CLI toolkit), wiring the two together. Keeping it in +/// its own package means the logging core never takes on the cli_tools +/// dependency, and the cli_tools toolkit never learns about serverpod. +library; + +export 'src/serverpod_cli_logger.dart'; +export 'src/std_out_log_writer.dart'; diff --git a/packages/serverpod_logging_cli/lib/src/serverpod_cli_logger.dart b/packages/serverpod_logging_cli/lib/src/serverpod_cli_logger.dart new file mode 100644 index 0000000..267eb01 --- /dev/null +++ b/packages/serverpod_logging_cli/lib/src/serverpod_cli_logger.dart @@ -0,0 +1,218 @@ +import 'dart:async'; +import 'dart:io'; + +import 'package:cli_tools/cli_tools.dart' as cli; +import 'package:serverpod_logging/serverpod_logging.dart'; + +import 'std_out_log_writer.dart'; + +/// A [cli.Logger] that delegates to a [Log]. +/// +/// This bridges the [cli.Logger] interface with the [LogWriter] architecture, +/// allowing multi-backend logging (terminal, TUI, file, database, etc.) via +/// [LogWriter] and [MultiLogWriter]. +/// +/// [cli.LogType] is preserved by stashing it in [LogEntry.metadata] under +/// [logTypeKey], so writers like [StdOutLogWriter] can format accordingly. +class ServerpodCliLogger extends cli.Logger { + final Log _log; + final LogWriter _writer; + + ServerpodCliLogger(LogWriter writer, {LogLevel logLevel = LogLevel.info}) + : _writer = writer, + _log = Log(writer, logLevel: logLevel), + super(toCliLogLevel(logLevel)); + + /// Releases any resources held by the underlying writer. + Future close() async { + await _log.close(); + await _writer.close(); + } + + @override + set logLevel(cli.LogLevel level) { + super.logLevel = level; + if (level == cli.LogLevel.nothing) return; + _log.logLevel = _mapLogLevel(level); + } + + @override + int? get wrapTextColumn => stdout.hasTerminal ? stdout.terminalColumns : null; + + @override + void debug( + String message, { + bool newParagraph = false, + cli.LogType type = cli.TextLogType.normal, + }) => + _call(LogLevel.debug, message, type: type); + + @override + void info( + String message, { + bool newParagraph = false, + cli.LogType type = cli.TextLogType.normal, + }) => + _call(LogLevel.info, message, type: type); + + @override + void warning( + String message, { + bool newParagraph = false, + cli.LogType type = cli.TextLogType.normal, + }) => + _call(LogLevel.warning, message, type: type); + + @override + void error( + String message, { + bool newParagraph = false, + StackTrace? stackTrace, + cli.LogType type = cli.TextLogType.normal, + }) => + _call(LogLevel.error, message, stackTrace: stackTrace, type: type); + + @override + void log( + String message, + cli.LogLevel level, { + bool newParagraph = false, + cli.LogType type = cli.TextLogType.normal, + }) { + // `nothing` is the "off" sentinel, not a message level - suppress rather + // than map it (mapping would throw on this otherwise-valid enum value). + if (level == cli.LogLevel.nothing) return; + _call(_mapLogLevel(level), message, type: type); + } + + @override + void write( + String message, + cli.LogLevel logLevel, { + bool newParagraph = false, + bool newLine = true, + }) { + if (logLevel == cli.LogLevel.nothing) return; + _call(_mapLogLevel(logLevel), message); + } + + @override + Future progress( + String message, + Future Function() runner, { + bool newParagraph = false, + String? successMessage, + }) { + if (_silent) return runner(); + return _log.progress(message, runner); + } + + /// Renders [stream] as a parent operation with one nested sub-operation per + /// event. Each sub-operation stays open until the next event arrives (or the + /// stream ends), so its elapsed time is the gap between events. The parent + /// closes when the stream completes. + /// + /// Returns the last event. Rethrows a stream error (failing the open + /// sub-operation and the parent). Throws [StateError] if the stream is empty. + @override + Future progressStream( + String initialMessage, + Stream stream, { + String Function(T)? toMessage, + bool Function(T)? isSuccess, + bool newParagraph = false, + }) async { + if (_silent) return _drain(stream); + + T? last; + return _log.progress( + initialMessage, + () async { + final events = StreamIterator(stream); + try { + if (!await events.moveNext()) { + throw StateError(_noEventsMessage); + } + while (true) { + final event = events.current; + last = event; + final label = toMessage?.call(event) ?? event.toString(); + // The sub-operation's lifetime is the wait for the next event. + var hasMore = false; + await _log.progress(label, () async { + hasMore = await events.moveNext(); + return true; + }); + if (!hasMore) break; + } + } finally { + await events.cancel(); + } + return last as T; + }, + // Let Log own the success verdict + isSuccess: isSuccess ?? (_) => true, + ); + } + + @override + Future flush() => _log.flush(); + + /// Consumes [stream] without rendering, honoring the same return/throw + /// contract as [progressStream] (used when output is silenced). + static Future _drain(Stream stream) async { + T? last; + var hasEvent = false; + await for (final event in stream) { + hasEvent = true; + last = event; + } + if (!hasEvent) throw StateError(_noEventsMessage); + return last as T; + } + + static const _noEventsMessage = 'No events in stream'; + + void _call( + LogLevel level, + String message, { + StackTrace? stackTrace, + cli.LogType? type, + }) { + if (_silent) return; + _log( + level, + () => LogEntry( + time: DateTime.now(), + level: level, + message: message, + scope: _log.currentScope, + stackTrace: stackTrace, + metadata: type != null ? {logTypeKey: type} : null, + ), + ); + } + + // serverpod_logging LogLevel has no "nothing" sentinel - its lowest-passing + // level is fatal, and the filter check is strict-`<` so fatal still leaks + // through. Progress / scope events bypass logLevel entirely. So when the + // caller sets cli.LogLevel.nothing we gate at the bridge instead of mapping + // through to _log.logLevel. + bool get _silent => super.logLevel == cli.LogLevel.nothing; + + static LogLevel _mapLogLevel(cli.LogLevel level) => switch (level) { + cli.LogLevel.debug => LogLevel.debug, + cli.LogLevel.info => LogLevel.info, + cli.LogLevel.warning => LogLevel.warning, + cli.LogLevel.error => LogLevel.error, + // The setter early-returns before reaching here, so this branch only + // fires from log() / write() being called with nothing as a message + // level - which is a programmer error worth surfacing. + cli.LogLevel.nothing => throw ArgumentError.value( + level, + 'level', + 'cli.LogLevel.nothing is a filter sentinel; it cannot be used as a ' + 'message level', + ), + }; +} diff --git a/packages/serverpod_logging_cli/lib/src/std_out_log_writer.dart b/packages/serverpod_logging_cli/lib/src/std_out_log_writer.dart new file mode 100644 index 0000000..4d2e8b0 --- /dev/null +++ b/packages/serverpod_logging_cli/lib/src/std_out_log_writer.dart @@ -0,0 +1,40 @@ +import 'package:cli_tools/cli_tools.dart' as cli; +import 'package:serverpod_logging/serverpod_logging.dart'; + +/// Metadata key used to pass [cli.LogType] through [LogEntry.metadata]. +const logTypeKey = 'serverpod:logType'; + +/// Maps a [LogLevel] to the [cli.LogLevel]. +cli.LogLevel toCliLogLevel(LogLevel level) => switch (level) { + LogLevel.debug => cli.LogLevel.debug, + LogLevel.info => cli.LogLevel.info, + LogLevel.warning => cli.LogLevel.warning, + LogLevel.error || LogLevel.fatal => cli.LogLevel.error, + }; + +/// A [TextLogWriter] that renders log lines through a [cli.StdOutLogger], +/// adding [cli.LogType]-aware formatting, ie. bullets, headers, boxes, Windows +/// emoji replacements, etc. +class StdOutLogWriter extends TextLogWriter { + final cli.StdOutLogger _logger; + + StdOutLogWriter({Map? replacements}) + : _logger = cli.StdOutLogger( + // Accept all levels - filtering is done by Log, not the writer. + cli.LogLevel.debug, + replacements: replacements, + // Match TextLogWriter: errors and above go to stderr. + logToStderrLevelThreshold: cli.LogLevel.error, + ); + + @override + void writeLogLine(LogEntry entry) { + final type = + entry.metadata?[logTypeKey] as cli.LogType? ?? cli.TextLogType.normal; + if (entry.level == LogLevel.error || entry.level == LogLevel.fatal) { + _logger.error(entry.message, stackTrace: entry.stackTrace, type: type); + } else { + _logger.log(entry.message, toCliLogLevel(entry.level), type: type); + } + } +} diff --git a/packages/serverpod_logging_cli/pubspec.yaml b/packages/serverpod_logging_cli/pubspec.yaml new file mode 100644 index 0000000..247a735 --- /dev/null +++ b/packages/serverpod_logging_cli/pubspec.yaml @@ -0,0 +1,21 @@ +name: serverpod_logging_cli +description: >- + A cli_tools.Logger bridge for the serverpod_logging architecture, rendering + scoped logs and progress to the terminal. +version: 0.1.0 +repository: https://github.com/serverpod/serverpod +homepage: https://serverpod.dev +issue_tracker: https://github.com/serverpod/serverpod/issues + +environment: + sdk: ^3.6.0 + +resolution: workspace + +dependencies: + cli_tools: ^0.13.1 + serverpod_logging: ^0.1.0 + +dev_dependencies: + serverpod_lints: '>=2.7.0' + test: ^1.25.6 diff --git a/packages/serverpod_logging_cli/test/serverpod_cli_logger_test.dart b/packages/serverpod_logging_cli/test/serverpod_cli_logger_test.dart new file mode 100644 index 0000000..a69f8ef --- /dev/null +++ b/packages/serverpod_logging_cli/test/serverpod_cli_logger_test.dart @@ -0,0 +1,209 @@ +import 'package:cli_tools/cli_tools.dart' as cli; +import 'package:serverpod_logging/serverpod_logging.dart'; +import 'package:serverpod_logging_cli/serverpod_logging_cli.dart'; +import 'package:test/test.dart'; + +Stream _failingStream(List before, Object error) async* { + for (final e in before) { + yield e; + } + throw error; +} + +void main() { + group('Given a ServerpodCliLogger over a TestLogWriter', () { + late TestLogWriter writer; + late ServerpodCliLogger logger; + + setUp(() { + writer = TestLogWriter(); + logger = ServerpodCliLogger(writer); + }); + + test( + 'when progress runs a runner that returns true, ' + 'then it opens and closes exactly one scope marked successful', + () async { + final result = await logger.progress('op', () async => true); + + expect(result, isTrue); + expect(writer.openedScopes.map((s) => s.label), ['op']); + expect(writer.closedScopes.single.success, isTrue); + }); + + test( + 'when progress runs a runner that returns false, ' + 'then the scope closes unsuccessfully', () async { + final result = await logger.progress('op', () async => false); + + expect(result, isFalse); + expect(writer.closedScopes.single.success, isFalse); + }); + + test( + 'when progressStream consumes a multi-event stream, ' + 'then each event is a sub-operation nested under the parent ' + '(the "db shape": one parent span, one child span per event)', + () async { + final result = await logger.progressStream( + 'Deploying', + Stream.fromIterable(['build', 'deploy']), + toMessage: (s) => s, + ); + + expect(result, 'deploy'); + + // Parent opens first, then a child per event. + expect(writer.openedScopes.map((s) => s.label), [ + 'Deploying', + 'build', + 'deploy', + ]); + + final parent = writer.openedScopes.first; + final children = writer.openedScopes.skip(1); + expect( + children.map((s) => s.parent?.id), + everyElement(parent.id), + reason: 'every event scope must nest under the parent operation', + ); + + // Children close before the parent; nothing is relabeled. + expect(writer.closedScopes.map((c) => c.scope.label), [ + 'build', + 'deploy', + 'Deploying', + ]); + expect(writer.closedScopes.map((c) => c.success), everyElement(isTrue)); + }); + + test( + 'when progressStream consumes a single event, ' + 'then it behaves like one sub-operation and returns the event', + () async { + final result = await logger.progressStream('P', Stream.value(42)); + + expect(result, 42); + expect(writer.openedScopes.map((s) => s.label), ['P', '42']); + expect(writer.closedScopes.map((c) => c.scope.label), ['42', 'P']); + }); + + test( + 'when progressStream is given an isSuccess, ' + 'then it decides the parent verdict while sub-operations stay successful', + () async { + await logger.progressStream( + 'P', + Stream.fromIterable(['a', 'b']), + toMessage: (s) => s, + isSuccess: (s) => s == 'never', + ); + + final byLabel = { + for (final c in writer.closedScopes) c.scope.label: c.success, + }; + expect(byLabel['a'], isTrue); + expect(byLabel['b'], isTrue); + expect(byLabel['P'], isFalse, reason: 'isSuccess(last) == false'); + }); + + test( + 'when progressStream consumes a bool stream ending in false without ' + 'isSuccess, then it still succeeds (the last event is not coerced)', + () async { + final result = await logger.progressStream( + 'P', + Stream.fromIterable([true, false]), + ); + + expect(result, isFalse, reason: 'returns the last event'); + final parent = writer.closedScopes.firstWhere( + (c) => c.scope.label == 'P', + ); + expect( + parent.success, + isTrue, + reason: 'stream completed without error -> success', + ); + }); + + test( + 'when the stream errors, ' + 'then the open sub-operation and the parent fail and it is rethrown', + () async { + await expectLater( + logger.progressStream( + 'P', + _failingStream(['a'], Exception('boom')), + toMessage: (s) => s, + ), + throwsA(isA()), + ); + + final byLabel = {for (final c in writer.closedScopes) c.scope.label: c}; + expect(byLabel['a']!.success, isFalse); + expect(byLabel['a']!.error, isA()); + expect(byLabel['P']!.success, isFalse); + }); + + test( + 'when progressStream consumes an empty stream, ' + 'then it throws StateError and fails the parent only', () async { + await expectLater( + logger.progressStream('P', const Stream.empty()), + throwsA(isA()), + ); + + expect(writer.openedScopes.map((s) => s.label), ['P']); + expect(writer.closedScopes.single.success, isFalse); + }); + + test( + 'when info() is given a cli LogType, ' + 'then the entry carries it in metadata', () async { + logger.info('hello', type: cli.TextLogType.bullet); + await logger.flush(); + + final entry = writer.entries.single; + expect(entry.message, 'hello'); + expect(entry.metadata?[logTypeKey], cli.TextLogType.bullet); + }); + + test( + 'when log/write is called with cli.LogLevel.nothing, ' + 'then it is suppressed, not an error', () async { + logger.log('x', cli.LogLevel.nothing); + logger.write('y', cli.LogLevel.nothing); + await logger.flush(); + + expect(writer.entries, isEmpty); + }); + + test( + 'when error() is given a stack trace, ' + 'then it stays structured on the entry', () async { + final st = StackTrace.current; + logger.error('bad', stackTrace: st); + await logger.flush(); + + final entry = writer.entries.single; + expect(entry.level, LogLevel.error); + expect(entry.message, 'bad', reason: 'message is not flattened'); + expect(entry.stackTrace, same(st)); + }); + + test( + 'when the logger is silenced (cli.LogLevel.nothing), ' + 'then nothing is logged or scoped (the runner still runs)', () async { + logger.logLevel = cli.LogLevel.nothing; + + logger.info('dropped'); + final result = await logger.progress('op', () async => true); + await logger.flush(); + + expect(result, isTrue, reason: 'runner still runs while silent'); + expect(writer.entries, isEmpty); + expect(writer.openedScopes, isEmpty); + }); + }); +} diff --git a/pubspec.yaml b/pubspec.yaml index 6b4b966..b874168 100644 --- a/pubspec.yaml +++ b/pubspec.yaml @@ -10,6 +10,7 @@ workspace: - packages/cli_tools - packages/serverpod_logging - packages/isolated_object + - packages/serverpod_logging_cli topics: - cli