From 9a7f8933c7f2bfc336ce0f08f1124225c211c06c Mon Sep 17 00:00:00 2001 From: Ashley Venn Date: Thu, 2 Jul 2026 18:38:41 -0700 Subject: [PATCH 1/3] feat: expand runtime logger levels --- apps/focus_flow_flutter/README.md | 18 ++- .../app/runtime/focus_flow_file_logger.dart | 93 ++++++++++-- .../runtime/focus_flow_runtime_config.dart | 15 +- .../test/app/runtime_config_test.dart | 139 +++++++++++++++++- 4 files changed, 243 insertions(+), 22 deletions(-) diff --git a/apps/focus_flow_flutter/README.md b/apps/focus_flow_flutter/README.md index a4676a1..cacbb15 100644 --- a/apps/focus_flow_flutter/README.md +++ b/apps/focus_flow_flutter/README.md @@ -51,16 +51,30 @@ Supported optional keys: ```json { - "LogLevel": "debug", + "LogLevel": "fine", "LogfileLocation": "~/ADHD_Scheduler/debug/" } ``` -`LogLevel` accepts `trace`, `debug`, `info`, `warn`, or `error`. +`LogLevel` accepts `finest`, `finer`, `fine`, `debug`, `info`, `warn`, or +`error`. `LogfileLocation` is treated as a directory, and the app writes `focus_flow.log` inside it. If either key is absent or invalid, file logging is not enabled and the app ignores that setting. +Verbose log levels can include automatic caller information without requiring +each call site to pass it manually. `finest` includes caller frames for every +written message. `fine`, `finer`, and `finest` include caller frames for +warnings and errors. This caller lookup is skipped when the configured level +does not require it. + +For expensive debug/detail messages, pass a lazy closure so work is skipped when +the configured level would not write the log: + +```dart +logger.debug(() => 'state=${expensiveStateDump()}'); +``` + ## Package Boundary Allowed app imports include public scheduler APIs such as: diff --git a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart index dd63d15..74e2b1c 100644 --- a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart +++ b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart @@ -8,6 +8,9 @@ import 'dart:io'; import 'focus_flow_runtime_config.dart'; +/// Lazily creates a log message only after the target level is enabled. +typedef FocusFlowLogMessage = Object? Function(); + /// Minimal append-only file logger for FocusFlow runtime diagnostics. final class FocusFlowFileLogger { /// Creates a logger with explicit runtime state. @@ -63,23 +66,33 @@ final class FocusFlowFileLogger { /// Whether this logger currently writes to a file. bool get isEnabled => minimumLevel != null && logFilePath != null; - /// Writes a trace-level [message] when enabled for trace. - Future trace(String message) { - return write(FocusFlowLogLevel.trace, message); + /// Writes a finest-level [message] when enabled for finest logging. + Future finest(Object? message) { + return write(FocusFlowLogLevel.finest, message); + } + + /// Writes a finer-level [message] when enabled for finer logging. + Future finer(Object? message) { + return write(FocusFlowLogLevel.finer, message); + } + + /// Writes a fine-level [message] when enabled for fine logging. + Future fine(Object? message) { + return write(FocusFlowLogLevel.fine, message); } /// Writes a debug-level [message] when enabled for debug or lower. - Future debug(String message) { + Future debug(Object? message) { return write(FocusFlowLogLevel.debug, message); } /// Writes an info-level [message] when enabled for info or lower. - Future info(String message) { + Future info(Object? message) { return write(FocusFlowLogLevel.info, message); } /// Writes a warning-level [message] when enabled for warning or lower. - Future warn(String message, {Object? error, StackTrace? stackTrace}) { + Future warn(Object? message, {Object? error, StackTrace? stackTrace}) { return write( FocusFlowLogLevel.warn, message, @@ -89,7 +102,7 @@ final class FocusFlowFileLogger { } /// Writes an error-level [message] when file logging is enabled. - Future error(String message, {Object? error, StackTrace? stackTrace}) { + Future error(Object? message, {Object? error, StackTrace? stackTrace}) { return write( FocusFlowLogLevel.error, message, @@ -101,7 +114,7 @@ final class FocusFlowFileLogger { /// Writes [message] at [level] when it passes the configured threshold. Future write( FocusFlowLogLevel level, - String message, { + Object? message, { Object? error, StackTrace? stackTrace, }) async { @@ -113,12 +126,23 @@ final class FocusFlowFileLogger { return; } + final caller = + _shouldCaptureCaller(level: level, minimumLevel: configuredLevel) + ? _callerFrame() + : null; + final resolvedMessage = _resolveMessage(message); final buffer = StringBuffer() ..write(_now().toUtc().toIso8601String()) ..write(' ') ..write(level.name.toUpperCase()) - ..write(' ') - ..write(message.trim()); + ..write(' '); + if (caller != null) { + buffer + ..write('caller=') + ..write(caller) + ..write(' '); + } + buffer.write(resolvedMessage); if (error != null) { buffer ..write(' | error=') @@ -145,17 +169,56 @@ bool _shouldWrite(FocusFlowLogLevel level, FocusFlowLogLevel minimumLevel) { /// Converts [level] to an ordered severity value. int _severity(FocusFlowLogLevel level) { return switch (level) { - FocusFlowLogLevel.trace => 0, - FocusFlowLogLevel.debug => 1, - FocusFlowLogLevel.info => 2, - FocusFlowLogLevel.warn => 3, - FocusFlowLogLevel.error => 4, + FocusFlowLogLevel.finest => 0, + FocusFlowLogLevel.finer => 1, + FocusFlowLogLevel.fine => 2, + FocusFlowLogLevel.debug => 3, + FocusFlowLogLevel.info => 4, + FocusFlowLogLevel.warn => 5, + FocusFlowLogLevel.error => 6, }; } +/// Whether automatic callsite capture should run for [level]. +bool _shouldCaptureCaller({ + required FocusFlowLogLevel level, + required FocusFlowLogLevel minimumLevel, +}) { + if (minimumLevel == FocusFlowLogLevel.finest) { + return true; + } + final capturesWarningContext = + level == FocusFlowLogLevel.warn || level == FocusFlowLogLevel.error; + return capturesWarningContext && + _severity(minimumLevel) <= _severity(FocusFlowLogLevel.fine); +} + +/// Resolves a plain or lazy message after level gating has passed. +String _resolveMessage(Object? message) { + final resolved = message is FocusFlowLogMessage ? message() : message; + return resolved?.toString().trim() ?? ''; +} + +/// Captures the first stack frame outside the logger implementation. +String _callerFrame() { + for (final line in StackTrace.current.toString().split('\n')) { + final trimmed = line.trim(); + if (trimmed.isEmpty || trimmed.contains('focus_flow_file_logger.dart')) { + continue; + } + return _sanitizeForSingleLine(trimmed); + } + return 'unknown'; +} + /// Returns the current UTC timestamp. DateTime _utcNow() => DateTime.now().toUtc(); +/// Keeps diagnostic text on one line for append-only file logs. +String _sanitizeForSingleLine(String value) { + return value.replaceAll('\n', r'\n'); +} + /// Joins [base] and [child] with the platform path separator. String _joinPath(String base, String child) { if (base.endsWith('/') || base.endsWith(r'\')) { diff --git a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart index 1d68d35..0013ea8 100644 --- a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart +++ b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart @@ -67,10 +67,16 @@ final class FocusFlowRuntimeConfig { bool get enablesFileLogging => logLevel != null && logFileLocation != null; } -/// Supported FocusFlow file logging levels. +/// Supported FocusFlow file logging levels, ordered from most to least verbose. enum FocusFlowLogLevel { - /// Logs every message, including trace-level detail. - trace, + /// Logs every message with automatic callsite detail. + finest, + + /// Logs intra-method minor actions and small state changes. + finer, + + /// Logs secondary details, possible issues, and rich warning/error context. + fine, /// Logs debug, info, warning, and error messages. debug, @@ -90,6 +96,9 @@ enum FocusFlowLogLevel { if (normalized == null || normalized.isEmpty) { return null; } + if (normalized == 'trace') { + return finest; + } for (final level in FocusFlowLogLevel.values) { if (level.name == normalized) { return level; diff --git a/apps/focus_flow_flutter/test/app/runtime_config_test.dart b/apps/focus_flow_flutter/test/app/runtime_config_test.dart index e9a38cf..7cc5251 100644 --- a/apps/focus_flow_flutter/test/app/runtime_config_test.dart +++ b/apps/focus_flow_flutter/test/app/runtime_config_test.dart @@ -38,16 +38,26 @@ void main() { '${directory.path}${Platform.pathSeparator}config.json', ); await configFile.writeAsString( - jsonEncode({'LogLevel': 'trace', 'LogfileLocation': directory.path}), + jsonEncode({'LogLevel': 'finest', 'LogfileLocation': directory.path}), ); final config = await FocusFlowRuntimeConfig.load(path: configFile.path); - expect(config.logLevel, FocusFlowLogLevel.trace); + expect(config.logLevel, FocusFlowLogLevel.finest); expect(config.logFileLocation, directory.path); expect(config.enablesFileLogging, isTrue); }); + test('parses every supported log level', () { + expect(FocusFlowLogLevel.tryParse('finest'), FocusFlowLogLevel.finest); + expect(FocusFlowLogLevel.tryParse('finer'), FocusFlowLogLevel.finer); + expect(FocusFlowLogLevel.tryParse('fine'), FocusFlowLogLevel.fine); + expect(FocusFlowLogLevel.tryParse('debug'), FocusFlowLogLevel.debug); + expect(FocusFlowLogLevel.tryParse('info'), FocusFlowLogLevel.info); + expect(FocusFlowLogLevel.tryParse('warn'), FocusFlowLogLevel.warn); + expect(FocusFlowLogLevel.tryParse('error'), FocusFlowLogLevel.error); + }); + test('loads supported logging settings from JSON', () { final config = FocusFlowRuntimeConfig.fromJson({ 'LogLevel': 'debug', @@ -107,5 +117,130 @@ void main() { expect(contents, contains('written warning')); expect(contents, contains('ERROR written error | error=boom')); }); + + test('skips lazy message work below the configured level', () async { + final directory = await Directory.systemTemp.createTemp( + 'focus-flow-lazy-skip-test-', + ); + addTearDown(() => directory.delete(recursive: true)); + final logger = await FocusFlowFileLogger.open( + FocusFlowRuntimeConfig( + logLevel: FocusFlowLogLevel.info, + logFileLocation: directory.path, + ), + ); + var evaluated = false; + + await logger.debug(() { + evaluated = true; + return 'expensive debug state'; + }); + + expect(evaluated, isFalse); + expect( + File( + '${directory.path}${Platform.pathSeparator}focus_flow.log', + ).existsSync(), + isFalse, + ); + }); + + test('evaluates lazy messages once the level is enabled', () async { + final directory = await Directory.systemTemp.createTemp( + 'focus-flow-lazy-write-test-', + ); + addTearDown(() => directory.delete(recursive: true)); + final logger = await FocusFlowFileLogger.open( + FocusFlowRuntimeConfig( + logLevel: FocusFlowLogLevel.debug, + logFileLocation: directory.path, + ), + now: () => DateTime.utc(2026, 7, 3, 12), + ); + var evaluations = 0; + + await logger.debug(() { + evaluations += 1; + return 'computed debug state'; + }); + + expect(evaluations, 1); + final contents = await File( + '${directory.path}${Platform.pathSeparator}focus_flow.log', + ).readAsString(); + expect(contents, contains('DEBUG computed debug state')); + }); + + test( + 'finest captures caller information for every written level', + () async { + final directory = await Directory.systemTemp.createTemp( + 'focus-flow-finest-caller-test-', + ); + addTearDown(() => directory.delete(recursive: true)); + final logger = await FocusFlowFileLogger.open( + FocusFlowRuntimeConfig( + logLevel: FocusFlowLogLevel.finest, + logFileLocation: directory.path, + ), + now: () => DateTime.utc(2026, 7, 3, 12), + ); + + await logger.info('high level message'); + + final contents = await File( + '${directory.path}${Platform.pathSeparator}focus_flow.log', + ).readAsString(); + expect(contents, contains('INFO caller=')); + expect(contents, contains('runtime_config_test.dart')); + expect(contents, contains('high level message')); + }, + ); + + test('fine captures caller information for warnings and errors', () async { + final directory = await Directory.systemTemp.createTemp( + 'focus-flow-fine-caller-test-', + ); + addTearDown(() => directory.delete(recursive: true)); + final logger = await FocusFlowFileLogger.open( + FocusFlowRuntimeConfig( + logLevel: FocusFlowLogLevel.fine, + logFileLocation: directory.path, + ), + now: () => DateTime.utc(2026, 7, 3, 12), + ); + + await logger.warn('handled warning'); + + final contents = await File( + '${directory.path}${Platform.pathSeparator}focus_flow.log', + ).readAsString(); + expect(contents, contains('WARN caller=')); + expect(contents, contains('runtime_config_test.dart')); + expect(contents, contains('handled warning')); + }); + + test('info does not capture caller information for warnings', () async { + final directory = await Directory.systemTemp.createTemp( + 'focus-flow-info-caller-test-', + ); + addTearDown(() => directory.delete(recursive: true)); + final logger = await FocusFlowFileLogger.open( + FocusFlowRuntimeConfig( + logLevel: FocusFlowLogLevel.info, + logFileLocation: directory.path, + ), + now: () => DateTime.utc(2026, 7, 3, 12), + ); + + await logger.warn('minimal warning'); + + final contents = await File( + '${directory.path}${Platform.pathSeparator}focus_flow.log', + ).readAsString(); + expect(contents, contains('WARN minimal warning')); + expect(contents, isNot(contains('caller='))); + expect(contents, isNot(contains('runtime_config_test.dart'))); + }); }); } From d5f5fc1b8f7336c8f58223c86e94a309ac139d0b Mon Sep 17 00:00:00 2001 From: Ashley Venn Date: Thu, 2 Jul 2026 18:46:58 -0700 Subject: [PATCH 2/3] feat: add flexible task action logging --- .../flexible_task_action_service.dart | 432 +++++++++++++++++- 1 file changed, 423 insertions(+), 9 deletions(-) diff --git a/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart b/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart index 12870b9..c0715bb 100644 --- a/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart @@ -3,6 +3,145 @@ part of '../../task_actions.dart'; +/// Lazily creates a flexible-task action log message after level gating passes. +typedef FlexibleTaskActionLogMessage = Object? Function(); + +/// Receives a flexible-task action log entry. +typedef FlexibleTaskActionLogSink = void Function( + FlexibleTaskActionLogEntry entry, +); + +/// Log levels used by [FlexibleTaskActionService]. +enum FlexibleTaskActionLogLevel { + /// Extremely granular data dumps with automatic caller information. + finest, + + /// Intra-method minor actions and small state changes. + finer, + + /// Secondary details, possible issues, and rich warning/error context. + fine, + + /// High-level debug flow and state values. + debug, + + /// Very high-level healthy lifecycle checkpoints. + info, + + /// Handled issues where the service recovered and returned a safe result. + warn, + + /// Invalid or unsafe states that should be reviewed. + error, +} + +/// Structured log entry emitted by [FlexibleTaskActionLogger]. +class FlexibleTaskActionLogEntry { + /// Creates a log entry for one flexible-task action event. + const FlexibleTaskActionLogEntry({ + required this.level, + required this.message, + this.caller, + }); + + /// Severity level for this entry. + final FlexibleTaskActionLogLevel level; + + /// Already-resolved message text. + final String message; + + /// Optional source frame captured according to the configured level. + final String? caller; +} + +/// Optional logger used by [FlexibleTaskActionService]. +/// +/// The default constructor is disabled, so existing callers pay only a cheap +/// null/level check. Expensive message construction should be guarded with +/// [isEnabled] and passed as a [FlexibleTaskActionLogMessage]. +class FlexibleTaskActionLogger { + /// Creates a logger that drops every message. + const FlexibleTaskActionLogger.disabled() + : minimumLevel = null, + sink = null; + + /// Creates a logger that sends enabled entries to [sink]. + const FlexibleTaskActionLogger({ + required this.minimumLevel, + required this.sink, + }); + + /// Minimum level to emit, or null when disabled. + final FlexibleTaskActionLogLevel? minimumLevel; + + /// Destination for enabled log entries. + final FlexibleTaskActionLogSink? sink; + + /// Whether [level] would be emitted by this logger. + bool isEnabled(FlexibleTaskActionLogLevel level) { + final configured = minimumLevel; + return configured != null && + sink != null && + _shouldWrite(level, configured); + } + + /// Logs [message] at `finest` when enabled. + void finest(Object? message) { + write(FlexibleTaskActionLogLevel.finest, message); + } + + /// Logs [message] at `finer` when enabled. + void finer(Object? message) { + write(FlexibleTaskActionLogLevel.finer, message); + } + + /// Logs [message] at `fine` when enabled. + void fine(Object? message) { + write(FlexibleTaskActionLogLevel.fine, message); + } + + /// Logs [message] at `debug` when enabled. + void debug(Object? message) { + write(FlexibleTaskActionLogLevel.debug, message); + } + + /// Logs [message] at `info` when enabled. + void info(Object? message) { + write(FlexibleTaskActionLogLevel.info, message); + } + + /// Logs [message] at `warn` when enabled. + void warn(Object? message) { + write(FlexibleTaskActionLogLevel.warn, message); + } + + /// Logs [message] at `error` when enabled. + void error(Object? message) { + write(FlexibleTaskActionLogLevel.error, message); + } + + /// Logs [message] at [level] when enabled. + void write(FlexibleTaskActionLogLevel level, Object? message) { + final configured = minimumLevel; + final currentSink = sink; + if (configured == null || + currentSink == null || + !_shouldWrite(level, configured)) { + return; + } + + currentSink( + FlexibleTaskActionLogEntry( + level: level, + message: _resolveLogMessage(message), + caller: _shouldCaptureCaller(level: level, minimumLevel: configured) + ? _callerFrame() + : null, + ), + ); + } +} + /// Applies low-friction quick actions for flexible task cards. /// /// This service is the adapter between small UI button presses and domain logic. @@ -16,6 +155,7 @@ class FlexibleTaskActionService { this.schedulingEngine = const SchedulingEngine(), this.transitionService = const TaskTransitionService(), this.clock = const SystemClock(), + this.logger = const FlexibleTaskActionLogger.disabled(), }); /// Scheduling dependency used for actions that need timeline changes. @@ -27,6 +167,9 @@ class FlexibleTaskActionService { /// Clock boundary used when an action timestamp is not supplied. final Clock clock; + /// Optional logger for diagnostics around flexible task actions. + final FlexibleTaskActionLogger logger; + /// Apply the first-stage quick action. /// /// Direct actions (`done`, `backlog`) return a changed task. `push` returns the @@ -43,15 +186,42 @@ class FlexibleTaskActionService { Iterable existingActivities = const [], }) { if (!task.isFlexible) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.error)) { + logger.error(() => 'Flexible action rejected for non-flexible task. ' + 'action=${action.name} taskId=${task.id} taskType=${task.type.name} ' + 'taskStatus=${task.status.name}'); + } throw ArgumentError.value( task.type, 'task.type', 'Task must be flexible.'); } + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Applying flexible quick action. ' + 'action=${action.name} taskId=${task.id} ' + 'taskStatus=${task.status.name} hasExplicitUpdatedAt=${updatedAt != null} ' + 'hasOperationId=${operationId != null}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { + logger.finest(() => 'Flexible quick action input dump. ' + 'action=${action.name} task=${_taskSummary(task)} ' + 'updatedAt=${updatedAt?.toIso8601String()} operationId=$operationId ' + 'actualStart=${actualStart?.toIso8601String()} ' + 'actualEnd=${actualEnd?.toIso8601String()} ' + 'lockedIntervals=${_intervalSummary(lockedIntervals)} ' + 'existingActivityCount=${existingActivities.length}'); + } + switch (action) { case FlexibleTaskQuickAction.done: final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId(action.name, task.id, now); + if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { + logger.finer(() => 'Completing flexible task. taskId=${task.id} ' + 'operationId=$opId occurredAt=${now.toIso8601String()} ' + 'hasActualStart=${actualStart != null} hasActualEnd=${actualEnd != null} ' + 'lockedIntervalCount=${lockedIntervals.length}'); + } final transition = transitionService.apply( task: task, transitionCode: TaskTransitionCode.complete, @@ -67,6 +237,19 @@ class FlexibleTaskActionService { lockedIntervals: lockedIntervals, existingActivities: existingActivities, ); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible task completion transition finished. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'nextStatus=${transition.task.status.name} ' + 'activityCount=${transition.activities.length}'); + } + if (transition.outcomeCode != TaskTransitionOutcomeCode.applied && + logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { + logger.fine(() => + 'Possible issue: flexible completion did not apply. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'previousStatus=${task.status.name} nextStatus=${transition.task.status.name}'); + } return FlexibleTaskActionResult( action: action, task: transition.task, @@ -74,6 +257,15 @@ class FlexibleTaskActionService { transitionOutcomeCode: transition.outcomeCode, ); case FlexibleTaskQuickAction.push: + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible push destination menu requested. ' + 'taskId=${task.id} taskStatus=${task.status.name}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { + logger.finer(() => 'Flexible push destinations prepared. ' + 'taskId=${task.id} destinations=' + '${PushDestination.values.map((destination) => destination.name).join(',')}'); + } return FlexibleTaskActionResult( action: action, task: task, @@ -87,6 +279,13 @@ class FlexibleTaskActionService { final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId(action.name, task.id, now); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger + .debug(() => 'Moving flexible task to backlog from quick action. ' + 'taskId=${task.id} operationId=$opId ' + 'occurredAt=${now.toIso8601String()} ' + 'previousStatus=${task.status.name}'); + } final transition = transitionService.apply( task: task, transitionCode: TaskTransitionCode.moveToBacklog, @@ -99,6 +298,19 @@ class FlexibleTaskActionService { occurredAt: now, existingActivities: existingActivities, ); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible task backlog transition finished. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'nextStatus=${transition.task.status.name} ' + 'activityCount=${transition.activities.length}'); + } + if (transition.outcomeCode != TaskTransitionOutcomeCode.applied && + logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { + logger.fine(() => + 'Possible issue: move-to-backlog quick action did not apply. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'previousStatus=${task.status.name} nextStatus=${transition.task.status.name}'); + } return FlexibleTaskActionResult( action: action, task: transition.task, @@ -106,6 +318,10 @@ class FlexibleTaskActionService { transitionOutcomeCode: transition.outcomeCode, ); case FlexibleTaskQuickAction.breakUp: + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible break-up flow requested. ' + 'taskId=${task.id} taskStatus=${task.status.name}'); + } return FlexibleTaskActionResult( action: action, task: task, @@ -129,11 +345,30 @@ class FlexibleTaskActionService { final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId('push-${destination.name}', taskId, now); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Applying flexible push destination. ' + 'destination=${destination.name} taskId=$taskId operationId=$opId ' + 'occurredAt=${now.toIso8601String()} taskCount=${input.tasks.length} ' + 'windowStart=${input.window.start.toIso8601String()} ' + 'windowEnd=${input.window.end.toIso8601String()}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { + logger.finest(() => 'Flexible push destination input dump. ' + 'destination=${destination.name} taskId=$taskId ' + 'tasks=${_taskListSummary(input.tasks)} ' + 'lockedIntervals=${_intervalSummary(input.lockedIntervals)} ' + 'requiredVisibleIntervals=${_intervalSummary(input.requiredVisibleIntervals)} ' + 'existingActivityCount=${existingActivities.length}'); + } if (_hasDuplicateActivity( existingActivities: existingActivities, operationId: opId, taskId: taskId, )) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.warn(() => 'Duplicate flexible push operation ignored. ' + 'destination=${destination.name} taskId=$taskId operationId=$opId'); + } return PushDestinationResult( destination: destination, schedulingResult: SchedulingResult( @@ -147,6 +382,10 @@ class FlexibleTaskActionService { ); } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { + logger.finer(() => 'Dispatching flexible push destination to scheduler. ' + 'destination=${destination.name} taskId=$taskId'); + } final result = switch (destination) { PushDestination.nextAvailableSlot => schedulingEngine.pushFlexibleTaskToNextAvailableSlot( @@ -166,19 +405,50 @@ class FlexibleTaskActionService { updatedAt: now, ), }; + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible push destination scheduling finished. ' + 'destination=${destination.name} taskId=$taskId ' + 'outcome=${result.outcomeCode.name} changeCount=${result.changes.length} ' + 'noticeCount=${result.notices.length}'); + } + if (_isHandledPushIssue(result.outcomeCode) && + logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.warn(() => 'Handled flexible push issue. ' + 'destination=${destination.name} taskId=$taskId ' + 'outcome=${result.outcomeCode.name} ' + 'notices=${_noticeSummary(result.notices)}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { + logger.fine(() => 'Flexible push result details. ' + 'destination=${destination.name} taskId=$taskId ' + 'changes=${_changeSummary(result.changes)} ' + 'notices=${_noticeSummary(result.notices)}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { + logger.finest(() => 'Flexible push destination result dump. ' + 'destination=${destination.name} taskId=$taskId ' + 'tasks=${_taskListSummary(result.tasks)}'); + } + + final activities = _activitiesForPushDestination( + destination: destination, + input: input, + result: result, + taskId: taskId, + operationId: opId, + occurredAt: now, + existingActivities: existingActivities, + ); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible push destination activities prepared. ' + 'destination=${destination.name} taskId=$taskId ' + 'activityCount=${activities.length}'); + } return PushDestinationResult( destination: destination, schedulingResult: result, - activities: _activitiesForPushDestination( - destination: destination, - input: input, - result: result, - taskId: taskId, - operationId: opId, - occurredAt: now, - existingActivities: existingActivities, - ), + activities: activities, ); } @@ -191,8 +461,22 @@ class FlexibleTaskActionService { required String taskId, DateTime? updatedAt, }) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger + .debug(() => 'Moving flexible task to backlog from push destination. ' + 'taskId=$taskId taskCount=${input.tasks.length} ' + 'hasExplicitUpdatedAt=${updatedAt != null}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { + logger.finest(() => 'Move-to-backlog input dump. ' + 'taskId=$taskId tasks=${_taskListSummary(input.tasks)}'); + } final task = _taskById(input.tasks, taskId); if (task == null) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.warn(() => 'Handled move-to-backlog issue: task not found. ' + 'taskId=$taskId'); + } return SchedulingResult( tasks: input.tasks, operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog, @@ -209,6 +493,11 @@ class FlexibleTaskActionService { } if (!task.isFlexible || task.status != TaskStatus.planned) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.warn(() => 'Handled move-to-backlog issue: invalid task state. ' + 'taskId=${task.id} taskType=${task.type.name} ' + 'taskStatus=${task.status.name}'); + } return SchedulingResult( tasks: input.tasks, operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog, @@ -228,6 +517,12 @@ class FlexibleTaskActionService { task, updatedAt: updatedAt, ); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible task moved to backlog. ' + 'taskId=${task.id} previousStart=${task.scheduledStart?.toIso8601String()} ' + 'previousEnd=${task.scheduledEnd?.toIso8601String()} ' + 'updatedAt=${updatedAt?.toIso8601String()}'); + } return SchedulingResult( tasks: List.unmodifiable( @@ -267,3 +562,122 @@ class FlexibleTaskActionService { ); } } + +/// Returns whether [level] should be emitted for [minimumLevel]. +bool _shouldWrite( + FlexibleTaskActionLogLevel level, + FlexibleTaskActionLogLevel minimumLevel, +) { + return _severity(level) >= _severity(minimumLevel); +} + +/// Converts [level] to a comparable severity value. +int _severity(FlexibleTaskActionLogLevel level) { + return switch (level) { + FlexibleTaskActionLogLevel.finest => 0, + FlexibleTaskActionLogLevel.finer => 1, + FlexibleTaskActionLogLevel.fine => 2, + FlexibleTaskActionLogLevel.debug => 3, + FlexibleTaskActionLogLevel.info => 4, + FlexibleTaskActionLogLevel.warn => 5, + FlexibleTaskActionLogLevel.error => 6, + }; +} + +/// Returns whether caller capture should run for [level]. +bool _shouldCaptureCaller({ + required FlexibleTaskActionLogLevel level, + required FlexibleTaskActionLogLevel minimumLevel, +}) { + if (minimumLevel == FlexibleTaskActionLogLevel.finest) { + return true; + } + final capturesWarningContext = level == FlexibleTaskActionLogLevel.warn || + level == FlexibleTaskActionLogLevel.error; + return capturesWarningContext && + _severity(minimumLevel) <= _severity(FlexibleTaskActionLogLevel.fine); +} + +/// Resolves a plain or lazy log [message]. +String _resolveLogMessage(Object? message) { + final resolved = + message is FlexibleTaskActionLogMessage ? message() : message; + return resolved?.toString().trim() ?? ''; +} + +/// Captures the first stack frame outside logger internals. +String _callerFrame() { + for (final line in StackTrace.current.toString().split('\n')) { + final trimmed = line.trim(); + if (trimmed.isEmpty || + trimmed.contains('_callerFrame') || + trimmed.contains('FlexibleTaskActionLogger.')) { + continue; + } + return trimmed.replaceAll('\n', r'\n'); + } + return 'unknown'; +} + +/// Returns whether [outcomeCode] represents a handled push issue. +bool _isHandledPushIssue(SchedulingOutcomeCode outcomeCode) { + return switch (outcomeCode) { + SchedulingOutcomeCode.success => false, + SchedulingOutcomeCode.noOp || + SchedulingOutcomeCode.notFound || + SchedulingOutcomeCode.invalidState || + SchedulingOutcomeCode.noSlot || + SchedulingOutcomeCode.overflow || + SchedulingOutcomeCode.conflict => + true, + }; +} + +/// Builds a compact summary for [notices]. +String _noticeSummary(List notices) { + if (notices.isEmpty) { + return 'none'; + } + return notices + .map((notice) => + '${notice.type.name}:${notice.issueCode?.name ?? notice.movementCode?.name ?? 'none'}') + .join(','); +} + +/// Builds a compact summary for [changes]. +String _changeSummary(List changes) { + if (changes.isEmpty) { + return 'none'; + } + return changes + .map((change) => + '${change.taskId}:${change.previousStart?.toIso8601String()}->${change.nextStart?.toIso8601String()}') + .join(','); +} + +/// Builds a compact dump for [tasks]. +String _taskListSummary(List tasks) { + if (tasks.isEmpty) { + return 'none'; + } + return tasks.map(_taskSummary).join(','); +} + +/// Builds a compact dump for [task]. +String _taskSummary(Task task) { + return '${task.id}{type=${task.type.name},status=${task.status.name},' + 'project=${task.projectId},duration=${task.durationMinutes},' + 'start=${task.scheduledStart?.toIso8601String()},' + 'end=${task.scheduledEnd?.toIso8601String()}}'; +} + +/// Builds a compact dump for [intervals]. +String _intervalSummary(List intervals) { + if (intervals.isEmpty) { + return 'none'; + } + return intervals + .map((interval) => + '${interval.start.toIso8601String()}-${interval.end.toIso8601String()}') + .join(','); +} From 507bee6ad145c22caf25cd04f395c6e1b2f04ccd Mon Sep 17 00:00:00 2001 From: Ashley Venn Date: Thu, 2 Jul 2026 19:05:17 -0700 Subject: [PATCH 3/3] refactor: centralize scheduler logging --- .../app/runtime/focus_flow_file_logger.dart | 161 ++---- .../runtime/focus_flow_runtime_config.dart | 45 +- .../test/app/runtime_config_test.dart | 3 + .../scheduler_core/lib/scheduler_core.dart | 1 + .../lib/src/logging/focus_flow_logger.dart | 390 ++++++++++++++ .../lib/src/scheduling/task_actions.dart | 1 + .../flexible_task_action_service.dart | 489 +++--------------- .../test/focus_flow_logger_test.dart | 118 +++++ 8 files changed, 652 insertions(+), 556 deletions(-) create mode 100644 packages/scheduler_core/lib/src/logging/focus_flow_logger.dart create mode 100644 packages/scheduler_core/test/focus_flow_logger_test.dart diff --git a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart index 74e2b1c..94ac7ba 100644 --- a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart +++ b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart @@ -6,10 +6,9 @@ library; import 'dart:io'; -import 'focus_flow_runtime_config.dart'; +import 'package:scheduler_core/scheduler_core.dart' as scheduler_core; -/// Lazily creates a log message only after the target level is enabled. -typedef FocusFlowLogMessage = Object? Function(); +import 'focus_flow_runtime_config.dart'; /// Minimal append-only file logger for FocusFlow runtime diagnostics. final class FocusFlowFileLogger { @@ -17,15 +16,21 @@ final class FocusFlowFileLogger { FocusFlowFileLogger._({ required this.minimumLevel, required this.logFilePath, - required this._now, + required this._logger, }); + /// Additional caller-frame marker for this app wrapper. + static const List _callerFrameIgnores = [ + 'focus_flow_file_logger.dart', + ]; + /// Creates a disabled logger that drops every message. factory FocusFlowFileLogger.disabled({DateTime Function()? now}) { + scheduler_core.logger.disable(now: now); return FocusFlowFileLogger._( minimumLevel: null, logFilePath: null, - now: now ?? _utcNow, + logger: scheduler_core.FocusFlowLogger.disabled(now: now), ); } @@ -44,10 +49,24 @@ final class FocusFlowFileLogger { try { final directory = Directory(location); await directory.create(recursive: true); + final logFilePath = _joinPath(directory.path, fileName); + final resolvedNow = now ?? _utcNow; + final sink = _fileSink(logFilePath); + scheduler_core.logger.configure( + minimumLevel: level, + sink: sink, + now: resolvedNow, + callerFrameIgnores: _callerFrameIgnores, + ); return FocusFlowFileLogger._( minimumLevel: level, - logFilePath: _joinPath(directory.path, fileName), - now: now ?? _utcNow, + logFilePath: logFilePath, + logger: scheduler_core.FocusFlowLogger( + minimumLevel: level, + sink: sink, + now: resolvedNow, + callerFrameIgnores: _callerFrameIgnores, + ), ); } on Object { return FocusFlowFileLogger.disabled(now: now); @@ -60,41 +79,41 @@ final class FocusFlowFileLogger { /// Concrete file path receiving appended log lines. final String? logFilePath; - /// Clock boundary used for log timestamps. - final DateTime Function() _now; + /// Shared logger implementation that owns gating and caller capture. + final scheduler_core.FocusFlowLogger _logger; /// Whether this logger currently writes to a file. - bool get isEnabled => minimumLevel != null && logFilePath != null; + bool get isEnabled => logFilePath != null && _logger.isEnabled; /// Writes a finest-level [message] when enabled for finest logging. Future finest(Object? message) { - return write(FocusFlowLogLevel.finest, message); + return write(scheduler_core.FocusFlowLogLevel.finest, message); } /// Writes a finer-level [message] when enabled for finer logging. Future finer(Object? message) { - return write(FocusFlowLogLevel.finer, message); + return write(scheduler_core.FocusFlowLogLevel.finer, message); } /// Writes a fine-level [message] when enabled for fine logging. Future fine(Object? message) { - return write(FocusFlowLogLevel.fine, message); + return write(scheduler_core.FocusFlowLogLevel.fine, message); } /// Writes a debug-level [message] when enabled for debug or lower. Future debug(Object? message) { - return write(FocusFlowLogLevel.debug, message); + return write(scheduler_core.FocusFlowLogLevel.debug, message); } /// Writes an info-level [message] when enabled for info or lower. Future info(Object? message) { - return write(FocusFlowLogLevel.info, message); + return write(scheduler_core.FocusFlowLogLevel.info, message); } /// Writes a warning-level [message] when enabled for warning or lower. Future warn(Object? message, {Object? error, StackTrace? stackTrace}) { return write( - FocusFlowLogLevel.warn, + scheduler_core.FocusFlowLogLevel.warn, message, error: error, stackTrace: stackTrace, @@ -104,7 +123,7 @@ final class FocusFlowFileLogger { /// Writes an error-level [message] when file logging is enabled. Future error(Object? message, {Object? error, StackTrace? stackTrace}) { return write( - FocusFlowLogLevel.error, + scheduler_core.FocusFlowLogLevel.error, message, error: error, stackTrace: stackTrace, @@ -113,110 +132,28 @@ final class FocusFlowFileLogger { /// Writes [message] at [level] when it passes the configured threshold. Future write( - FocusFlowLogLevel level, + scheduler_core.FocusFlowLogLevel level, Object? message, { Object? error, StackTrace? stackTrace, - }) async { - final path = logFilePath; - final configuredLevel = minimumLevel; - if (path == null || - configuredLevel == null || - !_shouldWrite(level, configuredLevel)) { - return; - } - - final caller = - _shouldCaptureCaller(level: level, minimumLevel: configuredLevel) - ? _callerFrame() - : null; - final resolvedMessage = _resolveMessage(message); - final buffer = StringBuffer() - ..write(_now().toUtc().toIso8601String()) - ..write(' ') - ..write(level.name.toUpperCase()) - ..write(' '); - if (caller != null) { - buffer - ..write('caller=') - ..write(caller) - ..write(' '); - } - buffer.write(resolvedMessage); - if (error != null) { - buffer - ..write(' | error=') - ..write(error); - } - if (stackTrace != null) { - buffer - ..write(' | stackTrace=') - ..write(stackTrace.toString().replaceAll('\n', r'\n')); - } - buffer.writeln(); - - await File( - path, - ).writeAsString(buffer.toString(), mode: FileMode.append, flush: true); + }) { + _logger.write(level, message, error: error, stackTrace: stackTrace); + return Future.value(); } } -/// Returns whether [level] should be written for [minimumLevel]. -bool _shouldWrite(FocusFlowLogLevel level, FocusFlowLogLevel minimumLevel) { - return _severity(level) >= _severity(minimumLevel); -} - -/// Converts [level] to an ordered severity value. -int _severity(FocusFlowLogLevel level) { - return switch (level) { - FocusFlowLogLevel.finest => 0, - FocusFlowLogLevel.finer => 1, - FocusFlowLogLevel.fine => 2, - FocusFlowLogLevel.debug => 3, - FocusFlowLogLevel.info => 4, - FocusFlowLogLevel.warn => 5, - FocusFlowLogLevel.error => 6, - }; -} - -/// Whether automatic callsite capture should run for [level]. -bool _shouldCaptureCaller({ - required FocusFlowLogLevel level, - required FocusFlowLogLevel minimumLevel, -}) { - if (minimumLevel == FocusFlowLogLevel.finest) { - return true; - } - final capturesWarningContext = - level == FocusFlowLogLevel.warn || level == FocusFlowLogLevel.error; - return capturesWarningContext && - _severity(minimumLevel) <= _severity(FocusFlowLogLevel.fine); -} - -/// Resolves a plain or lazy message after level gating has passed. -String _resolveMessage(Object? message) { - final resolved = message is FocusFlowLogMessage ? message() : message; - return resolved?.toString().trim() ?? ''; -} - -/// Captures the first stack frame outside the logger implementation. -String _callerFrame() { - for (final line in StackTrace.current.toString().split('\n')) { - final trimmed = line.trim(); - if (trimmed.isEmpty || trimmed.contains('focus_flow_file_logger.dart')) { - continue; - } - return _sanitizeForSingleLine(trimmed); - } - return 'unknown'; -} - /// Returns the current UTC timestamp. DateTime _utcNow() => DateTime.now().toUtc(); -/// Keeps diagnostic text on one line for append-only file logs. -String _sanitizeForSingleLine(String value) { - return value.replaceAll('\n', r'\n'); +/// Creates a file sink that appends formatted log entries. +scheduler_core.FocusFlowLogSink _fileSink(String path) { + return (entry) { + File(path).writeAsStringSync( + '${entry.toSingleLine()}\n', + mode: FileMode.append, + flush: true, + ); + }; } /// Joins [base] and [child] with the platform path separator. diff --git a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart index 0013ea8..4c937ab 100644 --- a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart +++ b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart @@ -7,6 +7,10 @@ library; import 'dart:convert'; import 'dart:io'; +import 'package:scheduler_core/scheduler_core.dart' show FocusFlowLogLevel; + +export 'package:scheduler_core/scheduler_core.dart' show FocusFlowLogLevel; + /// File-backed runtime configuration for optional developer diagnostics. final class FocusFlowRuntimeConfig { /// Creates a runtime configuration with optional logging controls. @@ -67,47 +71,6 @@ final class FocusFlowRuntimeConfig { bool get enablesFileLogging => logLevel != null && logFileLocation != null; } -/// Supported FocusFlow file logging levels, ordered from most to least verbose. -enum FocusFlowLogLevel { - /// Logs every message with automatic callsite detail. - finest, - - /// Logs intra-method minor actions and small state changes. - finer, - - /// Logs secondary details, possible issues, and rich warning/error context. - fine, - - /// Logs debug, info, warning, and error messages. - debug, - - /// Logs normal operational information, warnings, and errors. - info, - - /// Logs warnings and errors. - warn, - - /// Logs only errors. - error; - - /// Parses [value] into a supported logging level. - static FocusFlowLogLevel? tryParse(String? value) { - final normalized = value?.trim().toLowerCase(); - if (normalized == null || normalized.isEmpty) { - return null; - } - if (normalized == 'trace') { - return finest; - } - for (final level in FocusFlowLogLevel.values) { - if (level.name == normalized) { - return level; - } - } - return null; - } -} - /// Reads [value] as a non-empty string when present. String? _optionalString(Object? value) { if (value is! String) { diff --git a/apps/focus_flow_flutter/test/app/runtime_config_test.dart b/apps/focus_flow_flutter/test/app/runtime_config_test.dart index 7cc5251..fbb02d2 100644 --- a/apps/focus_flow_flutter/test/app/runtime_config_test.dart +++ b/apps/focus_flow_flutter/test/app/runtime_config_test.dart @@ -10,9 +10,12 @@ import 'dart:io'; import 'package:flutter_test/flutter_test.dart'; import 'package:focus_flow_flutter/app/runtime/focus_flow_file_logger.dart'; import 'package:focus_flow_flutter/app/runtime/focus_flow_runtime_config.dart'; +import 'package:scheduler_core/scheduler_core.dart' as scheduler_core; /// Runs runtime config tests. void main() { + tearDown(scheduler_core.logger.disable); + group('FocusFlowRuntimeConfig', () { test('missing config file leaves optional settings unset', () async { final directory = await Directory.systemTemp.createTemp( diff --git a/packages/scheduler_core/lib/scheduler_core.dart b/packages/scheduler_core/lib/scheduler_core.dart index 8736dd5..c8eab85 100644 --- a/packages/scheduler_core/lib/scheduler_core.dart +++ b/packages/scheduler_core/lib/scheduler_core.dart @@ -33,6 +33,7 @@ export 'src/persistence/document_mapping.dart'; export 'src/persistence/document_migration.dart'; export 'src/scheduling/free_slots.dart'; export 'src/domain/locked_time.dart'; +export 'src/logging/focus_flow_logger.dart'; export 'src/domain/occupancy_policy.dart'; export 'src/persistence/persistence_contract.dart'; export 'src/domain/project_statistics.dart'; diff --git a/packages/scheduler_core/lib/src/logging/focus_flow_logger.dart b/packages/scheduler_core/lib/src/logging/focus_flow_logger.dart new file mode 100644 index 0000000..efee2f2 --- /dev/null +++ b/packages/scheduler_core/lib/src/logging/focus_flow_logger.dart @@ -0,0 +1,390 @@ +// SPDX-FileCopyrightText: 2026 FocusFlow contributors +// SPDX-License-Identifier: AGPL-3.0-only + +/// Provides shared FocusFlow logging primitives for scheduler code. +library; + +/// Lazily creates a log message after level gating passes. +typedef FocusFlowLogMessage = Object? Function(); + +/// Receives one enabled log entry. +typedef FocusFlowLogSink = void Function(FocusFlowLogEntry entry); + +/// Shared process logger used by scheduler core code. +final FocusFlowLogger logger = FocusFlowLogger.disabled(); + +/// Supported FocusFlow logging levels, ordered from most to least verbose. +enum FocusFlowLogLevel { + /// Extremely granular diagnostics, data dumps, and caller details for every log. + finest, + + /// Intra-method minor actions and small state changes. + finer, + + /// Secondary details, possible issues, and rich warning/error context. + fine, + + /// High-level debug flow and useful state values. + debug, + + /// Very high-level operational checkpoints. + info, + + /// Handled issues where the app recovered and kept going. + warn, + + /// Invalid or unsafe states that need review. + error; + + /// Parses [value] into a supported logging level. + static FocusFlowLogLevel? tryParse(String? value) { + final normalized = value?.trim().toLowerCase(); + if (normalized == null || normalized.isEmpty) { + return null; + } + if (normalized == 'trace') { + return finest; + } + for (final level in FocusFlowLogLevel.values) { + if (level.name == normalized) { + return level; + } + } + return null; + } + + /// Ordered severity used for threshold comparisons. + int get severity { + return switch (this) { + FocusFlowLogLevel.finest => 0, + FocusFlowLogLevel.finer => 1, + FocusFlowLogLevel.fine => 2, + FocusFlowLogLevel.debug => 3, + FocusFlowLogLevel.info => 4, + FocusFlowLogLevel.warn => 5, + FocusFlowLogLevel.error => 6, + }; + } + + /// Whether this level should write when [minimumLevel] is configured. + bool writesAt(FocusFlowLogLevel minimumLevel) { + return severity >= minimumLevel.severity; + } +} + +/// Structured log entry produced after level gating has passed. +final class FocusFlowLogEntry { + /// Creates a structured log entry. + const FocusFlowLogEntry({ + required this.timestamp, + required this.level, + required this.message, + this.caller, + this.error, + this.stackTrace, + }); + + /// UTC timestamp for the log event. + final DateTime timestamp; + + /// Severity level for the log event. + final FocusFlowLogLevel level; + + /// Resolved log message. + final String message; + + /// Optional caller frame captured by [FocusFlowLogger]. + final String? caller; + + /// Optional error object attached to the entry. + final Object? error; + + /// Optional stack trace attached to the entry. + final StackTrace? stackTrace; + + /// Formats this entry as one append-only log line. + String toSingleLine() { + final buffer = StringBuffer() + ..write(timestamp.toUtc().toIso8601String()) + ..write(' ') + ..write(level.name.toUpperCase()) + ..write(' '); + final currentCaller = caller; + if (currentCaller != null) { + buffer + ..write('caller=') + ..write(_sanitizeForSingleLine(currentCaller)) + ..write(' '); + } + buffer.write(_sanitizeForSingleLine(message)); + final currentError = error; + if (currentError != null) { + buffer + ..write(' | error=') + ..write(_sanitizeForSingleLine(currentError.toString())); + } + final currentStackTrace = stackTrace; + if (currentStackTrace != null) { + buffer + ..write(' | stackTrace=') + ..write(_sanitizeForSingleLine(currentStackTrace.toString())); + } + return buffer.toString(); + } +} + +/// Logger that handles level gating, lazy messages, and caller capture. +final class FocusFlowLogger { + /// Creates a logger with optional runtime configuration. + FocusFlowLogger({ + FocusFlowLogLevel? minimumLevel, + FocusFlowLogSink? sink, + DateTime Function()? now, + Iterable callerFrameIgnores = const [], + }) : _minimumLevel = minimumLevel, + _sink = sink, + _now = now ?? _utcNow, + _callerFrameIgnores = _normalizedCallerFrameIgnores( + callerFrameIgnores, + ); + + /// Creates a logger that drops every message. + factory FocusFlowLogger.disabled({DateTime Function()? now}) { + return FocusFlowLogger(now: now); + } + + /// Minimum level currently configured for this logger. + FocusFlowLogLevel? _minimumLevel; + + /// Destination receiving enabled entries. + FocusFlowLogSink? _sink; + + /// Clock used to timestamp log entries. + DateTime Function() _now; + + /// Stack-frame markers ignored when capturing the caller. + List _callerFrameIgnores; + + /// Minimum level that will be written, or null when disabled. + FocusFlowLogLevel? get minimumLevel => _minimumLevel; + + /// Whether this logger has enough configuration to write entries. + bool get isEnabled => _minimumLevel != null && _sink != null; + + /// Replaces this logger's runtime configuration. + void configure({ + required FocusFlowLogLevel minimumLevel, + required FocusFlowLogSink sink, + DateTime Function()? now, + Iterable callerFrameIgnores = const [], + }) { + _minimumLevel = minimumLevel; + _sink = sink; + _now = now ?? _utcNow; + _callerFrameIgnores = _normalizedCallerFrameIgnores(callerFrameIgnores); + } + + /// Disables this logger and drops subsequent messages. + void disable({DateTime Function()? now}) { + _minimumLevel = null; + _sink = null; + _now = now ?? _utcNow; + _callerFrameIgnores = _normalizedCallerFrameIgnores(const []); + } + + /// Whether [level] would currently be written. + bool wouldWrite(FocusFlowLogLevel level) { + final configured = _minimumLevel; + return configured != null && _sink != null && level.writesAt(configured); + } + + /// Writes [message] at `finest` when enabled. + void finest( + Object? message, { + Object? error, + StackTrace? stackTrace, + }) { + write( + FocusFlowLogLevel.finest, + message, + error: error, + stackTrace: stackTrace, + ); + } + + /// Writes [message] at `finer` when enabled. + void finer( + Object? message, { + Object? error, + StackTrace? stackTrace, + }) { + write( + FocusFlowLogLevel.finer, + message, + error: error, + stackTrace: stackTrace, + ); + } + + /// Writes [message] at `fine` when enabled. + void fine( + Object? message, { + Object? error, + StackTrace? stackTrace, + }) { + write( + FocusFlowLogLevel.fine, + message, + error: error, + stackTrace: stackTrace, + ); + } + + /// Writes [message] at `debug` when enabled. + void debug( + Object? message, { + Object? error, + StackTrace? stackTrace, + }) { + write( + FocusFlowLogLevel.debug, + message, + error: error, + stackTrace: stackTrace, + ); + } + + /// Writes [message] at `info` when enabled. + void info( + Object? message, { + Object? error, + StackTrace? stackTrace, + }) { + write( + FocusFlowLogLevel.info, + message, + error: error, + stackTrace: stackTrace, + ); + } + + /// Writes [message] at `warn` when enabled. + void warn( + Object? message, { + Object? error, + StackTrace? stackTrace, + }) { + write( + FocusFlowLogLevel.warn, + message, + error: error, + stackTrace: stackTrace, + ); + } + + /// Writes [message] at `error` when enabled. + void error( + Object? message, { + Object? error, + StackTrace? stackTrace, + }) { + write( + FocusFlowLogLevel.error, + message, + error: error, + stackTrace: stackTrace, + ); + } + + /// Writes [message] at [level] when it passes the configured threshold. + void write( + FocusFlowLogLevel level, + Object? message, { + Object? error, + StackTrace? stackTrace, + }) { + final configured = _minimumLevel; + final currentSink = _sink; + if (configured == null || + currentSink == null || + !level.writesAt(configured)) { + return; + } + + final entry = FocusFlowLogEntry( + timestamp: _now().toUtc(), + level: level, + message: _resolveMessage(message), + caller: _shouldCaptureCaller(level: level, minimumLevel: configured) + ? _callerFrame() + : null, + error: error, + stackTrace: stackTrace, + ); + + try { + currentSink(entry); + } on Object { + return; + } + } + + /// Captures the first stack frame outside known logging internals. + String _callerFrame() { + for (final line in StackTrace.current.toString().split('\n')) { + final trimmed = line.trim(); + final shouldIgnore = _callerFrameIgnores.any(trimmed.contains); + if (trimmed.isEmpty || shouldIgnore) { + continue; + } + return _sanitizeForSingleLine(trimmed); + } + return 'unknown'; + } +} + +/// Returns whether caller capture should run for [level]. +bool _shouldCaptureCaller({ + required FocusFlowLogLevel level, + required FocusFlowLogLevel minimumLevel, +}) { + if (minimumLevel == FocusFlowLogLevel.finest) { + return true; + } + final capturesWarningContext = + level == FocusFlowLogLevel.warn || level == FocusFlowLogLevel.error; + return capturesWarningContext && + minimumLevel.severity <= FocusFlowLogLevel.fine.severity; +} + +/// Resolves a plain or lazy [message] after level gating passes. +String _resolveMessage(Object? message) { + try { + final resolved = message is FocusFlowLogMessage ? message() : message; + return resolved?.toString().trim() ?? ''; + } on Object catch (error) { + return 'Log message evaluation failed: $error'; + } +} + +/// Returns the current UTC timestamp. +DateTime _utcNow() => DateTime.now().toUtc(); + +/// Builds the complete set of caller frame markers to skip. +List _normalizedCallerFrameIgnores( + Iterable callerFrameIgnores, +) { + final ignores = {'focus_flow_logger.dart'}; + for (final ignore in callerFrameIgnores) { + final trimmed = ignore.trim(); + if (trimmed.isNotEmpty) { + ignores.add(trimmed); + } + } + return List.unmodifiable(ignores); +} + +/// Keeps diagnostic text on one physical log line. +String _sanitizeForSingleLine(String value) { + return value.replaceAll('\n', r'\n'); +} diff --git a/packages/scheduler_core/lib/src/scheduling/task_actions.dart b/packages/scheduler_core/lib/src/scheduling/task_actions.dart index d06a096..75340b9 100644 --- a/packages/scheduler_core/lib/src/scheduling/task_actions.dart +++ b/packages/scheduler_core/lib/src/scheduling/task_actions.dart @@ -13,6 +13,7 @@ library; import '../domain/models.dart'; import '../domain/occupancy_policy.dart'; +import '../logging/focus_flow_logger.dart'; import 'scheduling_engine.dart'; import 'task_lifecycle.dart'; import '../domain/time_contracts.dart'; diff --git a/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart b/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart index c0715bb..db13f9d 100644 --- a/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart @@ -3,145 +3,6 @@ part of '../../task_actions.dart'; -/// Lazily creates a flexible-task action log message after level gating passes. -typedef FlexibleTaskActionLogMessage = Object? Function(); - -/// Receives a flexible-task action log entry. -typedef FlexibleTaskActionLogSink = void Function( - FlexibleTaskActionLogEntry entry, -); - -/// Log levels used by [FlexibleTaskActionService]. -enum FlexibleTaskActionLogLevel { - /// Extremely granular data dumps with automatic caller information. - finest, - - /// Intra-method minor actions and small state changes. - finer, - - /// Secondary details, possible issues, and rich warning/error context. - fine, - - /// High-level debug flow and state values. - debug, - - /// Very high-level healthy lifecycle checkpoints. - info, - - /// Handled issues where the service recovered and returned a safe result. - warn, - - /// Invalid or unsafe states that should be reviewed. - error, -} - -/// Structured log entry emitted by [FlexibleTaskActionLogger]. -class FlexibleTaskActionLogEntry { - /// Creates a log entry for one flexible-task action event. - const FlexibleTaskActionLogEntry({ - required this.level, - required this.message, - this.caller, - }); - - /// Severity level for this entry. - final FlexibleTaskActionLogLevel level; - - /// Already-resolved message text. - final String message; - - /// Optional source frame captured according to the configured level. - final String? caller; -} - -/// Optional logger used by [FlexibleTaskActionService]. -/// -/// The default constructor is disabled, so existing callers pay only a cheap -/// null/level check. Expensive message construction should be guarded with -/// [isEnabled] and passed as a [FlexibleTaskActionLogMessage]. -class FlexibleTaskActionLogger { - /// Creates a logger that drops every message. - const FlexibleTaskActionLogger.disabled() - : minimumLevel = null, - sink = null; - - /// Creates a logger that sends enabled entries to [sink]. - const FlexibleTaskActionLogger({ - required this.minimumLevel, - required this.sink, - }); - - /// Minimum level to emit, or null when disabled. - final FlexibleTaskActionLogLevel? minimumLevel; - - /// Destination for enabled log entries. - final FlexibleTaskActionLogSink? sink; - - /// Whether [level] would be emitted by this logger. - bool isEnabled(FlexibleTaskActionLogLevel level) { - final configured = minimumLevel; - return configured != null && - sink != null && - _shouldWrite(level, configured); - } - - /// Logs [message] at `finest` when enabled. - void finest(Object? message) { - write(FlexibleTaskActionLogLevel.finest, message); - } - - /// Logs [message] at `finer` when enabled. - void finer(Object? message) { - write(FlexibleTaskActionLogLevel.finer, message); - } - - /// Logs [message] at `fine` when enabled. - void fine(Object? message) { - write(FlexibleTaskActionLogLevel.fine, message); - } - - /// Logs [message] at `debug` when enabled. - void debug(Object? message) { - write(FlexibleTaskActionLogLevel.debug, message); - } - - /// Logs [message] at `info` when enabled. - void info(Object? message) { - write(FlexibleTaskActionLogLevel.info, message); - } - - /// Logs [message] at `warn` when enabled. - void warn(Object? message) { - write(FlexibleTaskActionLogLevel.warn, message); - } - - /// Logs [message] at `error` when enabled. - void error(Object? message) { - write(FlexibleTaskActionLogLevel.error, message); - } - - /// Logs [message] at [level] when enabled. - void write(FlexibleTaskActionLogLevel level, Object? message) { - final configured = minimumLevel; - final currentSink = sink; - if (configured == null || - currentSink == null || - !_shouldWrite(level, configured)) { - return; - } - - currentSink( - FlexibleTaskActionLogEntry( - level: level, - message: _resolveLogMessage(message), - caller: _shouldCaptureCaller(level: level, minimumLevel: configured) - ? _callerFrame() - : null, - ), - ); - } -} - /// Applies low-friction quick actions for flexible task cards. /// /// This service is the adapter between small UI button presses and domain logic. @@ -155,7 +16,6 @@ class FlexibleTaskActionService { this.schedulingEngine = const SchedulingEngine(), this.transitionService = const TaskTransitionService(), this.clock = const SystemClock(), - this.logger = const FlexibleTaskActionLogger.disabled(), }); /// Scheduling dependency used for actions that need timeline changes. @@ -167,9 +27,6 @@ class FlexibleTaskActionService { /// Clock boundary used when an action timestamp is not supplied. final Clock clock; - /// Optional logger for diagnostics around flexible task actions. - final FlexibleTaskActionLogger logger; - /// Apply the first-stage quick action. /// /// Direct actions (`done`, `backlog`) return a changed task. `push` returns the @@ -186,42 +43,35 @@ class FlexibleTaskActionService { Iterable existingActivities = const [], }) { if (!task.isFlexible) { - if (logger.isEnabled(FlexibleTaskActionLogLevel.error)) { - logger.error(() => 'Flexible action rejected for non-flexible task. ' - 'action=${action.name} taskId=${task.id} taskType=${task.type.name} ' - 'taskStatus=${task.status.name}'); - } + logger.error(() => 'Flexible action rejected for non-flexible task. ' + 'action=${action.name} taskId=${task.id} ' + 'taskType=${task.type.name} taskStatus=${task.status.name}'); throw ArgumentError.value( task.type, 'task.type', 'Task must be flexible.'); } - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Applying flexible quick action. ' - 'action=${action.name} taskId=${task.id} ' - 'taskStatus=${task.status.name} hasExplicitUpdatedAt=${updatedAt != null} ' - 'hasOperationId=${operationId != null}'); - } - if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { - logger.finest(() => 'Flexible quick action input dump. ' - 'action=${action.name} task=${_taskSummary(task)} ' - 'updatedAt=${updatedAt?.toIso8601String()} operationId=$operationId ' - 'actualStart=${actualStart?.toIso8601String()} ' - 'actualEnd=${actualEnd?.toIso8601String()} ' - 'lockedIntervals=${_intervalSummary(lockedIntervals)} ' - 'existingActivityCount=${existingActivities.length}'); - } + logger.debug(() => 'Applying flexible quick action. ' + 'action=${action.name} taskId=${task.id} ' + 'taskStatus=${task.status.name} hasExplicitUpdatedAt=${updatedAt != null} ' + 'hasOperationId=${operationId != null}'); + logger.finest(() => 'Flexible quick action input dump. ' + 'action=${action.name} task=$task ' + 'updatedAt=${updatedAt?.toIso8601String()} operationId=$operationId ' + 'actualStart=${actualStart?.toIso8601String()} ' + 'actualEnd=${actualEnd?.toIso8601String()} ' + 'lockedIntervals=$lockedIntervals ' + 'existingActivityCount=${existingActivities.length}'); switch (action) { case FlexibleTaskQuickAction.done: final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId(action.name, task.id, now); - if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { - logger.finer(() => 'Completing flexible task. taskId=${task.id} ' - 'operationId=$opId occurredAt=${now.toIso8601String()} ' - 'hasActualStart=${actualStart != null} hasActualEnd=${actualEnd != null} ' - 'lockedIntervalCount=${lockedIntervals.length}'); - } + logger.finer(() => 'Completing flexible task. taskId=${task.id} ' + 'operationId=$opId occurredAt=${now.toIso8601String()} ' + 'hasActualStart=${actualStart != null} ' + 'hasActualEnd=${actualEnd != null} ' + 'lockedIntervalCount=${lockedIntervals.length}'); final transition = transitionService.apply( task: task, transitionCode: TaskTransitionCode.complete, @@ -237,18 +87,16 @@ class FlexibleTaskActionService { lockedIntervals: lockedIntervals, existingActivities: existingActivities, ); - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Flexible task completion transition finished. ' - 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' - 'nextStatus=${transition.task.status.name} ' - 'activityCount=${transition.activities.length}'); - } - if (transition.outcomeCode != TaskTransitionOutcomeCode.applied && - logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { - logger.fine(() => - 'Possible issue: flexible completion did not apply. ' - 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' - 'previousStatus=${task.status.name} nextStatus=${transition.task.status.name}'); + logger.debug(() => 'Flexible task completion transition finished. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'nextStatus=${transition.task.status.name} ' + 'activityCount=${transition.activities.length}'); + if (transition.outcomeCode != TaskTransitionOutcomeCode.applied) { + logger + .fine(() => 'Possible issue: flexible completion did not apply. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'previousStatus=${task.status.name} ' + 'nextStatus=${transition.task.status.name}'); } return FlexibleTaskActionResult( action: action, @@ -257,15 +105,10 @@ class FlexibleTaskActionService { transitionOutcomeCode: transition.outcomeCode, ); case FlexibleTaskQuickAction.push: - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Flexible push destination menu requested. ' - 'taskId=${task.id} taskStatus=${task.status.name}'); - } - if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { - logger.finer(() => 'Flexible push destinations prepared. ' - 'taskId=${task.id} destinations=' - '${PushDestination.values.map((destination) => destination.name).join(',')}'); - } + logger.debug(() => 'Flexible push destination menu requested. ' + 'taskId=${task.id} taskStatus=${task.status.name}'); + logger.finer(() => 'Flexible push destinations prepared. ' + 'taskId=${task.id} destinationCount=3'); return FlexibleTaskActionResult( action: action, task: task, @@ -279,13 +122,10 @@ class FlexibleTaskActionService { final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId(action.name, task.id, now); - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger - .debug(() => 'Moving flexible task to backlog from quick action. ' - 'taskId=${task.id} operationId=$opId ' - 'occurredAt=${now.toIso8601String()} ' - 'previousStatus=${task.status.name}'); - } + logger.debug(() => 'Moving flexible task to backlog from quick action. ' + 'taskId=${task.id} operationId=$opId ' + 'occurredAt=${now.toIso8601String()} ' + 'previousStatus=${task.status.name}'); final transition = transitionService.apply( task: task, transitionCode: TaskTransitionCode.moveToBacklog, @@ -298,18 +138,16 @@ class FlexibleTaskActionService { occurredAt: now, existingActivities: existingActivities, ); - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Flexible task backlog transition finished. ' - 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' - 'nextStatus=${transition.task.status.name} ' - 'activityCount=${transition.activities.length}'); - } - if (transition.outcomeCode != TaskTransitionOutcomeCode.applied && - logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { + logger.debug(() => 'Flexible task backlog transition finished. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'nextStatus=${transition.task.status.name} ' + 'activityCount=${transition.activities.length}'); + if (transition.outcomeCode != TaskTransitionOutcomeCode.applied) { logger.fine(() => 'Possible issue: move-to-backlog quick action did not apply. ' 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' - 'previousStatus=${task.status.name} nextStatus=${transition.task.status.name}'); + 'previousStatus=${task.status.name} ' + 'nextStatus=${transition.task.status.name}'); } return FlexibleTaskActionResult( action: action, @@ -318,10 +156,8 @@ class FlexibleTaskActionService { transitionOutcomeCode: transition.outcomeCode, ); case FlexibleTaskQuickAction.breakUp: - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Flexible break-up flow requested. ' - 'taskId=${task.id} taskStatus=${task.status.name}'); - } + logger.debug(() => 'Flexible break-up flow requested. ' + 'taskId=${task.id} taskStatus=${task.status.name}'); return FlexibleTaskActionResult( action: action, task: task, @@ -345,30 +181,21 @@ class FlexibleTaskActionService { final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId('push-${destination.name}', taskId, now); - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Applying flexible push destination. ' - 'destination=${destination.name} taskId=$taskId operationId=$opId ' - 'occurredAt=${now.toIso8601String()} taskCount=${input.tasks.length} ' - 'windowStart=${input.window.start.toIso8601String()} ' - 'windowEnd=${input.window.end.toIso8601String()}'); - } - if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { - logger.finest(() => 'Flexible push destination input dump. ' - 'destination=${destination.name} taskId=$taskId ' - 'tasks=${_taskListSummary(input.tasks)} ' - 'lockedIntervals=${_intervalSummary(input.lockedIntervals)} ' - 'requiredVisibleIntervals=${_intervalSummary(input.requiredVisibleIntervals)} ' - 'existingActivityCount=${existingActivities.length}'); - } + logger.debug(() => 'Applying flexible push destination. ' + 'destination=${destination.name} taskId=$taskId operationId=$opId ' + 'occurredAt=${now.toIso8601String()} taskCount=${input.tasks.length} ' + 'windowStart=${input.window.start.toIso8601String()} ' + 'windowEnd=${input.window.end.toIso8601String()}'); + logger.finest(() => 'Flexible push destination input dump. ' + 'destination=${destination.name} taskId=$taskId input=$input ' + 'existingActivityCount=${existingActivities.length}'); if (_hasDuplicateActivity( existingActivities: existingActivities, operationId: opId, taskId: taskId, )) { - if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { - logger.warn(() => 'Duplicate flexible push operation ignored. ' - 'destination=${destination.name} taskId=$taskId operationId=$opId'); - } + logger.warn(() => 'Duplicate flexible push operation ignored. ' + 'destination=${destination.name} taskId=$taskId operationId=$opId'); return PushDestinationResult( destination: destination, schedulingResult: SchedulingResult( @@ -382,10 +209,8 @@ class FlexibleTaskActionService { ); } - if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { - logger.finer(() => 'Dispatching flexible push destination to scheduler. ' - 'destination=${destination.name} taskId=$taskId'); - } + logger.finer(() => 'Dispatching flexible push destination to scheduler. ' + 'destination=${destination.name} taskId=$taskId'); final result = switch (destination) { PushDestination.nextAvailableSlot => schedulingEngine.pushFlexibleTaskToNextAvailableSlot( @@ -405,30 +230,20 @@ class FlexibleTaskActionService { updatedAt: now, ), }; - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Flexible push destination scheduling finished. ' - 'destination=${destination.name} taskId=$taskId ' - 'outcome=${result.outcomeCode.name} changeCount=${result.changes.length} ' - 'noticeCount=${result.notices.length}'); - } - if (_isHandledPushIssue(result.outcomeCode) && - logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.debug(() => 'Flexible push destination scheduling finished. ' + 'destination=${destination.name} taskId=$taskId ' + 'outcome=${result.outcomeCode.name} changeCount=${result.changes.length} ' + 'noticeCount=${result.notices.length}'); + if (result.outcomeCode != SchedulingOutcomeCode.success) { logger.warn(() => 'Handled flexible push issue. ' 'destination=${destination.name} taskId=$taskId ' - 'outcome=${result.outcomeCode.name} ' - 'notices=${_noticeSummary(result.notices)}'); - } - if (logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { - logger.fine(() => 'Flexible push result details. ' - 'destination=${destination.name} taskId=$taskId ' - 'changes=${_changeSummary(result.changes)} ' - 'notices=${_noticeSummary(result.notices)}'); - } - if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { - logger.finest(() => 'Flexible push destination result dump. ' - 'destination=${destination.name} taskId=$taskId ' - 'tasks=${_taskListSummary(result.tasks)}'); + 'outcome=${result.outcomeCode.name} notices=${result.notices}'); } + logger.fine(() => 'Flexible push result details. ' + 'destination=${destination.name} taskId=$taskId ' + 'changes=${result.changes} notices=${result.notices}'); + logger.finest(() => 'Flexible push destination result dump. ' + 'destination=${destination.name} taskId=$taskId result=$result'); final activities = _activitiesForPushDestination( destination: destination, @@ -439,11 +254,9 @@ class FlexibleTaskActionService { occurredAt: now, existingActivities: existingActivities, ); - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Flexible push destination activities prepared. ' - 'destination=${destination.name} taskId=$taskId ' - 'activityCount=${activities.length}'); - } + logger.debug(() => 'Flexible push destination activities prepared. ' + 'destination=${destination.name} taskId=$taskId ' + 'activityCount=${activities.length}'); return PushDestinationResult( destination: destination, @@ -461,22 +274,15 @@ class FlexibleTaskActionService { required String taskId, DateTime? updatedAt, }) { - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger - .debug(() => 'Moving flexible task to backlog from push destination. ' - 'taskId=$taskId taskCount=${input.tasks.length} ' - 'hasExplicitUpdatedAt=${updatedAt != null}'); - } - if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { - logger.finest(() => 'Move-to-backlog input dump. ' - 'taskId=$taskId tasks=${_taskListSummary(input.tasks)}'); - } + logger.debug(() => 'Moving flexible task to backlog from push destination. ' + 'taskId=$taskId taskCount=${input.tasks.length} ' + 'hasExplicitUpdatedAt=${updatedAt != null}'); + logger.finest(() => 'Move-to-backlog input dump. ' + 'taskId=$taskId tasks=${input.tasks}'); final task = _taskById(input.tasks, taskId); if (task == null) { - if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { - logger.warn(() => 'Handled move-to-backlog issue: task not found. ' - 'taskId=$taskId'); - } + logger.warn(() => 'Handled move-to-backlog issue: task not found. ' + 'taskId=$taskId'); return SchedulingResult( tasks: input.tasks, operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog, @@ -493,11 +299,9 @@ class FlexibleTaskActionService { } if (!task.isFlexible || task.status != TaskStatus.planned) { - if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { - logger.warn(() => 'Handled move-to-backlog issue: invalid task state. ' - 'taskId=${task.id} taskType=${task.type.name} ' - 'taskStatus=${task.status.name}'); - } + logger.warn(() => 'Handled move-to-backlog issue: invalid task state. ' + 'taskId=${task.id} taskType=${task.type.name} ' + 'taskStatus=${task.status.name}'); return SchedulingResult( tasks: input.tasks, operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog, @@ -517,12 +321,10 @@ class FlexibleTaskActionService { task, updatedAt: updatedAt, ); - if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { - logger.debug(() => 'Flexible task moved to backlog. ' - 'taskId=${task.id} previousStart=${task.scheduledStart?.toIso8601String()} ' - 'previousEnd=${task.scheduledEnd?.toIso8601String()} ' - 'updatedAt=${updatedAt?.toIso8601String()}'); - } + logger.debug(() => 'Flexible task moved to backlog. ' + 'taskId=${task.id} previousStart=${task.scheduledStart?.toIso8601String()} ' + 'previousEnd=${task.scheduledEnd?.toIso8601String()} ' + 'updatedAt=${updatedAt?.toIso8601String()}'); return SchedulingResult( tasks: List.unmodifiable( @@ -562,122 +364,3 @@ class FlexibleTaskActionService { ); } } - -/// Returns whether [level] should be emitted for [minimumLevel]. -bool _shouldWrite( - FlexibleTaskActionLogLevel level, - FlexibleTaskActionLogLevel minimumLevel, -) { - return _severity(level) >= _severity(minimumLevel); -} - -/// Converts [level] to a comparable severity value. -int _severity(FlexibleTaskActionLogLevel level) { - return switch (level) { - FlexibleTaskActionLogLevel.finest => 0, - FlexibleTaskActionLogLevel.finer => 1, - FlexibleTaskActionLogLevel.fine => 2, - FlexibleTaskActionLogLevel.debug => 3, - FlexibleTaskActionLogLevel.info => 4, - FlexibleTaskActionLogLevel.warn => 5, - FlexibleTaskActionLogLevel.error => 6, - }; -} - -/// Returns whether caller capture should run for [level]. -bool _shouldCaptureCaller({ - required FlexibleTaskActionLogLevel level, - required FlexibleTaskActionLogLevel minimumLevel, -}) { - if (minimumLevel == FlexibleTaskActionLogLevel.finest) { - return true; - } - final capturesWarningContext = level == FlexibleTaskActionLogLevel.warn || - level == FlexibleTaskActionLogLevel.error; - return capturesWarningContext && - _severity(minimumLevel) <= _severity(FlexibleTaskActionLogLevel.fine); -} - -/// Resolves a plain or lazy log [message]. -String _resolveLogMessage(Object? message) { - final resolved = - message is FlexibleTaskActionLogMessage ? message() : message; - return resolved?.toString().trim() ?? ''; -} - -/// Captures the first stack frame outside logger internals. -String _callerFrame() { - for (final line in StackTrace.current.toString().split('\n')) { - final trimmed = line.trim(); - if (trimmed.isEmpty || - trimmed.contains('_callerFrame') || - trimmed.contains('FlexibleTaskActionLogger.')) { - continue; - } - return trimmed.replaceAll('\n', r'\n'); - } - return 'unknown'; -} - -/// Returns whether [outcomeCode] represents a handled push issue. -bool _isHandledPushIssue(SchedulingOutcomeCode outcomeCode) { - return switch (outcomeCode) { - SchedulingOutcomeCode.success => false, - SchedulingOutcomeCode.noOp || - SchedulingOutcomeCode.notFound || - SchedulingOutcomeCode.invalidState || - SchedulingOutcomeCode.noSlot || - SchedulingOutcomeCode.overflow || - SchedulingOutcomeCode.conflict => - true, - }; -} - -/// Builds a compact summary for [notices]. -String _noticeSummary(List notices) { - if (notices.isEmpty) { - return 'none'; - } - return notices - .map((notice) => - '${notice.type.name}:${notice.issueCode?.name ?? notice.movementCode?.name ?? 'none'}') - .join(','); -} - -/// Builds a compact summary for [changes]. -String _changeSummary(List changes) { - if (changes.isEmpty) { - return 'none'; - } - return changes - .map((change) => - '${change.taskId}:${change.previousStart?.toIso8601String()}->${change.nextStart?.toIso8601String()}') - .join(','); -} - -/// Builds a compact dump for [tasks]. -String _taskListSummary(List tasks) { - if (tasks.isEmpty) { - return 'none'; - } - return tasks.map(_taskSummary).join(','); -} - -/// Builds a compact dump for [task]. -String _taskSummary(Task task) { - return '${task.id}{type=${task.type.name},status=${task.status.name},' - 'project=${task.projectId},duration=${task.durationMinutes},' - 'start=${task.scheduledStart?.toIso8601String()},' - 'end=${task.scheduledEnd?.toIso8601String()}}'; -} - -/// Builds a compact dump for [intervals]. -String _intervalSummary(List intervals) { - if (intervals.isEmpty) { - return 'none'; - } - return intervals - .map((interval) => - '${interval.start.toIso8601String()}-${interval.end.toIso8601String()}') - .join(','); -} diff --git a/packages/scheduler_core/test/focus_flow_logger_test.dart b/packages/scheduler_core/test/focus_flow_logger_test.dart new file mode 100644 index 0000000..72483bf --- /dev/null +++ b/packages/scheduler_core/test/focus_flow_logger_test.dart @@ -0,0 +1,118 @@ +// SPDX-FileCopyrightText: 2026 FocusFlow contributors +// SPDX-License-Identifier: AGPL-3.0-only + +/// Tests shared FocusFlow logging behavior. +library; + +import 'package:scheduler_core/scheduler_core.dart'; +import 'package:test/test.dart'; + +/// Runs shared logger tests. +void main() { + tearDown(logger.disable); + + group('FocusFlowLogLevel', () { + test('parses every supported level and trace alias', () { + expect(FocusFlowLogLevel.tryParse('finest'), FocusFlowLogLevel.finest); + expect(FocusFlowLogLevel.tryParse('finer'), FocusFlowLogLevel.finer); + expect(FocusFlowLogLevel.tryParse('fine'), FocusFlowLogLevel.fine); + expect(FocusFlowLogLevel.tryParse('debug'), FocusFlowLogLevel.debug); + expect(FocusFlowLogLevel.tryParse('info'), FocusFlowLogLevel.info); + expect(FocusFlowLogLevel.tryParse('warn'), FocusFlowLogLevel.warn); + expect(FocusFlowLogLevel.tryParse('error'), FocusFlowLogLevel.error); + expect(FocusFlowLogLevel.tryParse('trace'), FocusFlowLogLevel.finest); + expect(FocusFlowLogLevel.tryParse('verbose'), isNull); + }); + }); + + group('FocusFlowLogger', () { + test('skips lazy messages below the configured level', () { + final entries = []; + final testLogger = FocusFlowLogger( + minimumLevel: FocusFlowLogLevel.info, + sink: entries.add, + now: () => DateTime.utc(2026, 7, 3, 12), + ); + var evaluated = false; + + testLogger.debug(() { + evaluated = true; + return 'expensive debug state'; + }); + + expect(evaluated, isFalse); + expect(entries, isEmpty); + }); + + test('writes enabled lazy messages with timestamps', () { + final entries = []; + final testLogger = FocusFlowLogger( + minimumLevel: FocusFlowLogLevel.debug, + sink: entries.add, + now: () => DateTime.utc(2026, 7, 3, 12), + ); + + testLogger.debug(() => 'computed debug state'); + + expect(entries.single.level, FocusFlowLogLevel.debug); + expect(entries.single.timestamp, DateTime.utc(2026, 7, 3, 12)); + expect(entries.single.message, 'computed debug state'); + }); + + test('finest captures caller information for every written level', () { + final entries = []; + final testLogger = FocusFlowLogger( + minimumLevel: FocusFlowLogLevel.finest, + sink: entries.add, + now: () => DateTime.utc(2026, 7, 3, 12), + ); + + testLogger.info('high level message'); + + expect(entries.single.caller, contains('focus_flow_logger_test.dart')); + }); + + test('fine captures caller information for warnings and errors', () { + final entries = []; + final testLogger = FocusFlowLogger( + minimumLevel: FocusFlowLogLevel.fine, + sink: entries.add, + now: () => DateTime.utc(2026, 7, 3, 12), + ); + + testLogger.warn('handled warning'); + + expect(entries.single.caller, contains('focus_flow_logger_test.dart')); + }); + + test('info does not capture caller information for warnings', () { + final entries = []; + final testLogger = FocusFlowLogger( + minimumLevel: FocusFlowLogLevel.info, + sink: entries.add, + now: () => DateTime.utc(2026, 7, 3, 12), + ); + + testLogger.warn('minimal warning'); + + expect(entries.single.caller, isNull); + }); + + test('formats errors and stack traces on a single line', () { + final entry = FocusFlowLogEntry( + timestamp: DateTime.utc(2026, 7, 3, 12), + level: FocusFlowLogLevel.error, + message: 'bad state', + caller: '#1 method (file.dart:10:2)', + error: 'boom', + stackTrace: StackTrace.fromString('first\nsecond'), + ); + + expect( + entry.toSingleLine(), + '2026-07-03T12:00:00.000Z ERROR caller=#1 method (file.dart:10:2) ' + r'bad state | error=boom | stackTrace=first\nsecond', + ); + }); + }); +}