From a24b64179a767d33387232366814cff9b7562c3e Mon Sep 17 00:00:00 2001 From: Ashley Venn Date: Fri, 3 Jul 2026 10:21:02 -0700 Subject: [PATCH] feat: add logging to entire project --- analysis_options.yaml | 7 ++ .../lib/app/home/focus_flow_home_state.dart | 26 +++- .../app/persistent_scheduler_composition.dart | 36 ++++-- .../app/runtime/focus_flow_file_logger.dart | 11 +- .../runtime/focus_flow_runtime_config.dart | 30 ++++- .../scheduler_command_controller_impl.dart | 86 +++++++++++-- .../scheduler_read_controller.dart | 24 +++- .../controllers/selected_date_controller.dart | 5 + .../controllers/today_screen_controller.dart | 48 +++++++- apps/focus_flow_flutter/lib/main.dart | 15 ++- .../task_card/task_timeline_card_state.dart | 12 ++ .../widgets/timeline/task_timeline_card.dart | 1 + .../test/persistent_composition_test.dart | 4 +- .../lib/src/encrypted_backup.dart | 1 + .../codec/backup_encryption_codec.dart | 14 ++- .../encrypted_backup_operations.dart | 16 ++- .../encrypted_backup/paths/backup_paths.dart | 2 + packages/scheduler_backup/pubspec.yaml | 1 + .../src/application/application_commands.dart | 1 + .../v1_application_command_use_cases.dart | 91 ++++++++++++++ .../src/application/application_layer.dart | 1 + .../in_memory_application_unit_of_work.dart | 83 ++++++++++++- .../application/application_management.dart | 1 + .../v1_application_management_use_cases.dart | 115 +++++++++++++++++- .../src/application/application_recovery.dart | 1 + .../v1_app_open_recovery_use_cases.dart | 50 +++++++- .../src/persistence/document_migration.dart | 1 + .../v1_document_migration_service.dart | 34 ++++++ .../lib/src/scheduling/child_tasks.dart | 1 + .../services/child_task_break_up_service.dart | 23 ++++ .../child_task_completion_service.dart | 38 ++++++ .../lib/src/scheduling/free_slots.dart | 1 + .../free_slots/free_slot_service.dart | 22 ++++ .../lib/src/scheduling/quick_capture.dart | 1 + .../quick_capture/quick_capture_service.dart | 31 +++++ .../lib/src/scheduling/reminder_policy.dart | 1 + .../services/reminder_policy_service.dart | 30 +++++ .../lib/src/scheduling/scheduling_engine.dart | 1 + .../engine/scheduling_engine.dart | 81 +++++++++++- .../required_task_action_service.dart | 14 +++ .../services/surprise_task_log_service.dart | 34 ++++++ .../lib/src/scheduling/task_lifecycle.dart | 1 + .../services/task_transition_service.dart | 32 ++++- .../lib/src/scheduling/today_state.dart | 1 + .../queries/get_today_state_query.dart | 22 ++++ .../controller/export_controller.dart | 19 +++ .../registry/export_writer_registry.dart | 7 +- .../lib/src/json_csv_writers.dart | 2 + .../lib/src/notification_adapter.dart | 1 + .../adapter/fake_notification_adapter.dart | 12 +- packages/scheduler_notifications/pubspec.yaml | 3 + .../src/desktop_notification_adapter_io.dart | 1 + .../adapter/desktop_notification_adapter.dart | 12 +- .../desktop_notification_backend_factory.dart | 3 + .../fallback/stdout_notification_backend.dart | 7 +- .../platform/linux_notify_send_backend.dart | 17 ++- .../platform/mac_os_notification_backend.dart | 17 ++- .../desktop_notification_adapter_stub.dart | 1 + .../adapter/desktop_notification_adapter.dart | 12 +- .../desktop_notification_backend_factory.dart | 6 +- .../backends/stdout_notification_backend.dart | 7 +- .../pubspec.yaml | 1 + ...n_memory_schedule_snapshot_repository.dart | 12 ++ .../sqlite_application_runtime.dart | 22 +++- .../sqlite_application_unit_of_work.dart | 58 ++++++++- 65 files changed, 1196 insertions(+), 75 deletions(-) diff --git a/analysis_options.yaml b/analysis_options.yaml index 1654f9e..c7fb9a4 100644 --- a/analysis_options.yaml +++ b/analysis_options.yaml @@ -4,6 +4,13 @@ include: package:lints/recommended.yaml analyzer: + exclude: + - .dart_tool/** + - archive/** + - builds/** + - coverage/** + - doc/api/** + - logging_handoff_with_logging/** language: strict-casts: true strict-inference: true diff --git a/apps/focus_flow_flutter/lib/app/home/focus_flow_home_state.dart b/apps/focus_flow_flutter/lib/app/home/focus_flow_home_state.dart index 8b05692..f42e373 100644 --- a/apps/focus_flow_flutter/lib/app/home/focus_flow_home_state.dart +++ b/apps/focus_flow_flutter/lib/app/home/focus_flow_home_state.dart @@ -23,6 +23,7 @@ class _FocusFlowHomeState extends State { @override void initState() { super.initState(); + logger.debug(() => 'FocusFlow home initializing controllers.'); selectedDateController = widget.composition.createSelectedDateController(); controller = widget.composition.createTodayScreenController( selectedDates: selectedDateController, @@ -31,6 +32,7 @@ class _FocusFlowHomeState extends State { refreshReads: controller.load, selectedDate: () => selectedDateController.date, ); + logger.finer(() => 'FocusFlow home triggering initial Today load.'); controller.load(); } @@ -38,6 +40,7 @@ class _FocusFlowHomeState extends State { /// Controllers, listeners, and other disposable collaborators should be cleaned up here to avoid stale callbacks. @override void dispose() { + logger.debug(() => 'FocusFlow home disposing controllers.'); commandController.dispose(); controller.dispose(); selectedDateController.dispose(); @@ -49,8 +52,16 @@ class _FocusFlowHomeState extends State { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. Future _toggleCardCompletion(TimelineCardModel card) async { if (!card.canToggleCompletion) { + logger.finer( + () => 'Timeline completion toggle ignored. cardId=${card.id}', + ); return; } + logger.debug( + () => + 'Timeline completion toggle requested. ' + 'cardId=${card.id} taskType=${card.taskType.name} isCompleted=${card.isCompleted}', + ); if (card.isCompleted) { await commandController.uncompleteTask(taskId: card.id); } else { @@ -63,11 +74,13 @@ class _FocusFlowHomeState extends State { /// Adds a generic filler task from the timeline context menu. Future _addGenericFlexibleTask() async { + logger.debug(() => 'Timeline add generic flexible task requested.'); await commandController.addGenericFlexibleTask(); } /// Pushes [card] to the next available slot after the current clock time. Future _pushCardToNext(TimelineCardModel card) async { + logger.debug(() => 'Timeline push-to-next requested. cardId=${card.id}'); await commandController.pushTaskToNextAvailableSlot( taskId: card.id, expectedUpdatedAt: card.expectedUpdatedAt, @@ -76,6 +89,9 @@ class _FocusFlowHomeState extends State { /// Pushes [card] to tomorrow's first available slot. Future _pushCardToTomorrow(TimelineCardModel card) async { + logger.debug( + () => 'Timeline push-to-tomorrow requested. cardId=${card.id}', + ); await commandController.pushTaskToTomorrow( taskId: card.id, expectedUpdatedAt: card.expectedUpdatedAt, @@ -84,6 +100,7 @@ class _FocusFlowHomeState extends State { /// Pushes [card] back to Backlog. Future _pushCardToBacklog(TimelineCardModel card) async { + logger.debug(() => 'Timeline push-to-backlog requested. cardId=${card.id}'); await commandController.pushTaskToBacklog( taskId: card.id, expectedUpdatedAt: card.expectedUpdatedAt, @@ -92,11 +109,13 @@ class _FocusFlowHomeState extends State { /// Moves the visible planning date backward by one day. void _selectPreviousDate() { + logger.finer(() => 'Previous date action requested.'); selectedDateController.selectPreviousDay(); } /// Moves the visible planning date forward by one day. void _selectNextDate() { + logger.finer(() => 'Next date action requested.'); selectedDateController.selectNextDay(); } @@ -110,9 +129,14 @@ class _FocusFlowHomeState extends State { builder: _buildDatePickerTheme, ); if (picked == null) { + logger.finer(() => 'Date picker dismissed without selection.'); return; } - selectedDateController.selectDate(_civilDateForDateTime(picked)); + final selected = _civilDateForDateTime(picked); + logger.debug( + () => 'Date picker selected date. date=${selected.toIsoString()}', + ); + selectedDateController.selectDate(selected); } /// Builds the widget subtree for this component. diff --git a/apps/focus_flow_flutter/lib/app/persistent_scheduler_composition.dart b/apps/focus_flow_flutter/lib/app/persistent_scheduler_composition.dart index 3fa119c..4a25fd7 100644 --- a/apps/focus_flow_flutter/lib/app/persistent_scheduler_composition.dart +++ b/apps/focus_flow_flutter/lib/app/persistent_scheduler_composition.dart @@ -6,7 +6,10 @@ library; import 'dart:io'; -import 'package:scheduler_core/scheduler_core.dart'; +import 'package:scheduler_core/scheduler_core.dart' hide logger; +import 'package:scheduler_core/scheduler_core.dart' + as scheduler_core + show logger; import 'package:scheduler_persistence_sqlite/sqlite.dart'; import '../controllers/scheduler_command_controller.dart'; @@ -38,27 +41,31 @@ final class PersistentSchedulerComposition implements SchedulerAppComposition { }) async { final resolvedLogger = logger ?? FocusFlowFileLogger.disabled(); final resolvedSqlitePath = sqlitePath ?? sqlitePathFromEnvironment(); - await resolvedLogger.info('Opening SQLite runtime at $resolvedSqlitePath.'); + scheduler_core.logger.info( + () => 'Opening SQLite runtime. sqlitePath=$resolvedSqlitePath', + ); final runtime = await SqliteApplicationRuntime.open( path: resolvedSqlitePath, ); final bootstrap = await runtime.bootstrap(); if (bootstrap.isFailure) { await runtime.close(); - await resolvedLogger.error( - 'SQLite bootstrap failed.', + scheduler_core.logger.error( + () => + 'SQLite bootstrap failed. failureCode=${bootstrap.failure!.code.name}', error: bootstrap.failure!.code.name, ); throw StateError( 'SQLite bootstrap failed: ${bootstrap.failure!.code.name}', ); } - await resolvedLogger.debug('SQLite bootstrap completed.'); + scheduler_core.logger.debug(() => 'SQLite bootstrap completed.'); final resolvedClock = clock ?? const SystemClock(); final date = selectedDate ?? CivilDate.fromDateTime(resolvedClock.now()); final readAt = resolvedClock.now().toUtc(); - await resolvedLogger.info( - 'Persistent scheduler composition opened for ${date.toIsoString()}.', + scheduler_core.logger.info( + () => + 'Persistent scheduler composition opened. date=${date.toIsoString()} readAt=${readAt.toIso8601String()}', ); return PersistentSchedulerComposition._( @@ -140,6 +147,10 @@ final class PersistentSchedulerComposition implements SchedulerAppComposition { /// Creates the controller that owns the visible planning date. @override SelectedDateController createSelectedDateController() { + scheduler_core.logger.finer( + () => + 'Creating selected date controller. date=${initialDate.toIsoString()}', + ); return SelectedDateController(initialDate: initialDate); } @@ -148,6 +159,9 @@ final class PersistentSchedulerComposition implements SchedulerAppComposition { TodayScreenController createTodayScreenController({ required SelectedDateController selectedDates, }) { + scheduler_core.logger.finer( + () => 'Creating today screen controller. date=${date.toIsoString()}', + ); return TodayScreenController( selectedDates: selectedDates, dateLabelFor: dateLabelFor, @@ -169,6 +183,10 @@ final class PersistentSchedulerComposition implements SchedulerAppComposition { required ReadRefresh refreshReads, required SelectedDateReader selectedDate, }) { + scheduler_core.logger.finer( + () => + 'Creating scheduler command controller. operationIdPrefix=ui-command-${readAt.microsecondsSinceEpoch}', + ); return SchedulerCommandController( commands: commandUseCases, contextFor: context, @@ -200,8 +218,8 @@ final class PersistentSchedulerComposition implements SchedulerAppComposition { /// Closes runtime resources and records shutdown diagnostics when enabled. Future _dispose() async { - await logger.debug('Closing SQLite runtime.'); + scheduler_core.logger.debug(() => 'Closing SQLite runtime.'); await runtime.close(); - await logger.info('SQLite runtime closed.'); + scheduler_core.logger.info(() => 'SQLite runtime closed.'); } } 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 94ac7ba..62eaec1 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 @@ -58,6 +58,10 @@ final class FocusFlowFileLogger { now: resolvedNow, callerFrameIgnores: _callerFrameIgnores, ); + scheduler_core.logger.info( + () => + 'FocusFlow file logging configured. level=${level.name} path=$logFilePath', + ); return FocusFlowFileLogger._( minimumLevel: level, logFilePath: logFilePath, @@ -68,7 +72,12 @@ final class FocusFlowFileLogger { callerFrameIgnores: _callerFrameIgnores, ), ); - } on Object { + } on Object catch (error, stackTrace) { + scheduler_core.logger.error( + () => 'FocusFlow file logging setup failed; disabling file logging.', + error: error, + stackTrace: stackTrace, + ); return FocusFlowFileLogger.disabled(now: now); } } 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 4c937ab..bcd05ec 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 @@ -8,6 +8,7 @@ import 'dart:convert'; import 'dart:io'; import 'package:scheduler_core/scheduler_core.dart' show FocusFlowLogLevel; +import 'package:scheduler_core/scheduler_core.dart' show logger; export 'package:scheduler_core/scheduler_core.dart' show FocusFlowLogLevel; @@ -21,15 +22,33 @@ final class FocusFlowRuntimeConfig { final configPath = path ?? configPathFromEnvironment(); final file = File(_expandHome(configPath)); if (!await file.exists()) { + logger.finer(() => 'Runtime config file not found. path=${file.path}'); return const FocusFlowRuntimeConfig(); } try { + logger.debug(() => 'Loading runtime config. path=${file.path}'); final decoded = jsonDecode(await file.readAsString()); if (decoded is Map) { - return fromJson(decoded); + final config = fromJson(decoded); + logger.debug( + () => + 'Runtime config loaded. hasLogLevel=${config.logLevel != null} ' + 'hasLogFileLocation=${config.logFileLocation != null}', + ); + return config; } - } on Object { + logger.warn( + () => + 'Runtime config ignored because decoded JSON was not an object. ' + 'path=${file.path} decodedType=${decoded.runtimeType}', + ); + } on Object catch (error, stackTrace) { + logger.warn( + () => 'Runtime config unreadable; using defaults. path=${file.path}', + error: error, + stackTrace: stackTrace, + ); return const FocusFlowRuntimeConfig(); } @@ -41,9 +60,14 @@ final class FocusFlowRuntimeConfig { const configured = String.fromEnvironment('FOCUS_FLOW_CONFIG_PATH'); final trimmed = configured.trim(); if (trimmed.isNotEmpty) { + logger.finer( + () => 'Runtime config path resolved from environment. path=$trimmed', + ); return trimmed; } - return defaultConfigPath(); + final path = defaultConfigPath(); + logger.finer(() => 'Runtime config path resolved from default. path=$path'); + return path; } /// Returns the default config file path. diff --git a/apps/focus_flow_flutter/lib/controllers/command/scheduler_command_controller_impl.dart b/apps/focus_flow_flutter/lib/controllers/command/scheduler_command_controller_impl.dart index 2632f93..0f01d30 100644 --- a/apps/focus_flow_flutter/lib/controllers/command/scheduler_command_controller_impl.dart +++ b/apps/focus_flow_flutter/lib/controllers/command/scheduler_command_controller_impl.dart @@ -12,10 +12,9 @@ class SchedulerCommandController extends ChangeNotifier { required this.selectedDate, required this.refreshReads, required this.quickCaptureProjectId, - String operationIdPrefix = 'ui-command', + this.operationIdPrefix = 'ui-command', DateTime Function()? now, - }) : _operationIdPrefix = operationIdPrefix, - now = now ?? _utcNow; + }) : now = now ?? _utcNow; /// Scheduler write use cases invoked by this controller. final V1ApplicationCommandUseCases commands; @@ -32,9 +31,8 @@ class SchedulerCommandController extends ChangeNotifier { /// Project id used by quick-capture commands. final String quickCaptureProjectId; - /// Private state stored as `_operationIdPrefix` for this implementation. - /// The field is intentionally scoped to this library so only the owning type can change the related scheduler or UI behavior. - final String _operationIdPrefix; + /// Prefix used to generate unique operation ids for scheduler commands. + final String operationIdPrefix; /// Clock used by direct UI commands such as marking a task complete. final DateTime Function() now; @@ -58,6 +56,11 @@ class SchedulerCommandController extends ChangeNotifier { /// Captures [title] as a backlog task. Future quickCaptureToBacklog(String title) async { + logger.debug( + () => + 'UI command requested: quick capture to backlog. ' + 'projectId=$quickCaptureProjectId hasTitle=${title.trim().isNotEmpty}', + ); await _run( label: 'Capturing task', successMessage: 'Task captured', @@ -75,6 +78,11 @@ class SchedulerCommandController extends ChangeNotifier { /// Adds a generic flexible task to the next available Today slot. Future addGenericFlexibleTask() async { + logger.debug( + () => + 'UI command requested: add generic flexible task. ' + 'durationMinutes=$_genericFlexibleTaskDurationMinutes projectId=$quickCaptureProjectId', + ); await _run( label: 'Adding task', successMessage: 'Task added', @@ -98,6 +106,12 @@ class SchedulerCommandController extends ChangeNotifier { required int durationMinutes, required DateTime expectedUpdatedAt, }) async { + logger.debug( + () => + 'UI command requested: schedule backlog item. ' + 'taskId=$taskId durationMinutes=$durationMinutes ' + 'expectedUpdatedAt=${expectedUpdatedAt.toIso8601String()}', + ); await _run( label: 'Scheduling task', successMessage: 'Task scheduled', @@ -134,6 +148,13 @@ class SchedulerCommandController extends ChangeNotifier { DateTime? expectedUpdatedAt, }) async { final completedAt = now(); + logger.debug( + () => + 'UI command requested: complete task. ' + 'taskId=$taskId taskType=${taskType.name} ' + 'hasExpectedUpdatedAt=${expectedUpdatedAt != null} ' + 'occurredAt=${completedAt.toIso8601String()}', + ); await _run( label: 'Completing task', successMessage: 'Task completed', @@ -177,6 +198,12 @@ class SchedulerCommandController extends ChangeNotifier { DateTime? expectedUpdatedAt, }) async { final occurredAt = now(); + logger.debug( + () => + 'UI command requested: uncomplete task. ' + 'taskId=$taskId hasExpectedUpdatedAt=${expectedUpdatedAt != null} ' + 'occurredAt=${occurredAt.toIso8601String()}', + ); await _run( label: 'Reopening task', successMessage: 'Task marked as not done', @@ -198,6 +225,12 @@ class SchedulerCommandController extends ChangeNotifier { DateTime? expectedUpdatedAt, }) async { final commandAt = now(); + logger.debug( + () => + 'UI command requested: push task to next available slot. ' + 'taskId=$taskId hasExpectedUpdatedAt=${expectedUpdatedAt != null} ' + 'occurredAt=${commandAt.toIso8601String()}', + ); await _run( label: 'Pushing task', successMessage: 'Task pushed', @@ -219,6 +252,12 @@ class SchedulerCommandController extends ChangeNotifier { DateTime? expectedUpdatedAt, }) async { final commandAt = now(); + logger.debug( + () => + 'UI command requested: push task to tomorrow. ' + 'taskId=$taskId hasExpectedUpdatedAt=${expectedUpdatedAt != null} ' + 'occurredAt=${commandAt.toIso8601String()}', + ); await _run( label: 'Pushing task', successMessage: 'Task moved to tomorrow', @@ -240,6 +279,12 @@ class SchedulerCommandController extends ChangeNotifier { DateTime? expectedUpdatedAt, }) async { final commandAt = now(); + logger.debug( + () => + 'UI command requested: push task to backlog. ' + 'taskId=$taskId hasExpectedUpdatedAt=${expectedUpdatedAt != null} ' + 'occurredAt=${commandAt.toIso8601String()}', + ); await _run( label: 'Moving task to backlog', successMessage: 'Task moved to backlog', @@ -266,19 +311,44 @@ class SchedulerCommandController extends ChangeNotifier { action, }) async { final operationId = _nextOperationId(); + logger.debug( + () => 'Scheduler command started. operationId=$operationId label=$label', + ); _setState(SchedulerCommandRunning(label)); try { final result = await action(operationId); final failure = result.failure; if (failure != null) { + logger.warn( + () => + 'Scheduler command returned failure. ' + 'operationId=$operationId code=${failure.code.name} ' + 'detailCode=${failure.detailCode} entityId=${failure.entityId}', + ); _setState(SchedulerCommandFailure(failure: failure)); return; } + logger.debug( + () => + 'Scheduler command succeeded. operationId=$operationId ' + 'refreshAfterSuccess=$refreshAfterSuccess', + ); if (refreshAfterSuccess) { + logger.finer( + () => + 'Refreshing reads after scheduler command. ' + 'operationId=$operationId', + ); await refreshReads(); } _setState(SchedulerCommandSuccess(successMessage)); - } on Object catch (error) { + } on Object catch (error, stackTrace) { + logger.error( + () => + 'Scheduler command threw unexpectedly. operationId=$operationId label=$label', + error: error, + stackTrace: stackTrace, + ); _setState(SchedulerCommandFailure(error: error)); } } @@ -287,7 +357,7 @@ class SchedulerCommandController extends ChangeNotifier { /// The helper centralizes a small piece of transformation or validation so higher-level scheduler flow remains easier to read. String _nextOperationId() { _sequence += 1; - return '$_operationIdPrefix-$_sequence'; + return '$operationIdPrefix-$_sequence'; } /// Runs the `_setState` helper used inside this library. diff --git a/apps/focus_flow_flutter/lib/controllers/scheduler_read_controller.dart b/apps/focus_flow_flutter/lib/controllers/scheduler_read_controller.dart index b446e31..4a8d3cb 100644 --- a/apps/focus_flow_flutter/lib/controllers/scheduler_read_controller.dart +++ b/apps/focus_flow_flutter/lib/controllers/scheduler_read_controller.dart @@ -98,21 +98,35 @@ class ApplicationReadController extends UiReadController { /// Loads the current value and updates [state]. @override Future load() async { + logger.debug(() => 'Scheduler read started. valueType=$T'); _setState(SchedulerReadLoading()); try { final result = await read(); final failure = result.failure; if (failure != null) { + logger.warn( + () => + 'Scheduler read returned failure. valueType=$T ' + 'code=${failure.code.name} detailCode=${failure.detailCode} ' + 'entityId=${failure.entityId}', + ); _setState(SchedulerReadFailure(failure: failure)); return; } final value = result.requireValue; - _setState( - isEmpty(value) - ? SchedulerReadEmpty(value) - : SchedulerReadData(value), + final empty = isEmpty(value); + logger.debug( + () => 'Scheduler read finished. valueType=$T isEmpty=$empty', + ); + _setState( + empty ? SchedulerReadEmpty(value) : SchedulerReadData(value), + ); + } on Object catch (error, stackTrace) { + logger.error( + () => 'Scheduler read threw unexpectedly. valueType=$T', + error: error, + stackTrace: stackTrace, ); - } on Object catch (error) { _setState(SchedulerReadFailure(error: error)); } } diff --git a/apps/focus_flow_flutter/lib/controllers/selected_date_controller.dart b/apps/focus_flow_flutter/lib/controllers/selected_date_controller.dart index 72ad816..86f6923 100644 --- a/apps/focus_flow_flutter/lib/controllers/selected_date_controller.dart +++ b/apps/focus_flow_flutter/lib/controllers/selected_date_controller.dart @@ -25,8 +25,13 @@ class SelectedDateController extends ChangeNotifier { /// Selects [date] as the visible planning day. bool selectDate(CivilDate date) { if (date == _date) { + logger.finer(() => 'Selected date unchanged. date=${date.toIsoString()}'); return false; } + logger.debug( + () => + 'Selected date changed. previous=${_date.toIsoString()} next=${date.toIsoString()}', + ); _date = date; notifyListeners(); return true; diff --git a/apps/focus_flow_flutter/lib/controllers/today_screen_controller.dart b/apps/focus_flow_flutter/lib/controllers/today_screen_controller.dart index 0282ee3..2eb7e13 100644 --- a/apps/focus_flow_flutter/lib/controllers/today_screen_controller.dart +++ b/apps/focus_flow_flutter/lib/controllers/today_screen_controller.dart @@ -118,15 +118,30 @@ class TodayScreenController extends ChangeNotifier { Future load() async { final date = selectedDates.date; final sequence = _nextLoadSequence(); + logger.debug( + () => + 'Today screen load started. date=${date.toIsoString()} sequence=$sequence', + ); _state = TodayScreenLoading(dateLabelFor(date)); notifyListeners(); try { final result = await read(date); if (_isStale(sequence)) { + logger.finer( + () => + 'Ignoring stale Today screen load result. ' + 'date=${date.toIsoString()} sequence=$sequence currentSequence=$_loadSequence', + ); return; } final failure = result.failure; if (failure != null) { + logger.warn( + () => + 'Today screen load returned failure. ' + 'date=${date.toIsoString()} code=${failure.code.name} ' + 'detailCode=${failure.detailCode} entityId=${failure.entityId}', + ); _state = TodayScreenFailure( message: failure.detailCode ?? failure.code.name, data: _emptyDataFor(date), @@ -143,11 +158,27 @@ class TodayScreenController extends ChangeNotifier { _state = data.cards.isEmpty ? TodayScreenEmpty(data) : TodayScreenReady(data); + logger.debug( + () => + 'Today screen load finished. date=${date.toIsoString()} ' + 'sequence=$sequence cardCount=${data.cards.length}', + ); notifyListeners(); - } on Object catch (error) { + } on Object catch (error, stackTrace) { if (_isStale(sequence)) { + logger.finer( + () => + 'Ignoring stale Today screen load exception. ' + 'date=${date.toIsoString()} sequence=$sequence currentSequence=$_loadSequence', + ); return; } + logger.error( + () => + 'Today screen load threw unexpectedly. date=${date.toIsoString()} sequence=$sequence', + error: error, + stackTrace: stackTrace, + ); _state = TodayScreenFailure( message: error.toString(), data: _emptyDataFor(date), @@ -159,8 +190,12 @@ class TodayScreenController extends ChangeNotifier { /// Selects [card] when the card allows selection. void selectCard(TimelineCardModel card) { if (!card.isSelectable) { + logger.finer( + () => 'Today screen card selection ignored. cardId=${card.id}', + ); return; } + logger.finer(() => 'Today screen card selected. cardId=${card.id}'); _selectedCard = card; notifyListeners(); } @@ -170,6 +205,9 @@ class TodayScreenController extends ChangeNotifier { if (_selectedCard == null) { return; } + logger.finer( + () => 'Today screen card selection cleared. cardId=${_selectedCard!.id}', + ); _selectedCard = null; notifyListeners(); } @@ -185,6 +223,10 @@ class TodayScreenController extends ChangeNotifier { /// Runs the `_handleSelectedDateChanged` helper used inside this library. /// The helper centralizes a small piece of transformation or validation so higher-level scheduler flow remains easier to read. void _handleSelectedDateChanged() { + logger.debug( + () => + 'Today screen selected date changed. date=${selectedDates.date.toIsoString()}', + ); _selectedCard = null; unawaited(load()); } @@ -221,6 +263,10 @@ class TodayScreenController extends ChangeNotifier { return; } } + logger.finer( + () => + 'Today screen selected card no longer present. cardId=${selected.id}', + ); _selectedCard = null; } diff --git a/apps/focus_flow_flutter/lib/main.dart b/apps/focus_flow_flutter/lib/main.dart index 6a49531..b146e3c 100644 --- a/apps/focus_flow_flutter/lib/main.dart +++ b/apps/focus_flow_flutter/lib/main.dart @@ -5,6 +5,9 @@ library; import 'package:flutter/material.dart'; +import 'package:scheduler_core/scheduler_core.dart' + as scheduler_core + show logger; import 'app/focus_flow_app.dart'; import 'app/persistent_scheduler_composition.dart'; @@ -22,18 +25,18 @@ Future main() async { try { final config = await FocusFlowRuntimeConfig.load(); logger = await FocusFlowFileLogger.open(config); - await logger.info('FocusFlow startup started.'); - await logger.debug( - 'Runtime config loaded. fileLogging=${logger.isEnabled}', + scheduler_core.logger.info(() => 'FocusFlow startup started.'); + scheduler_core.logger.debug( + () => 'Runtime config loaded. fileLogging=${logger.isEnabled}', ); final composition = await PersistentSchedulerComposition.open( logger: logger, ); - await logger.info('FocusFlow startup completed.'); + scheduler_core.logger.info(() => 'FocusFlow startup completed.'); runApp(FocusFlowApp(composition: composition)); } on Object catch (error, stackTrace) { - await logger.error( - 'FocusFlow startup failed.', + scheduler_core.logger.error( + () => 'FocusFlow startup failed.', error: error, stackTrace: stackTrace, ); diff --git a/apps/focus_flow_flutter/lib/widgets/timeline/task_card/task_timeline_card_state.dart b/apps/focus_flow_flutter/lib/widgets/timeline/task_card/task_timeline_card_state.dart index c445903..29eb8ed 100644 --- a/apps/focus_flow_flutter/lib/widgets/timeline/task_card/task_timeline_card_state.dart +++ b/apps/focus_flow_flutter/lib/widgets/timeline/task_card/task_timeline_card_state.dart @@ -117,13 +117,25 @@ class _TaskTimelineCardState extends State { Future Function(TimelineCardModel card) callback, ) async { if (_isPushRunning) { + logger.warn( + () => 'Duplicate card push action ignored. cardId=${widget.card.id}', + ); return; } + logger.debug(() => 'Card push action started. cardId=${widget.card.id}'); setState(() { _isPushRunning = true; }); try { await callback(widget.card); + logger.debug(() => 'Card push action finished. cardId=${widget.card.id}'); + } on Object catch (error, stackTrace) { + logger.error( + () => 'Card push action failed. cardId=${widget.card.id}', + error: error, + stackTrace: stackTrace, + ); + rethrow; } finally { if (mounted) { setState(() { diff --git a/apps/focus_flow_flutter/lib/widgets/timeline/task_timeline_card.dart b/apps/focus_flow_flutter/lib/widgets/timeline/task_timeline_card.dart index 02c005d..e4cb781 100644 --- a/apps/focus_flow_flutter/lib/widgets/timeline/task_timeline_card.dart +++ b/apps/focus_flow_flutter/lib/widgets/timeline/task_timeline_card.dart @@ -8,6 +8,7 @@ import 'dart:async'; import 'dart:math' as math; import 'package:flutter/material.dart'; +import 'package:scheduler_core/scheduler_core.dart' show logger; import '../../models/today_screen_models.dart'; import '../../theme/focus_flow_tokens.dart'; diff --git a/apps/focus_flow_flutter/test/persistent_composition_test.dart b/apps/focus_flow_flutter/test/persistent_composition_test.dart index 7f85e92..4cc47b0 100644 --- a/apps/focus_flow_flutter/test/persistent_composition_test.dart +++ b/apps/focus_flow_flutter/test/persistent_composition_test.dart @@ -128,7 +128,7 @@ void main() { selectedDate: selectedDate, clock: FixedClock(_instant(8, 10)), ); - var scheduled = await _readTodayItem( + final scheduled = await _readTodayItem( tester, composition, tomorrow, @@ -225,7 +225,7 @@ void main() { selectedDate: _date, clock: FixedClock(commandNow), ); - var commandController = _commandController( + final commandController = _commandController( composition, selectedDate: _date, operationIdPrefix: 'past-push', diff --git a/packages/scheduler_backup/lib/src/encrypted_backup.dart b/packages/scheduler_backup/lib/src/encrypted_backup.dart index 1169931..5f55ebb 100644 --- a/packages/scheduler_backup/lib/src/encrypted_backup.dart +++ b/packages/scheduler_backup/lib/src/encrypted_backup.dart @@ -10,6 +10,7 @@ import 'dart:math'; import 'dart:typed_data'; import 'package:cryptography/cryptography.dart'; +import 'package:scheduler_core/scheduler_core.dart' show logger; part 'encrypted_backup/errors/backup_decryption_exception.dart'; part 'encrypted_backup/codec/backup_encryption_codec.dart'; part 'encrypted_backup/errors/backup_exception.dart'; diff --git a/packages/scheduler_backup/lib/src/encrypted_backup/codec/backup_encryption_codec.dart b/packages/scheduler_backup/lib/src/encrypted_backup/codec/backup_encryption_codec.dart index 00b43ff..8ccba31 100644 --- a/packages/scheduler_backup/lib/src/encrypted_backup/codec/backup_encryption_codec.dart +++ b/packages/scheduler_backup/lib/src/encrypted_backup/codec/backup_encryption_codec.dart @@ -56,9 +56,19 @@ Future> _decryptBytes({ SecretBox(cipherText, nonce: nonce, mac: mac), secretKey: key, ); - } on BackupDecryptionException { + } on BackupDecryptionException catch (error, stackTrace) { + logger.error( + () => 'Encrypted backup decryption failed with known backup error.', + error: error, + stackTrace: stackTrace, + ); rethrow; - } on Object { + } on Object catch (error, stackTrace) { + logger.error( + () => 'Encrypted backup decryption failed.', + error: error, + stackTrace: stackTrace, + ); throw const BackupDecryptionException(); } } diff --git a/packages/scheduler_backup/lib/src/encrypted_backup/operations/encrypted_backup_operations.dart b/packages/scheduler_backup/lib/src/encrypted_backup/operations/encrypted_backup_operations.dart index 9174859..4a32971 100644 --- a/packages/scheduler_backup/lib/src/encrypted_backup/operations/encrypted_backup_operations.dart +++ b/packages/scheduler_backup/lib/src/encrypted_backup/operations/encrypted_backup_operations.dart @@ -16,7 +16,10 @@ Future createEncryptedBackup({ DateTime? now, }) async { final source = sqliteFile ?? defaultSchedulerSqliteFile(); + logger.info(() => 'Encrypted backup started. sourcePath=${source.path}'); if (!await source.exists()) { + logger.warn(() => + 'Encrypted backup source file missing. sourcePath=${source.path}'); throw BackupException('SQLite file does not exist: ${source.path}'); } @@ -35,7 +38,11 @@ Future createEncryptedBackup({ passphrase: passphrase, plaintext: plaintext, ); - return destination.writeAsBytes(encoded, flush: true); + final output = await destination.writeAsBytes(encoded, flush: true); + logger.info(() => 'Encrypted backup completed. sourcePath=${source.path} ' + 'destinationPath=${output.path} sourceBytes=${plaintext.length} ' + 'encodedBytes=${encoded.length}'); + return output; } /// Restore an encrypted backup over the scheduler SQLite file. @@ -47,7 +54,11 @@ Future restoreEncryptedBackup( String passphrase, { File? targetFile, }) async { + logger.info( + () => 'Encrypted backup restore started. backupPath=${backup.path}'); if (!await backup.exists()) { + logger.warn(() => + 'Encrypted backup restore source missing. backupPath=${backup.path}'); throw BackupException('Backup file does not exist: ${backup.path}'); } @@ -64,4 +75,7 @@ Future restoreEncryptedBackup( await target.delete(); } await temporary.rename(target.path); + logger.info( + () => 'Encrypted backup restore completed. backupPath=${backup.path} ' + 'targetPath=${target.path} restoredBytes=${plaintext.length}'); } diff --git a/packages/scheduler_backup/lib/src/encrypted_backup/paths/backup_paths.dart b/packages/scheduler_backup/lib/src/encrypted_backup/paths/backup_paths.dart index 2bd5e85..d6c8b12 100644 --- a/packages/scheduler_backup/lib/src/encrypted_backup/paths/backup_paths.dart +++ b/packages/scheduler_backup/lib/src/encrypted_backup/paths/backup_paths.dart @@ -28,6 +28,8 @@ Directory _homeDirectory() { Platform.environment['USERPROFILE'] ?? Platform.environment['HOMEDRIVE']; if (home == null || home.trim().isEmpty) { + logger.warn( + () => 'Backup home directory could not be resolved from environment.'); throw const BackupException('Home directory could not be resolved.'); } return Directory(home); diff --git a/packages/scheduler_backup/pubspec.yaml b/packages/scheduler_backup/pubspec.yaml index 1c8bf80..9f960c5 100644 --- a/packages/scheduler_backup/pubspec.yaml +++ b/packages/scheduler_backup/pubspec.yaml @@ -13,6 +13,7 @@ environment: dependencies: cryptography: ^2.7.0 encrypt: ^5.0.3 + scheduler_core: any dev_dependencies: lints: ^5.0.0 diff --git a/packages/scheduler_core/lib/src/application/application_commands.dart b/packages/scheduler_core/lib/src/application/application_commands.dart index 4c0d3b7..1b57a32 100644 --- a/packages/scheduler_core/lib/src/application/application_commands.dart +++ b/packages/scheduler_core/lib/src/application/application_commands.dart @@ -21,6 +21,7 @@ import '../scheduling/scheduling_engine.dart'; import '../scheduling/task_actions.dart'; import '../scheduling/task_lifecycle.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'application_commands/codes/application_command_code.dart'; part 'application_commands/messages/application_child_task_draft.dart'; part 'application_commands/messages/application_command_read_hint.dart'; diff --git a/packages/scheduler_core/lib/src/application/application_commands/use_cases/v1_application_command_use_cases.dart b/packages/scheduler_core/lib/src/application/application_commands/use_cases/v1_application_command_use_cases.dart index b569a62..e28e8ae 100644 --- a/packages/scheduler_core/lib/src/application/application_commands/use_cases/v1_application_command_use_cases.dart +++ b/packages/scheduler_core/lib/src/application/application_commands/use_cases/v1_application_command_use_cases.dart @@ -80,6 +80,10 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} hasTitle=${title.trim().isNotEmpty} ' + 'projectId=$projectId taskType=${type.name} durationMinutes=$durationMinutes'); final result = quickCaptureService.capture( QuickCaptureRequest( id: context.idGenerator.nextId(), @@ -136,6 +140,11 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} ' + 'hasTitle=${title.trim().isNotEmpty} projectId=$projectId ' + 'durationMinutes=$durationMinutes'); final state = await _loadPlanningState(repositories, context, localDate); final taskId = context.idGenerator.nextId(); @@ -199,9 +208,16 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} ' + 'taskId=$taskId durationMinutes=$durationMinutes'); var state = await _loadPlanningState(repositories, context, localDate); var task = _taskById(state.tasks, taskId); if (task == null) { + logger.finer(() => + 'Planning-state task lookup missed; reading by id. ' + 'command=${commandCode.name} taskId=$taskId operationId=${context.operationId}'); task = await repositories.tasks.findById(taskId); if (task != null) { state = state.withTask(task); @@ -316,6 +332,9 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug( + () => 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} taskId=$taskId'); final task = await repositories.tasks.findById(taskId); if (task == null) { return _failure(ApplicationFailureCode.notFound, entityId: taskId); @@ -370,9 +389,15 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} taskId=$taskId'); var state = await _loadPlanningState(repositories, context, localDate); var task = _taskById(state.tasks, taskId); if (task == null) { + logger.finer(() => + 'Planning-state task lookup missed; reading by id. ' + 'command=${commandCode.name} taskId=$taskId operationId=${context.operationId}'); task = await repositories.tasks.findById(taskId); if (task != null) { state = state.withTask(task); @@ -432,9 +457,15 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} taskId=$taskId'); var state = await _loadPlanningState(repositories, context, localDate); var task = _taskById(state.tasks, taskId); if (task == null) { + logger.finer(() => + 'Planning-state task lookup missed; reading by id. ' + 'command=${commandCode.name} taskId=$taskId operationId=${context.operationId}'); task = await repositories.tasks.findById(taskId); if (task != null) { state = state.withTask(task); @@ -492,9 +523,16 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} taskId=$taskId ' + 'action=${action.name}'); var state = await _loadPlanningState(repositories, context, localDate); var task = _taskById(state.tasks, taskId); if (task == null) { + logger.finer(() => + 'Planning-state task lookup missed; reading by id. ' + 'command=${commandCode.name} taskId=$taskId operationId=${context.operationId}'); task = await repositories.tasks.findById(taskId); if (task != null) { state = state.withTask(task); @@ -560,6 +598,11 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} ' + 'hasTitle=${title.trim().isNotEmpty} hasStartedAt=${startedAt != null} ' + 'timeUsedMinutes=$timeUsedMinutes projectId=$projectId'); final state = await _loadPlanningState(repositories, context, localDate); final logResult = surpriseTaskLogService.log( @@ -613,6 +656,11 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} ' + 'start=${start.toIso8601String()} end=${end.toIso8601String()} ' + 'projectId=$projectId hasTitle=${title.trim().isNotEmpty}'); final freeSlot = freeSlotService.create( id: context.idGenerator.nextId(), title: title, @@ -654,6 +702,11 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} taskId=$taskId ' + 'start=${start.toIso8601String()} end=${end.toIso8601String()} ' + 'hasTitle=${title != null} projectId=$projectId'); final task = await repositories.tasks.findById(taskId); if (task == null) { return _failure(ApplicationFailureCode.notFound, entityId: taskId); @@ -698,6 +751,9 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} taskId=$taskId'); final task = await repositories.tasks.findById(taskId); if (task == null) { return _failure(ApplicationFailureCode.notFound, entityId: taskId); @@ -746,6 +802,10 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug( + () => 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} parentTaskId=$parentTaskId ' + 'childDraftCount=${children.length}'); final tasks = await repositories.tasks.findAll(); final parent = _taskById(tasks, parentTaskId); if (parent == null) { @@ -882,9 +942,16 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug(() => + 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} localDate=${localDate.toIsoString()} taskId=$taskId ' + 'destination=${destination.name}'); var state = await _loadPlanningState(repositories, context, localDate); var task = _taskById(state.tasks, taskId); if (task == null) { + logger.finer(() => + 'Planning-state task lookup missed; reading by id. ' + 'command=${commandCode.name} taskId=$taskId operationId=${context.operationId}'); task = await repositories.tasks.findById(taskId); if (task != null) { state = state.withTask(task); @@ -950,6 +1017,9 @@ class V1ApplicationCommandUseCases { context: context, operationName: commandCode.name, action: (repositories) async { + logger.debug( + () => 'Application command executing. command=${commandCode.name} ' + 'operationId=${context.operationId} taskId=$taskId'); final tasks = await repositories.tasks.findAll(); final task = _taskById(tasks, taskId); if (task == null) { @@ -989,6 +1059,8 @@ class V1ApplicationCommandUseCases { CivilDate localDate, ) async { final ownerId = context.ownerTimeZone.ownerId; + logger.debug(() => 'Loading planning state. ownerId=$ownerId ' + 'localDate=${localDate.toIsoString()} operationId=${context.operationId}'); final settings = await repositories.ownerSettings.findByOwnerId(ownerId) ?? OwnerSettings( ownerId: ownerId, @@ -1027,6 +1099,11 @@ class V1ApplicationCommandUseCases { resolutionOptions: resolutionOptions, ); + logger.debug(() => + 'Planning state loaded. ownerId=$ownerId localDate=${localDate.toIsoString()} ' + 'taskCount=${tasks.length} lockedIntervalCount=${lockedExpansion.schedulingIntervals.length} ' + 'windowStart=${window.start.toIso8601String()} windowEnd=${window.end.toIso8601String()}'); + return _PlanningState( tasks: tasks, window: window, @@ -1067,6 +1144,11 @@ class V1ApplicationCommandUseCases { List childTaskIds = const [], }) async { final changedTasks = _changedTasks(beforeTasks, afterTasks); + logger.debug(() => + 'Persisting application command result. command=${commandCode.name} ' + 'operationId=${context.operationId} changedTaskCount=${changedTasks.length} ' + 'activityCount=${activities.length} noticeCount=${schedulingResult?.notices.length ?? 0} ' + 'changeCount=${schedulingResult?.changes.length ?? 0}'); await repositories.tasks.saveAll(changedTasks); await repositories.taskActivities.saveAll(activities); final projectStats = await _saveProjectStatistics( @@ -1075,6 +1157,11 @@ class V1ApplicationCommandUseCases { tasks: afterTasks, ); + logger.debug(() => + 'Application command persisted. command=${commandCode.name} ' + 'operationId=${context.operationId} changedTaskCount=${changedTasks.length} ' + 'projectStatisticsCount=${projectStats.length}'); + return ApplicationResult.success( ApplicationCommandResult( commandCode: commandCode, @@ -1104,6 +1191,8 @@ class V1ApplicationCommandUseCases { .where((activity) => activity.code == TaskActivityCode.completed) .map((activity) => activity.projectId) .toSet(); + logger.finer(() => 'Saving project statistics after command. ' + 'projectCount=${projectIds.length} activityCount=${activities.length}'); final updated = []; for (final projectId in projectIds) { @@ -1119,6 +1208,8 @@ class V1ApplicationCommandUseCases { if (result.appliedActivityIds.isEmpty) { continue; } + logger.finer(() => 'Project statistics updated. projectId=$projectId ' + 'appliedActivityCount=${result.appliedActivityIds.length}'); await repositories.projectStatistics.save(result.statistics); updated.add(result.statistics); } diff --git a/packages/scheduler_core/lib/src/application/application_layer.dart b/packages/scheduler_core/lib/src/application/application_layer.dart index 5d67f36..fe730ba 100644 --- a/packages/scheduler_core/lib/src/application/application_layer.dart +++ b/packages/scheduler_core/lib/src/application/application_layer.dart @@ -18,6 +18,7 @@ import '../persistence/repositories.dart'; import '../scheduling/scheduling_engine.dart'; import '../scheduling/task_lifecycle.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'application_layer/context/owner_time_zone_context.dart'; part 'application_layer/context/application_operation_context.dart'; part 'application_layer/results/application_failure_code.dart'; diff --git a/packages/scheduler_core/lib/src/application/application_layer/repositories/in_memory/in_memory_application_unit_of_work.dart b/packages/scheduler_core/lib/src/application/application_layer/repositories/in_memory/in_memory_application_unit_of_work.dart index d3049dc..add1b88 100644 --- a/packages/scheduler_core/lib/src/application/application_layer/repositories/in_memory/in_memory_application_unit_of_work.dart +++ b/packages/scheduler_core/lib/src/application/application_layer/repositories/in_memory/in_memory_application_unit_of_work.dart @@ -195,7 +195,13 @@ class InMemoryApplicationUnitOfWork implements ApplicationUnitOfWork { ApplicationUnitOfWorkRepositories repositories, ) action, }) async { + logger.debug(() => 'In-memory unit of work run started. ' + 'operationId=${context.operationId} operationName=$operationName ' + 'ownerId=${context.ownerTimeZone.ownerId}'); if (_state.operationsById.containsKey(context.operationId)) { + logger.warn(() => + 'Duplicate operation ignored by in-memory unit of work. ' + 'operationId=${context.operationId} operationName=$operationName'); return ApplicationResult.failure( ApplicationFailure( code: ApplicationFailureCode.duplicateOperation, @@ -210,6 +216,9 @@ class InMemoryApplicationUnitOfWork implements ApplicationUnitOfWork { try { final result = await action(repositories); if (result.isFailure) { + logger.warn(() => 'In-memory unit of work action returned failure. ' + 'operationId=${context.operationId} operationName=$operationName ' + 'code=${result.failure!.code.name} detailCode=${result.failure!.detailCode}'); return result; } @@ -222,14 +231,29 @@ class InMemoryApplicationUnitOfWork implements ApplicationUnitOfWork { if (_failNextCommit) { _failNextCommit = false; + logger.error(() => 'In-memory unit of work commit failed by test hook. ' + 'operationId=${context.operationId} operationName=$operationName'); throw const ApplicationPersistenceException(); } _state = staged; + logger.debug(() => 'In-memory unit of work run committed. ' + 'operationId=${context.operationId} operationName=$operationName ' + 'taskCount=${_state.tasksById.length} projectCount=${_state.projectsById.length} ' + 'lockedBlockCount=${_state.lockedBlocksById.length} ' + 'snapshotCount=${_state.schedulingSnapshotsById.length} ' + 'operationCount=${_state.operationsById.length}'); return result; } on ApplicationFailureException catch (error) { + logger.warn(() => 'In-memory unit of work caught application failure. ' + 'operationId=${context.operationId} operationName=$operationName ' + 'code=${error.failure.code.name} detailCode=${error.failure.detailCode}'); return ApplicationResult.failure(error.failure); } on DomainValidationException catch (error) { + logger.warn( + () => 'In-memory unit of work caught domain validation failure. ' + 'operationId=${context.operationId} operationName=$operationName ' + 'code=${error.code.name}'); return ApplicationResult.failure( ApplicationFailure( code: ApplicationFailureCode.validation, @@ -237,19 +261,35 @@ class InMemoryApplicationUnitOfWork implements ApplicationUnitOfWork { ), ); } on ArgumentError catch (error) { + logger.warn( + () => 'In-memory unit of work caught argument validation failure. ' + 'operationId=${context.operationId} operationName=$operationName ' + 'argumentName=${error.name}'); return ApplicationResult.failure( ApplicationFailure( code: ApplicationFailureCode.validation, detailCode: error.name, ), ); - } on ApplicationPersistenceException { + } on ApplicationPersistenceException catch (error, stackTrace) { + logger.error( + () => 'In-memory unit of work persistence failure. ' + 'operationId=${context.operationId} operationName=$operationName', + error: error, + stackTrace: stackTrace, + ); return ApplicationResult.failure( const ApplicationFailure( code: ApplicationFailureCode.persistenceFailure, ), ); - } catch (_) { + } catch (error, stackTrace) { + logger.error( + () => 'In-memory unit of work unexpected failure. ' + 'operationId=${context.operationId} operationName=$operationName', + error: error, + stackTrace: stackTrace, + ); return ApplicationResult.failure( const ApplicationFailure(code: ApplicationFailureCode.unexpected), ); @@ -264,14 +304,34 @@ class InMemoryApplicationUnitOfWork implements ApplicationUnitOfWork { ApplicationUnitOfWorkRepositories repositories, ) action, }) async { + logger.debug(() => 'In-memory unit of work read started. ' + 'taskCount=${_state.tasksById.length} projectCount=${_state.projectsById.length} ' + 'lockedBlockCount=${_state.lockedBlocksById.length} ' + 'snapshotCount=${_state.schedulingSnapshotsById.length}'); final staged = _state.copy(); final repositories = _InMemoryApplicationRepositories(staged); try { - return await action(repositories); + final result = await action(repositories); + if (result.isFailure) { + logger.warn(() => 'In-memory unit of work read returned failure. ' + 'code=${result.failure!.code.name} detailCode=${result.failure!.detailCode}'); + } else { + logger.debug(() => 'In-memory unit of work read finished. ' + 'taskCount=${staged.tasksById.length} projectCount=${staged.projectsById.length} ' + 'lockedBlockCount=${staged.lockedBlocksById.length} ' + 'snapshotCount=${staged.schedulingSnapshotsById.length}'); + } + return result; } on ApplicationFailureException catch (error) { + logger.warn(() => + 'In-memory unit of work read caught application failure. ' + 'code=${error.failure.code.name} detailCode=${error.failure.detailCode}'); return ApplicationResult.failure(error.failure); } on DomainValidationException catch (error) { + logger.warn( + () => 'In-memory unit of work read caught domain validation failure. ' + 'code=${error.code.name}'); return ApplicationResult.failure( ApplicationFailure( code: ApplicationFailureCode.validation, @@ -279,19 +339,32 @@ class InMemoryApplicationUnitOfWork implements ApplicationUnitOfWork { ), ); } on ArgumentError catch (error) { + logger.warn(() => + 'In-memory unit of work read caught argument validation failure. ' + 'argumentName=${error.name}'); return ApplicationResult.failure( ApplicationFailure( code: ApplicationFailureCode.validation, detailCode: error.name, ), ); - } on ApplicationPersistenceException { + } on ApplicationPersistenceException catch (error, stackTrace) { + logger.error( + () => 'In-memory unit of work read persistence failure.', + error: error, + stackTrace: stackTrace, + ); return ApplicationResult.failure( const ApplicationFailure( code: ApplicationFailureCode.persistenceFailure, ), ); - } catch (_) { + } catch (error, stackTrace) { + logger.error( + () => 'In-memory unit of work read unexpected failure.', + error: error, + stackTrace: stackTrace, + ); return ApplicationResult.failure( const ApplicationFailure(code: ApplicationFailureCode.unexpected), ); diff --git a/packages/scheduler_core/lib/src/application/application_management.dart b/packages/scheduler_core/lib/src/application/application_management.dart index 5016520..258d5e8 100644 --- a/packages/scheduler_core/lib/src/application/application_management.dart +++ b/packages/scheduler_core/lib/src/application/application_management.dart @@ -17,6 +17,7 @@ import '../domain/locked_time.dart'; import '../domain/models.dart'; import '../domain/project_statistics.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'application_management/codes/application_management_command_code.dart'; part 'application_management/codes/owner_settings_warning_code.dart'; part 'application_management/requests/get_backlog_request.dart'; diff --git a/packages/scheduler_core/lib/src/application/application_management/use_cases/v1_application_management_use_cases.dart b/packages/scheduler_core/lib/src/application/application_management/use_cases/v1_application_management_use_cases.dart index 20cbe71..1b8ea36 100644 --- a/packages/scheduler_core/lib/src/application/application_management/use_cases/v1_application_management_use_cases.dart +++ b/packages/scheduler_core/lib/src/application/application_management/use_cases/v1_application_management_use_cases.dart @@ -26,6 +26,8 @@ class V1ApplicationManagementUseCases { return applicationStore.read( action: (repositories) async { final ownerId = request.context.ownerTimeZone.ownerId; + logger.debug(() => 'Loading backlog query. ownerId=$ownerId ' + 'sortKey=${request.sortKey.name} hasFilter=${request.filter != null}'); final settings = await _ownerSettingsOrDefault( repositories, request.context.ownerTimeZone, @@ -46,6 +48,9 @@ class V1ApplicationManagementUseCases { stalenessSettings: settings.backlogStalenessSettings, ); final sorted = view.sorted(request.sortKey); + logger.debug(() => 'Backlog query loaded. ownerId=$ownerId ' + 'candidateCount=${candidates.length} filteredCount=${filtered.length} ' + 'itemCount=${sorted.length}'); return ApplicationResult.success( BacklogQueryResult( @@ -70,6 +75,9 @@ class V1ApplicationManagementUseCases { ) { return applicationStore.read( action: (repositories) async { + logger.debug(() => + 'Loading project defaults. ownerId=${request.context.ownerTimeZone.ownerId} ' + 'includeArchived=${request.includeArchived}'); final projects = (await repositories.projects.findByOwner( ownerId: request.context.ownerTimeZone.ownerId, includeArchived: request.includeArchived, @@ -94,6 +102,10 @@ class V1ApplicationManagementUseCases { ); } + logger.debug(() => + 'Project defaults loaded. ownerId=${request.context.ownerTimeZone.ownerId} ' + 'projectCount=${projects.length} resolutionCount=${resolutions.length}'); + return ApplicationResult.success( ProjectDefaultsQueryResult( ownerId: request.context.ownerTimeZone.ownerId, @@ -115,8 +127,14 @@ class V1ApplicationManagementUseCases { operationName: ApplicationManagementCommandCode.createProject.name, action: (repositories) async { final id = draft.id ?? context.idGenerator.nextId(); + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.createProject.name} ' + 'operationId=${context.operationId} projectId=$id hasName=${draft.name.trim().isNotEmpty} ' + 'defaultDurationMinutes=${draft.defaultDurationMinutes}'); final existing = await repositories.projects.findById(id); if (existing != null) { + logger.warn(() => 'Create project failed: project already exists. ' + 'operationId=${context.operationId} projectId=$id'); return _failure( ApplicationFailureCode.conflict, entityId: id, @@ -134,6 +152,8 @@ class V1ApplicationManagementUseCases { defaultDurationMinutes: draft.defaultDurationMinutes, ); await repositories.projects.save(project); + logger.debug(() => + 'Project created. operationId=${context.operationId} projectId=$id'); return ApplicationResult.success(project); }, ); @@ -150,6 +170,10 @@ class V1ApplicationManagementUseCases { context: context, operationName: ApplicationManagementCommandCode.updateProject.name, action: (repositories) async { + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.updateProject.name} ' + 'operationId=${context.operationId} projectId=$projectId ' + 'hasName=${update.name != null} hasColorKey=${update.colorKey != null}'); final project = await _requireProject(repositories, projectId); final updated = project.copyWith( name: update.name, @@ -162,6 +186,8 @@ class V1ApplicationManagementUseCases { clearDefaultDuration: update.clearDefaultDuration, ); await repositories.projects.save(updated); + logger.debug(() => + 'Project updated. operationId=${context.operationId} projectId=$projectId'); return ApplicationResult.success(updated); }, ); @@ -177,9 +203,14 @@ class V1ApplicationManagementUseCases { context: context, operationName: ApplicationManagementCommandCode.archiveProject.name, action: (repositories) async { + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.archiveProject.name} ' + 'operationId=${context.operationId} projectId=$projectId'); final project = await _requireProject(repositories, projectId); final archived = project.copyWith(archivedAt: context.now); await repositories.projects.save(archived); + logger.debug(() => + 'Project archived. operationId=${context.operationId} projectId=$projectId'); return ApplicationResult.success(archived); }, ); @@ -196,8 +227,14 @@ class V1ApplicationManagementUseCases { operationName: ApplicationManagementCommandCode.createLockedBlock.name, action: (repositories) async { final id = draft.id ?? context.idGenerator.nextId(); + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.createLockedBlock.name} ' + 'operationId=${context.operationId} lockedBlockId=$id date=${draft.date?.toIsoString()} ' + 'hasRecurrence=${draft.recurrence != null} hiddenByDefault=${draft.hiddenByDefault}'); final existing = await repositories.lockedBlocks.findBlockById(id); if (existing != null) { + logger.warn(() => 'Create locked block failed: block already exists. ' + 'operationId=${context.operationId} lockedBlockId=$id'); return _failure( ApplicationFailureCode.conflict, entityId: id, @@ -217,6 +254,8 @@ class V1ApplicationManagementUseCases { updatedAt: context.now, ); await repositories.lockedBlocks.saveBlock(block); + logger.debug(() => + 'Locked block created. operationId=${context.operationId} lockedBlockId=$id'); return ApplicationResult.success(block); }, ); @@ -233,6 +272,11 @@ class V1ApplicationManagementUseCases { context: context, operationName: ApplicationManagementCommandCode.updateLockedBlock.name, action: (repositories) async { + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.updateLockedBlock.name} ' + 'operationId=${context.operationId} lockedBlockId=$lockedBlockId ' + 'hasName=${update.name != null} hasDate=${update.date != null} ' + 'hasRecurrence=${update.recurrence != null}'); final block = await _requireLockedBlock(repositories, lockedBlockId); final updated = block.copyWith( name: update.name, @@ -245,6 +289,8 @@ class V1ApplicationManagementUseCases { updatedAt: context.now, ); await repositories.lockedBlocks.saveBlock(updated); + logger.debug(() => + 'Locked block updated. operationId=${context.operationId} lockedBlockId=$lockedBlockId'); return ApplicationResult.success(updated); }, ); @@ -260,12 +306,17 @@ class V1ApplicationManagementUseCases { context: context, operationName: ApplicationManagementCommandCode.archiveLockedBlock.name, action: (repositories) async { + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.archiveLockedBlock.name} ' + 'operationId=${context.operationId} lockedBlockId=$lockedBlockId'); final block = await _requireLockedBlock(repositories, lockedBlockId); final archived = block.copyWith( updatedAt: context.now, archivedAt: context.now, ); await repositories.lockedBlocks.saveBlock(archived); + logger.debug(() => + 'Locked block archived. operationId=${context.operationId} lockedBlockId=$lockedBlockId'); return ApplicationResult.success(archived); }, ); @@ -287,6 +338,10 @@ class V1ApplicationManagementUseCases { operationName: ApplicationManagementCommandCode.addLockedBlockOverride.name, action: (repositories) async { + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.addLockedBlockOverride.name} ' + 'operationId=${context.operationId} date=${date.toIsoString()} hiddenByDefault=$hiddenByDefault ' + 'hasProjectId=${projectId != null}'); final override = LockedBlockOverride.add( id: context.idGenerator.nextId(), date: date, @@ -298,6 +353,8 @@ class V1ApplicationManagementUseCases { createdAt: context.now, ); await repositories.lockedBlocks.saveOverride(override); + logger.debug(() => + 'Locked block override added. operationId=${context.operationId} overrideId=${override.id}'); return ApplicationResult.success(override); }, ); @@ -315,6 +372,9 @@ class V1ApplicationManagementUseCases { operationName: ApplicationManagementCommandCode.removeLockedBlockOccurrence.name, action: (repositories) async { + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.removeLockedBlockOccurrence.name} ' + 'operationId=${context.operationId} lockedBlockId=$lockedBlockId date=${date.toIsoString()}'); await _requireLockedBlock(repositories, lockedBlockId); final override = LockedBlockOverride.remove( id: context.idGenerator.nextId(), @@ -323,6 +383,9 @@ class V1ApplicationManagementUseCases { createdAt: context.now, ); await repositories.lockedBlocks.saveOverride(override); + logger.debug(() => + 'Locked block occurrence removed. operationId=${context.operationId} ' + 'lockedBlockId=$lockedBlockId overrideId=${override.id}'); return ApplicationResult.success(override); }, ); @@ -345,6 +408,10 @@ class V1ApplicationManagementUseCases { operationName: ApplicationManagementCommandCode.replaceLockedBlockOccurrence.name, action: (repositories) async { + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.replaceLockedBlockOccurrence.name} ' + 'operationId=${context.operationId} lockedBlockId=$lockedBlockId date=${date.toIsoString()} ' + 'hasName=${name != null} hiddenByDefault=$hiddenByDefault'); await _requireLockedBlock(repositories, lockedBlockId); final override = LockedBlockOverride.replace( id: context.idGenerator.nextId(), @@ -358,6 +425,9 @@ class V1ApplicationManagementUseCases { createdAt: context.now, ); await repositories.lockedBlocks.saveOverride(override); + logger.debug(() => + 'Locked block occurrence replaced. operationId=${context.operationId} ' + 'lockedBlockId=$lockedBlockId overrideId=${override.id}'); return ApplicationResult.success(override); }, ); @@ -373,6 +443,11 @@ class V1ApplicationManagementUseCases { context: context, operationName: ApplicationManagementCommandCode.updateOwnerSettings.name, action: (repositories) async { + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.updateOwnerSettings.name} ' + 'operationId=${context.operationId} ownerId=${context.ownerTimeZone.ownerId} ' + 'hasTimeZone=${update.timeZoneId != null} hasDayStart=${update.dayStart != null} ' + 'hasDayEnd=${update.dayEnd != null} hasStaleness=${update.backlogStalenessSettings != null}'); final current = await _ownerSettingsOrDefault( repositories, context.ownerTimeZone, @@ -382,6 +457,9 @@ class V1ApplicationManagementUseCases { (stalenessSettings.greenMaxAge.isNegative || stalenessSettings.blueMaxAge.isNegative || stalenessSettings.blueMaxAge < stalenessSettings.greenMaxAge)) { + logger.warn(() => + 'Owner settings update failed: invalid staleness thresholds. ' + 'operationId=${context.operationId} ownerId=${context.ownerTimeZone.ownerId}'); return _failure( ApplicationFailureCode.validation, detailCode: 'invalidBacklogStalenessThresholds', @@ -404,6 +482,9 @@ class V1ApplicationManagementUseCases { OwnerSettingsWarningCode.planningWindowChanged, ]; await repositories.ownerSettings.save(updated); + logger.debug(() => + 'Owner settings updated. operationId=${context.operationId} ' + 'ownerId=${context.ownerTimeZone.ownerId} warningCount=${warnings.length}'); return ApplicationResult.success( OwnerSettingsUpdateResult(settings: updated, warnings: warnings), ); @@ -422,8 +503,13 @@ class V1ApplicationManagementUseCases { operationName: ApplicationManagementCommandCode.acknowledgeNotice.name, action: (repositories) async { final ownerId = context.ownerTimeZone.ownerId; + logger.debug(() => + 'Management command executing. command=${ApplicationManagementCommandCode.acknowledgeNotice.name} ' + 'operationId=${context.operationId} ownerId=$ownerId noticeId=$noticeId'); final parsed = _parseNoticeId(noticeId); if (parsed == null) { + logger.warn(() => 'Notice acknowledgement failed: invalid notice id. ' + 'operationId=${context.operationId} noticeId=$noticeId'); return _failure( ApplicationFailureCode.validation, entityId: noticeId, @@ -433,6 +519,9 @@ class V1ApplicationManagementUseCases { final snapshot = await repositories.schedulingSnapshots.findById(parsed.snapshotId); if (snapshot == null || parsed.noticeIndex >= snapshot.notices.length) { + logger.warn(() => 'Notice acknowledgement failed: notice not found. ' + 'operationId=${context.operationId} noticeId=$noticeId ' + 'snapshotId=${parsed.snapshotId} noticeIndex=${parsed.noticeIndex}'); return _failure( ApplicationFailureCode.notFound, entityId: noticeId, @@ -444,6 +533,9 @@ class V1ApplicationManagementUseCases { noticeId: noticeId, ); if (existing != null) { + logger.finer(() => + 'Notice already acknowledged. operationId=${context.operationId} ' + 'noticeId=$noticeId ownerId=$ownerId'); return ApplicationResult.success( NoticeAcknowledgementResult( record: existing, @@ -458,6 +550,9 @@ class V1ApplicationManagementUseCases { acknowledgedAt: context.now, ); await repositories.noticeAcknowledgements.save(record); + logger.debug( + () => 'Notice acknowledged. operationId=${context.operationId} ' + 'noticeId=$noticeId ownerId=$ownerId'); return ApplicationResult.success( NoticeAcknowledgementResult( record: record, @@ -476,6 +571,7 @@ class V1ApplicationManagementUseCases { ) async { final project = await repositories.projects.findById(projectId); if (project == null) { + logger.warn(() => 'Required project not found. projectId=$projectId'); throw ApplicationFailureException( ApplicationFailure( code: ApplicationFailureCode.notFound, @@ -495,6 +591,8 @@ class V1ApplicationManagementUseCases { ) async { final block = await repositories.lockedBlocks.findBlockById(lockedBlockId); if (block == null) { + logger.warn(() => + 'Required locked block not found. lockedBlockId=$lockedBlockId'); throw ApplicationFailureException( ApplicationFailure( code: ApplicationFailureCode.notFound, @@ -513,12 +611,17 @@ Future _ownerSettingsOrDefault( ApplicationUnitOfWorkRepositories repositories, OwnerTimeZoneContext ownerTimeZone, ) async { - return await repositories.ownerSettings - .findByOwnerId(ownerTimeZone.ownerId) ?? - OwnerSettings( - ownerId: ownerTimeZone.ownerId, - timeZoneId: ownerTimeZone.timeZoneId, - ); + final settings = + await repositories.ownerSettings.findByOwnerId(ownerTimeZone.ownerId); + if (settings != null) { + return settings; + } + logger.finer(() => 'Owner settings missing; using defaults. ' + 'ownerId=${ownerTimeZone.ownerId} timeZoneId=${ownerTimeZone.timeZoneId}'); + return OwnerSettings( + ownerId: ownerTimeZone.ownerId, + timeZoneId: ownerTimeZone.timeZoneId, + ); } /// Top-level helper that performs the `_failure` operation for this file. diff --git a/packages/scheduler_core/lib/src/application/application_recovery.dart b/packages/scheduler_core/lib/src/application/application_recovery.dart index 021891c..e2ca4ee 100644 --- a/packages/scheduler_core/lib/src/application/application_recovery.dart +++ b/packages/scheduler_core/lib/src/application/application_recovery.dart @@ -17,6 +17,7 @@ import '../persistence/repositories.dart'; import '../scheduling/scheduling_engine.dart'; import '../scheduling/task_lifecycle.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'application_recovery/app_open_recovery_outcome.dart'; part 'application_recovery/run_app_open_recovery_request.dart'; part 'application_recovery/app_open_recovery_result.dart'; diff --git a/packages/scheduler_core/lib/src/application/application_recovery/v1_app_open_recovery_use_cases.dart b/packages/scheduler_core/lib/src/application/application_recovery/v1_app_open_recovery_use_cases.dart index b84239a..7d63291 100644 --- a/packages/scheduler_core/lib/src/application/application_recovery/v1_app_open_recovery_use_cases.dart +++ b/packages/scheduler_core/lib/src/application/application_recovery/v1_app_open_recovery_use_cases.dart @@ -42,9 +42,16 @@ class V1AppOpenRecoveryUseCases { ownerId: ownerId, sourceDate: sourceDate, ); + logger.info(() => 'App-open recovery started. ownerId=$ownerId ' + 'operationId=${context.operationId} sourceDate=${sourceDate.toIsoString()} ' + 'targetDate=${targetDate.toIsoString()} snapshotId=$snapshotId'); final existingSnapshot = await repositories.schedulingSnapshots.findById(snapshotId); if (existingSnapshot != null) { + logger.info(() => + 'App-open recovery already processed. ownerId=$ownerId ' + 'operationId=${context.operationId} snapshotId=$snapshotId ' + 'noticeCount=${existingSnapshot.notices.length} changeCount=${existingSnapshot.changes.length}'); return ApplicationResult.success( AppOpenRecoveryResult( outcome: AppOpenRecoveryOutcome.alreadyProcessed, @@ -87,6 +94,10 @@ class V1AppOpenRecoveryUseCases { timeZoneResolver: timeZoneResolver, resolutionOptions: resolutionOptions, ); + logger.debug(() => 'App-open recovery loaded source and target state. ' + 'ownerId=$ownerId taskCount=${tasks.length} blockCount=${blocks.length} ' + 'overrideCount=${overrides.length} ' + 'lockedIntervalCount=${lockedExpansion.schedulingIntervals.length}'); final input = SchedulingInput( tasks: tasks, window: targetWindow, @@ -101,6 +112,10 @@ class V1AppOpenRecoveryUseCases { if (schedulingResult.outcomeCode == SchedulingOutcomeCode.overflow || schedulingResult.outcomeCode == SchedulingOutcomeCode.noSlot) { + logger.warn(() => 'App-open recovery could not place rollover tasks. ' + 'ownerId=$ownerId operationId=${context.operationId} ' + 'snapshotId=$snapshotId outcome=${schedulingResult.outcomeCode.name} ' + 'noticeCount=${schedulingResult.notices.length}'); return ApplicationResult.failure( ApplicationFailure( code: ApplicationFailureCode.noSlot, @@ -135,9 +150,16 @@ class V1AppOpenRecoveryUseCases { operationName: 'appOpenRecovery', ); + logger.debug(() => 'Persisting app-open recovery. ownerId=$ownerId ' + 'operationId=${context.operationId} snapshotId=$snapshotId ' + 'changedTaskCount=${changedTasks.length} activityCount=${activities.length} ' + 'noticeCount=${snapshot.notices.length} changeCount=${schedulingResult.changes.length}'); await repositories.tasks.saveAll(changedTasks); await repositories.taskActivities.saveAll(activities); await repositories.schedulingSnapshots.save(snapshot); + logger.info(() => 'App-open recovery completed. ownerId=$ownerId ' + 'operationId=${context.operationId} outcome=${rolloverNotice == null ? AppOpenRecoveryOutcome.noUnfinishedFlexibleTasks.name : AppOpenRecoveryOutcome.rolledOver.name} ' + 'changedTaskCount=${changedTasks.length} activityCount=${activities.length}'); return ApplicationResult.success( AppOpenRecoveryResult( @@ -198,12 +220,17 @@ Future _ownerSettingsOrDefault( ApplicationUnitOfWorkRepositories repositories, OwnerTimeZoneContext ownerTimeZone, ) async { - return await repositories.ownerSettings - .findByOwnerId(ownerTimeZone.ownerId) ?? - OwnerSettings( - ownerId: ownerTimeZone.ownerId, - timeZoneId: ownerTimeZone.timeZoneId, - ); + final settings = + await repositories.ownerSettings.findByOwnerId(ownerTimeZone.ownerId); + if (settings != null) { + return settings; + } + logger.finer(() => 'Owner settings missing during recovery; using defaults. ' + 'ownerId=${ownerTimeZone.ownerId} timeZoneId=${ownerTimeZone.timeZoneId}'); + return OwnerSettings( + ownerId: ownerTimeZone.ownerId, + timeZoneId: ownerTimeZone.timeZoneId, + ); } /// Top-level helper that performs the `_loadSourceAndTargetTasks` operation for this file. @@ -213,6 +240,11 @@ Future> _loadSourceAndTargetTasks( required SchedulingWindow sourceWindow, required SchedulingWindow targetWindow, }) async { + logger.debug(() => 'Loading recovery source and target tasks. ' + 'sourceStart=${sourceWindow.start.toIso8601String()} ' + 'sourceEnd=${sourceWindow.end.toIso8601String()} ' + 'targetStart=${targetWindow.start.toIso8601String()} ' + 'targetEnd=${targetWindow.end.toIso8601String()}'); final byId = {}; for (final task in await repositories.tasks.findScheduledInWindow( sourceWindow, @@ -224,6 +256,8 @@ Future> _loadSourceAndTargetTasks( )) { byId[task.id] = task; } + logger.debug(() => + 'Recovery source and target tasks loaded. taskCount=${byId.length}'); return List.unmodifiable(byId.values); } @@ -249,8 +283,12 @@ SchedulingNotice? _rolloverNotice({ .map((change) => change.taskId) .toSet(); if (rolledTaskIds.isEmpty) { + logger.finer( + () => 'No rollover notice needed; no tasks moved from source day.'); return null; } + logger.debug( + () => 'Rollover notice created. rolledTaskCount=${rolledTaskIds.length}'); return SchedulingNotice( '${rolledTaskIds.length} unfinished flexible tasks were moved to today.', diff --git a/packages/scheduler_core/lib/src/persistence/document_migration.dart b/packages/scheduler_core/lib/src/persistence/document_migration.dart index b57cefe..f7fd9da 100644 --- a/packages/scheduler_core/lib/src/persistence/document_migration.dart +++ b/packages/scheduler_core/lib/src/persistence/document_migration.dart @@ -13,6 +13,7 @@ library; import 'document_mapping.dart'; import 'persistence_contract.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'document_migration/codes/document_migration_entity.dart'; part 'document_migration/codes/document_migration_status.dart'; part 'document_migration/codes/document_migration_failure_code.dart'; diff --git a/packages/scheduler_core/lib/src/persistence/document_migration/service/v1_document_migration_service.dart b/packages/scheduler_core/lib/src/persistence/document_migration/service/v1_document_migration_service.dart index 9c71f0a..7930dca 100644 --- a/packages/scheduler_core/lib/src/persistence/document_migration/service/v1_document_migration_service.dart +++ b/packages/scheduler_core/lib/src/persistence/document_migration/service/v1_document_migration_service.dart @@ -80,8 +80,14 @@ class V1DocumentMigrationService { required void Function(Map document) validateCurrent, }) { final documentId = _documentId(document); + logger.debug(() => 'Document migration started. ' + 'entity=${entity.name} documentId=$documentId ' + 'ownerId=$ownerId migratedAt=${migratedAt.toIso8601String()}'); final schemaRead = _readSchemaVersion(document); if (schemaRead.failure != null) { + logger.warn(() => 'Document migration failed schema version read. ' + 'entity=${entity.name} documentId=$documentId ' + 'detailCode=${schemaRead.failure}'); return _failed( entity: entity, documentId: documentId, @@ -93,10 +99,15 @@ class V1DocumentMigrationService { } final fromVersion = schemaRead.version; + logger.finer(() => 'Document migration schema version resolved. ' + 'entity=${entity.name} documentId=$documentId fromSchemaVersion=$fromVersion'); if (fromVersion == v1SchemaVersion) { try { final copy = _deepCopyDocument(document); validateCurrent(copy); + logger.debug(() => + 'Document migration skipped; document already current. ' + 'entity=${entity.name} documentId=$documentId fromSchemaVersion=$fromVersion'); return DocumentMigrationResult( document: copy, report: DocumentMigrationReport( @@ -107,6 +118,11 @@ class V1DocumentMigrationService { ), ); } on DocumentMappingException catch (error) { + logger.warn( + () => 'Document migration failed current document validation. ' + 'entity=${entity.name} documentId=$documentId ' + 'fromSchemaVersion=$fromVersion mappingCode=${error.code.name} ' + 'fieldName=${error.fieldName} detailCode=${error.detailCode}'); return _failedFromMapping( entity: entity, documentId: documentId, @@ -118,6 +134,9 @@ class V1DocumentMigrationService { } if (fromVersion > v1SchemaVersion || fromVersion < 0) { + logger.warn(() => + 'Document migration rejected unsupported schema version. ' + 'entity=${entity.name} documentId=$documentId fromSchemaVersion=$fromVersion'); return _failed( entity: entity, documentId: documentId, @@ -129,6 +148,9 @@ class V1DocumentMigrationService { } if (fromVersion != 0) { + logger.warn(() => + 'Document migration rejected unsupported schema version. ' + 'entity=${entity.name} documentId=$documentId fromSchemaVersion=$fromVersion'); return _failed( entity: entity, documentId: documentId, @@ -144,6 +166,10 @@ class V1DocumentMigrationService { try { migrated = migrateV0(document, notes); } on _LegacyDocumentException catch (error) { + logger.warn(() => 'Document migration failed legacy document validation. ' + 'entity=${entity.name} documentId=$documentId ' + 'fromSchemaVersion=$fromVersion fieldName=${error.fieldName} ' + 'detailCode=${error.detailCode}'); return _failed( entity: entity, documentId: documentId, @@ -157,6 +183,11 @@ class V1DocumentMigrationService { try { validateCurrent(migrated); } on DocumentMappingException catch (error) { + logger + .warn(() => 'Document migration failed migrated document validation. ' + 'entity=${entity.name} documentId=$documentId ' + 'fromSchemaVersion=$fromVersion mappingCode=${error.code.name} ' + 'fieldName=${error.fieldName} detailCode=${error.detailCode}'); return _failedFromMapping( entity: entity, documentId: documentId, @@ -166,6 +197,9 @@ class V1DocumentMigrationService { ); } + logger.debug(() => 'Document migration finished. ' + 'entity=${entity.name} documentId=$documentId fromSchemaVersion=$fromVersion ' + 'toSchemaVersion=$v1SchemaVersion noteCount=${notes.length}'); return DocumentMigrationResult( document: migrated, report: DocumentMigrationReport( diff --git a/packages/scheduler_core/lib/src/scheduling/child_tasks.dart b/packages/scheduler_core/lib/src/scheduling/child_tasks.dart index f0abef4..9cbb071 100644 --- a/packages/scheduler_core/lib/src/scheduling/child_tasks.dart +++ b/packages/scheduler_core/lib/src/scheduling/child_tasks.dart @@ -13,6 +13,7 @@ library; import '../domain/models.dart'; import 'task_lifecycle.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'child_tasks/models/child_task_entry.dart'; part 'child_tasks/requests/child_task_break_up_request.dart'; part 'child_tasks/results/child_task_break_up_result.dart'; diff --git a/packages/scheduler_core/lib/src/scheduling/child_tasks/services/child_task_break_up_service.dart b/packages/scheduler_core/lib/src/scheduling/child_tasks/services/child_task_break_up_service.dart index 23fa5ce..a89d871 100644 --- a/packages/scheduler_core/lib/src/scheduling/child_tasks/services/child_task_break_up_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/child_tasks/services/child_task_break_up_service.dart @@ -17,8 +17,14 @@ class ChildTaskBreakUpService { required List tasks, required ChildTaskBreakUpRequest request, }) { + logger.debug( + () => 'Breaking up parent task. parentTaskId=${request.parentTaskId} ' + 'entryCount=${request.entries.length} taskCount=${tasks.length} ' + 'operationId=${request.operationId}'); final parent = _taskById(tasks, request.parentTaskId); if (parent == null) { + logger.warn(() => 'Child task break-up failed: parent not found. ' + 'parentTaskId=${request.parentTaskId} operationId=${request.operationId}'); throw ArgumentError.value( request.parentTaskId, 'parentTaskId', @@ -26,6 +32,8 @@ class ChildTaskBreakUpService { ); } if (request.entries.isEmpty) { + logger.warn(() => 'Child task break-up failed: no child entries. ' + 'parentTaskId=${request.parentTaskId} operationId=${request.operationId}'); throw ArgumentError.value( request.entries, 'entries', @@ -38,9 +46,14 @@ class ChildTaskBreakUpService { for (final entry in request.entries) { final childId = entry.id.trim(); if (childId.isEmpty) { + logger.warn(() => 'Child task break-up failed: blank child id. ' + 'parentTaskId=${parent.id} operationId=${request.operationId}'); throw ArgumentError.value(entry.id, 'id', 'Child id is required.'); } if (childId == parent.id) { + logger + .warn(() => 'Child task break-up failed: child id matched parent. ' + 'parentTaskId=${parent.id} operationId=${request.operationId}'); throw ArgumentError.value( entry.id, 'id', @@ -48,6 +61,9 @@ class ChildTaskBreakUpService { ); } if (!requestedIds.add(childId)) { + logger.warn(() => 'Child task break-up failed: duplicate child id. ' + 'parentTaskId=${parent.id} childTaskId=$childId ' + 'operationId=${request.operationId}'); throw ArgumentError.value( entry.id, 'id', @@ -55,6 +71,10 @@ class ChildTaskBreakUpService { ); } if (existingIds.contains(childId)) { + logger + .warn(() => 'Child task break-up failed: child id already exists. ' + 'parentTaskId=${parent.id} childTaskId=$childId ' + 'operationId=${request.operationId}'); throw ArgumentError.value( entry.id, 'id', @@ -66,6 +86,9 @@ class ChildTaskBreakUpService { final childTasks = request.entries .map((entry) => entry.toTask(parent: parent)) .toList(growable: false); + logger.debug(() => 'Parent task break-up produced children. ' + 'parentTaskId=${parent.id} childCount=${childTasks.length} ' + 'operationId=${request.operationId}'); return ChildTaskBreakUpResult( tasks: List.unmodifiable([...tasks, ...childTasks]), diff --git a/packages/scheduler_core/lib/src/scheduling/child_tasks/services/child_task_completion_service.dart b/packages/scheduler_core/lib/src/scheduling/child_tasks/services/child_task_completion_service.dart index 9b8509a..5e8dfbc 100644 --- a/packages/scheduler_core/lib/src/scheduling/child_tasks/services/child_task_completion_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/child_tasks/services/child_task_completion_service.dart @@ -32,19 +32,28 @@ class ChildTaskCompletionService { Iterable appliedActivityIds = const [], }) { final now = updatedAt ?? clock.now(); + logger.debug(() => 'Completing child task. childTaskId=$childTaskId ' + 'taskCount=${tasks.length} operationId=$operationId ' + 'updatedAt=${now.toIso8601String()}'); final child = _taskById(tasks, childTaskId); if (child == null) { + logger.warn(() => 'Child completion failed: task not found. ' + 'childTaskId=$childTaskId operationId=$operationId'); throw ArgumentError.value(childTaskId, 'childTaskId', 'Task not found.'); } final parentId = child.parentTaskId; if (parentId == null) { + logger.warn(() => 'Child completion failed: task has no parent. ' + 'childTaskId=$childTaskId operationId=$operationId'); throw ArgumentError.value( childTaskId, 'childTaskId', 'Task is not a child.'); } final parent = _taskById(tasks, parentId); if (parent == null) { + logger.warn(() => 'Child completion failed: parent not found. ' + 'childTaskId=$childTaskId parentTaskId=$parentId operationId=$operationId'); throw ArgumentError.value(parentId, 'parentTaskId', 'Parent not found.'); } @@ -69,6 +78,9 @@ class ChildTaskCompletionService { final outcomes = [childTransition.outcomeCode]; if (!shouldCompleteParent) { + logger.debug(() => 'Child task completed without parent auto-complete. ' + 'childTaskId=${child.id} parentTaskId=${parent.id} ' + 'childApplied=${childTransition.applied} operationId=$opId'); return ChildTaskCompletionResult( tasks: List.unmodifiable(withChildCompleted), changedTaskIds: childTransition.applied ? [child.id] : const [], @@ -100,6 +112,10 @@ class ChildTaskCompletionService { if (parentTransition.applied) parent.id, ]; + logger.debug(() => 'Child task completion auto-completed parent. ' + 'childTaskId=${child.id} parentTaskId=${parent.id} ' + 'changedCount=${changedTaskIds.length} operationId=$opId'); + return ChildTaskCompletionResult( tasks: List.unmodifiable(completedTasks), changedTaskIds: List.unmodifiable(changedTaskIds), @@ -120,12 +136,19 @@ class ChildTaskCompletionService { Iterable existingActivities = const [], Iterable appliedActivityIds = const [], }) { + logger.debug(() => 'Completing parent from child. childTaskId=$childTaskId ' + 'taskCount=${tasks.length} operationId=$operationId'); final child = _taskById(tasks, childTaskId); if (child == null) { + logger.warn(() => 'Parent-from-child completion failed: task not found. ' + 'childTaskId=$childTaskId operationId=$operationId'); throw ArgumentError.value(childTaskId, 'childTaskId', 'Task not found.'); } final parentId = child.parentTaskId; if (parentId == null) { + logger.warn( + () => 'Parent-from-child completion failed: task has no parent. ' + 'childTaskId=$childTaskId operationId=$operationId'); throw ArgumentError.value( childTaskId, 'childTaskId', @@ -155,8 +178,13 @@ class ChildTaskCompletionService { Iterable appliedActivityIds = const [], }) { final now = updatedAt ?? clock.now(); + logger.debug(() => 'Completing parent task. parentTaskId=$parentTaskId ' + 'taskCount=${tasks.length} initiatingChildTaskId=$initiatingChildTaskId ' + 'operationId=$operationId updatedAt=${now.toIso8601String()}'); final parent = _taskById(tasks, parentTaskId); if (parent == null) { + logger.warn(() => 'Parent completion failed: parent not found. ' + 'parentTaskId=$parentTaskId operationId=$operationId'); throw ArgumentError.value( parentTaskId, 'parentTaskId', 'Parent not found.'); } @@ -164,6 +192,10 @@ class ChildTaskCompletionService { final directChildren = ChildTaskView(tasks: tasks).childrenOf(parent); if (initiatingChildTaskId != null && !directChildren.any((child) => child.id == initiatingChildTaskId)) { + logger.warn( + () => 'Parent completion failed: initiating child is not direct. ' + 'parentTaskId=${parent.id} childTaskId=$initiatingChildTaskId ' + 'operationId=$operationId'); throw ArgumentError.value( initiatingChildTaskId, 'initiatingChildTaskId', @@ -234,6 +266,12 @@ class ChildTaskCompletionService { updatedTasks.add(task); } + logger.debug( + () => 'Parent task completion finished. parentTaskId=${parent.id} ' + 'directChildCount=${directChildren.length} ' + 'forceCompletedCount=${forceCompletedChildIds.length} ' + 'changedCount=${changedTaskIds.length} operationId=$opId'); + return ChildTaskCompletionResult( tasks: List.unmodifiable(updatedTasks), changedTaskIds: List.unmodifiable(changedTaskIds), diff --git a/packages/scheduler_core/lib/src/scheduling/free_slots.dart b/packages/scheduler_core/lib/src/scheduling/free_slots.dart index 7278c70..79bfb4d 100644 --- a/packages/scheduler_core/lib/src/scheduling/free_slots.dart +++ b/packages/scheduler_core/lib/src/scheduling/free_slots.dart @@ -13,6 +13,7 @@ library; import '../domain/models.dart'; import '../domain/occupancy_policy.dart'; import 'scheduling_engine.dart'; +import '../logging/focus_flow_logger.dart'; part 'free_slots/required_commitment_schedule_status.dart'; part 'free_slots/protected_free_slot_conflict.dart'; part 'free_slots/required_commitment_schedule_result.dart'; diff --git a/packages/scheduler_core/lib/src/scheduling/free_slots/free_slot_service.dart b/packages/scheduler_core/lib/src/scheduling/free_slots/free_slot_service.dart index 6e4b32f..f9cf46c 100644 --- a/packages/scheduler_core/lib/src/scheduling/free_slots/free_slot_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/free_slots/free_slot_service.dart @@ -19,6 +19,9 @@ class FreeSlotService { String projectId = 'inbox', DateTime? updatedAt, }) { + logger.debug(() => 'Creating protected free slot. taskId=$id ' + 'start=${start.toIso8601String()} end=${end.toIso8601String()} ' + 'projectId=$projectId'); final interval = TimeInterval(start: start, end: end, label: id); return Task( @@ -45,7 +48,12 @@ class FreeSlotService { String? title, String? projectId, }) { + logger.debug(() => 'Updating protected free slot. taskId=${freeSlot.id} ' + 'start=${start.toIso8601String()} end=${end.toIso8601String()} ' + 'projectId=$projectId hasTitle=${title != null}'); if (freeSlot.type != TaskType.freeSlot) { + logger.error(() => 'Free slot update failed: invalid task type. ' + 'taskId=${freeSlot.id} taskType=${freeSlot.type.name}'); throw ArgumentError.value( freeSlot.type, 'freeSlot.type', @@ -78,8 +86,14 @@ class FreeSlotService { required DateTime end, DateTime? updatedAt, }) { + logger.debug(() => 'Scheduling required commitment. taskId=$taskId ' + 'start=${start.toIso8601String()} end=${end.toIso8601String()} ' + 'taskCount=${input.tasks.length}'); final task = _taskById(input.tasks, taskId); if (task == null) { + logger + .warn(() => 'Required commitment scheduling failed: task not found. ' + 'taskId=$taskId'); return _unchangedRequiredResult( input: input, status: RequiredCommitmentScheduleStatus.taskNotFound, @@ -94,6 +108,9 @@ class FreeSlotService { } if (!task.isRequiredVisible) { + logger.warn( + () => 'Required commitment scheduling failed: invalid task type. ' + 'taskId=${task.id} taskType=${task.type.name}'); return _unchangedRequiredResult( input: input, status: RequiredCommitmentScheduleStatus.invalidTaskType, @@ -171,6 +188,11 @@ class FreeSlotService { ), ]; + logger.debug(() => + 'Required commitment scheduling finished. taskId=${task.id} ' + 'status=${conflicts.isEmpty ? RequiredCommitmentScheduleStatus.scheduled.name : RequiredCommitmentScheduleStatus.scheduledWithProtectedFreeSlotConflict.name} ' + 'conflictCount=${conflicts.length} changeCount=${changes.length}'); + return RequiredCommitmentScheduleResult( status: conflicts.isEmpty ? RequiredCommitmentScheduleStatus.scheduled diff --git a/packages/scheduler_core/lib/src/scheduling/quick_capture.dart b/packages/scheduler_core/lib/src/scheduling/quick_capture.dart index 8c04100..4afb0d9 100644 --- a/packages/scheduler_core/lib/src/scheduling/quick_capture.dart +++ b/packages/scheduler_core/lib/src/scheduling/quick_capture.dart @@ -13,6 +13,7 @@ library; import '../domain/models.dart'; import 'scheduling_engine.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'quick_capture/quick_capture_status.dart'; part 'quick_capture/quick_capture_request.dart'; part 'quick_capture/quick_capture_result.dart'; diff --git a/packages/scheduler_core/lib/src/scheduling/quick_capture/quick_capture_service.dart b/packages/scheduler_core/lib/src/scheduling/quick_capture/quick_capture_service.dart index 6e205fc..c184a36 100644 --- a/packages/scheduler_core/lib/src/scheduling/quick_capture/quick_capture_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/quick_capture/quick_capture_service.dart @@ -41,6 +41,10 @@ class QuickCaptureService { SchedulingInput? schedulingInput, DateTime? updatedAt, }) { + logger.debug(() => 'Quick capture requested. taskId=${request.id} ' + 'projectId=${request.projectId} taskType=${request.type.name} ' + 'hasDuration=${request.durationMinutes != null} ' + 'addToNextAvailableSlot=${request.addToNextAvailableSlot}'); final capturedTaskWithoutDuration = Task.quickCapture( id: request.id, title: request.title, @@ -55,6 +59,9 @@ class QuickCaptureService { ); if (request.durationMinutes != null && request.durationMinutes! <= 0) { + logger.warn(() => + 'Quick capture validation failed: non-positive duration. ' + 'taskId=${request.id} durationMinutes=${request.durationMinutes}'); return QuickCaptureResult( task: capturedTaskWithoutDuration, status: QuickCaptureStatus.validationError, @@ -67,6 +74,8 @@ class QuickCaptureService { ); if (!request.addToNextAvailableSlot) { + logger.debug( + () => 'Quick capture added to backlog. taskId=${capturedTask.id}'); return QuickCaptureResult( task: capturedTask, status: QuickCaptureStatus.addedToBacklog, @@ -74,6 +83,9 @@ class QuickCaptureService { } if (request.durationMinutes == null || request.durationMinutes! <= 0) { + logger.warn( + () => 'Quick capture scheduling validation failed: missing duration. ' + 'taskId=${capturedTask.id}'); return QuickCaptureResult( task: capturedTask, status: QuickCaptureStatus.validationError, @@ -82,6 +94,9 @@ class QuickCaptureService { } if (request.type != TaskType.flexible) { + logger.warn(() => + 'Quick capture scheduling validation failed: non-flexible task. ' + 'taskId=${capturedTask.id} taskType=${request.type.name}'); return QuickCaptureResult( task: capturedTask, status: QuickCaptureStatus.validationError, @@ -90,6 +105,9 @@ class QuickCaptureService { } if (schedulingInput == null) { + logger.warn(() => + 'Quick capture scheduling validation failed: missing scheduling input. ' + 'taskId=${capturedTask.id}'); return QuickCaptureResult( task: capturedTask, status: QuickCaptureStatus.validationError, @@ -110,6 +128,9 @@ class QuickCaptureService { final scheduledTask = _taskById(result.tasks, capturedTask.id); if (scheduledTask == null || scheduledTask.isBacklog) { + logger.warn(() => 'Quick capture scheduling did not place task. ' + 'taskId=${capturedTask.id} outcome=${result.outcomeCode.name} ' + 'noticeCount=${result.notices.length}'); return QuickCaptureResult( task: capturedTask, status: QuickCaptureStatus.validationError, @@ -118,6 +139,10 @@ class QuickCaptureService { ); } + logger.debug(() => 'Quick capture scheduled. taskId=${scheduledTask.id} ' + 'start=${scheduledTask.scheduledStart?.toIso8601String()} ' + 'end=${scheduledTask.scheduledEnd?.toIso8601String()} ' + 'changeCount=${result.changes.length} noticeCount=${result.notices.length}'); return QuickCaptureResult( task: scheduledTask, status: QuickCaptureStatus.scheduled, @@ -142,10 +167,16 @@ class QuickCaptureService { }) { final generator = idGenerator; if (generator == null) { + logger.error( + () => 'Quick capture rejected because id generator is missing.'); throw StateError('Quick capture needs an id generator.'); } final now = createdAt ?? updatedAt ?? clock.now(); + logger.debug(() => 'Quick capture new task requested. ' + 'hasTitle=${title.trim().isNotEmpty} projectId=$projectId ' + 'type=${type.name} addToNextAvailableSlot=$addToNextAvailableSlot ' + 'occurredAt=${now.toIso8601String()}'); return capture( QuickCaptureRequest( diff --git a/packages/scheduler_core/lib/src/scheduling/reminder_policy.dart b/packages/scheduler_core/lib/src/scheduling/reminder_policy.dart index 584b54c..b3d6273 100644 --- a/packages/scheduler_core/lib/src/scheduling/reminder_policy.dart +++ b/packages/scheduler_core/lib/src/scheduling/reminder_policy.dart @@ -12,6 +12,7 @@ library; import '../domain/models.dart'; import '../domain/occupancy_policy.dart'; +import '../logging/focus_flow_logger.dart'; part 'reminder_policy/directives/reminder_directive_action.dart'; part 'reminder_policy/directives/reminder_directive_reason.dart'; part 'reminder_policy/profiles/effective_reminder_profile.dart'; diff --git a/packages/scheduler_core/lib/src/scheduling/reminder_policy/services/reminder_policy_service.dart b/packages/scheduler_core/lib/src/scheduling/reminder_policy/services/reminder_policy_service.dart index f60bf11..3970deb 100644 --- a/packages/scheduler_core/lib/src/scheduling/reminder_policy/services/reminder_policy_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/reminder_policy/services/reminder_policy_service.dart @@ -25,6 +25,8 @@ class ReminderPolicyService { }) { final override = task.reminderOverride; if (override != null) { + logger.finer(() => 'Reminder profile resolved from task override. ' + 'taskId=${task.id} profile=${override.name}'); return EffectiveReminderProfile( profile: override, source: EffectiveReminderProfileSource.taskOverride, @@ -32,12 +34,17 @@ class ReminderPolicyService { } if (project != null) { + logger.finer(() => 'Reminder profile resolved from project default. ' + 'taskId=${task.id} projectId=${project.id} ' + 'profile=${project.defaultReminderProfile.name}'); return EffectiveReminderProfile( profile: project.defaultReminderProfile, source: EffectiveReminderProfileSource.projectDefault, ); } + logger.finer(() => 'Reminder profile resolved from fallback. ' + 'taskId=${task.id} profile=${fallbackProfile.name}'); return EffectiveReminderProfile( profile: fallbackProfile, source: EffectiveReminderProfileSource.fallback, @@ -51,11 +58,19 @@ class ReminderPolicyService { ProjectProfile? project, Iterable contextTasks = const [], }) { + logger.debug(() => 'Reminder directive evaluation started. ' + 'taskId=${task.id} type=${task.type.name} status=${task.status.name} ' + 'now=${now.toIso8601String()}'); final effective = resolveEffectiveProfile(task: task, project: project); final activeFreeSlot = _activeProtectedFreeSlot( now: now, contextTasks: contextTasks, ); + if (activeFreeSlot != null) { + logger.finer(() => 'Reminder directive found active protected free slot. ' + 'taskId=${task.id} freeSlotTaskId=${activeFreeSlot.taskId} ' + 'freeSlotEnd=${activeFreeSlot.interval?.end.toIso8601String()}'); + } return _directiveForTask( task: task, @@ -81,6 +96,12 @@ class ReminderPolicyService { required ReminderDirectiveReason reason, DateTime? nextEligibleAt, }) { + logger.debug(() => 'Reminder directive evaluation finished. ' + 'taskId=${task.id} action=${action.name} reason=${reason.name} ' + 'profile=${effective.profile.name} source=${effective.source.name} ' + 'hasSchedule=${start != null && end != null} ' + 'nextEligibleAt=${nextEligibleAt?.toIso8601String()} ' + 'protectedFreeSlotTaskId=${activeFreeSlot?.taskId}'); return ReminderDirective( taskId: task.id, action: action, @@ -165,6 +186,8 @@ class ReminderPolicyService { if (task.type == TaskType.critical && effective.profile == ReminderProfile.strict) { + logger.finer(() => 'Reminder directive requires acknowledgement. ' + 'taskId=${task.id} profile=${effective.profile.name}'); return build( action: ReminderDirectiveAction.requireAcknowledgement, reason: ReminderDirectiveReason.requireRequiredAcknowledgement, @@ -191,6 +214,9 @@ class ReminderPolicyService { }) { if (task.type == TaskType.critical && effective.profile == ReminderProfile.strict) { + logger.finer(() => + 'Reminder directive requires acknowledgement during protected rest. ' + 'taskId=${task.id} profile=${effective.profile.name}'); return build( action: ReminderDirectiveAction.requireAcknowledgement, reason: ReminderDirectiveReason.requireRequiredAcknowledgement, @@ -199,6 +225,10 @@ class ReminderPolicyService { if (task.type == TaskType.inflexible && effective.profile == ReminderProfile.gentle) { + logger.finer(() => + 'Reminder directive deferred required task during protected rest. ' + 'taskId=${task.id} profile=${effective.profile.name} ' + 'nextEligibleAt=${freeSlotEnd?.toIso8601String()}'); return build( action: ReminderDirectiveAction.defer, reason: ReminderDirectiveReason.deferRequiredDuringProtectedRest, diff --git a/packages/scheduler_core/lib/src/scheduling/scheduling_engine.dart b/packages/scheduler_core/lib/src/scheduling/scheduling_engine.dart index 3309442..65db2f3 100644 --- a/packages/scheduler_core/lib/src/scheduling/scheduling_engine.dart +++ b/packages/scheduler_core/lib/src/scheduling/scheduling_engine.dart @@ -22,6 +22,7 @@ import '../domain/models.dart'; import '../domain/occupancy_policy.dart'; import 'task_lifecycle.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'scheduling_engine/codes/notices/scheduling_notice_type.dart'; part 'scheduling_engine/codes/operations/scheduling_operation_code.dart'; part 'scheduling_engine/codes/operations/scheduling_outcome_code.dart'; diff --git a/packages/scheduler_core/lib/src/scheduling/scheduling_engine/engine/scheduling_engine.dart b/packages/scheduler_core/lib/src/scheduling/scheduling_engine/engine/scheduling_engine.dart index 332daec..a420756 100644 --- a/packages/scheduler_core/lib/src/scheduling/scheduling_engine/engine/scheduling_engine.dart +++ b/packages/scheduler_core/lib/src/scheduling/scheduling_engine/engine/scheduling_engine.dart @@ -45,10 +45,16 @@ class SchedulingEngine { required String taskId, DateTime? updatedAt, }) { + logger.debug(() => 'Scheduling backlog task into next available slot. ' + 'taskId=$taskId taskCount=${input.tasks.length} ' + 'windowStart=${input.window.start.toIso8601String()} ' + 'windowEnd=${input.window.end.toIso8601String()}'); // Step 1: resolve and validate the task. The engine does not create tasks; // quick capture or persistence code is responsible for adding it to the list. final task = _taskById(input.tasks, taskId); if (task == null) { + logger.warn( + () => 'Backlog scheduling failed: task not found. taskId=$taskId'); return _unchangedResult( input, SchedulingNotice( @@ -64,6 +70,8 @@ class SchedulingEngine { } if (!task.isFlexible || !task.isBacklog) { + logger.warn(() => 'Backlog scheduling failed: invalid task state. ' + 'taskId=${task.id} taskType=${task.type.name} taskStatus=${task.status.name}'); return _unchangedResult( input, SchedulingNotice( @@ -80,6 +88,8 @@ class SchedulingEngine { final taskDuration = _durationFromMinutes(task.durationMinutes); if (taskDuration == null) { + logger.warn(() => 'Backlog scheduling failed: missing positive duration. ' + 'taskId=${task.id} durationMinutes=${task.durationMinutes}'); return _unchangedResult( input, SchedulingNotice( @@ -103,6 +113,8 @@ class SchedulingEngine { ); if (placement == null) { + logger.warn(() => 'Backlog scheduling failed: no available slot. ' + 'taskId=${task.id} blockedIntervalCount=${input.blockedIntervals.length}'); return _unchangedResult( input, SchedulingNotice( @@ -140,10 +152,15 @@ class SchedulingEngine { DateTime? earliestStart, bool countAsManualPush = true, }) { + logger.debug(() => 'Pushing flexible task to next available slot. ' + 'taskId=$taskId taskCount=${input.tasks.length} ' + 'earliestStart=${earliestStart?.toIso8601String()} ' + 'countAsManualPush=$countAsManualPush'); // Resolve the selected task by id so UI code only needs to pass a stable // identifier, not object references. final task = _taskById(input.tasks, taskId); if (task == null) { + logger.warn(() => 'Flexible push failed: task not found. taskId=$taskId'); return _unchangedResult( input, SchedulingNotice( @@ -159,6 +176,8 @@ class SchedulingEngine { } if (!task.isFlexible || task.status != TaskStatus.planned) { + logger.warn(() => 'Flexible push failed: invalid task state. ' + 'taskId=${task.id} taskType=${task.type.name} taskStatus=${task.status.name}'); return _unchangedResult( input, SchedulingNotice( @@ -176,6 +195,9 @@ class SchedulingEngine { final currentInterval = _scheduledIntervalFor(task); if (currentInterval == null || (earliestStart == null && !input.window.contains(currentInterval))) { + logger.warn(() => + 'Flexible push failed: missing or out-of-window scheduled slot. ' + 'taskId=${task.id} hasCurrentInterval=${currentInterval != null}'); return _unchangedResult( input, SchedulingNotice( @@ -191,6 +213,9 @@ class SchedulingEngine { } if (currentInterval.duration.inMicroseconds <= 0) { + logger.warn(() => + 'Flexible push failed: non-positive scheduled duration. ' + 'taskId=${task.id} durationMicroseconds=${currentInterval.duration.inMicroseconds}'); return _unchangedResult( input, SchedulingNotice( @@ -213,6 +238,8 @@ class SchedulingEngine { ); if (placement == null) { + logger.warn(() => + 'Flexible push failed: no available slot today. taskId=${task.id}'); return _unchangedResult( input, SchedulingNotice( @@ -253,8 +280,13 @@ class SchedulingEngine { required String taskId, DateTime? updatedAt, }) { + logger.debug(() => 'Pushing flexible task to tomorrow top of queue. ' + 'taskId=$taskId taskCount=${input.tasks.length} ' + 'windowStart=${input.window.start.toIso8601String()} ' + 'windowEnd=${input.window.end.toIso8601String()}'); final task = _taskById(input.tasks, taskId); if (task == null) { + logger.warn(() => 'Tomorrow push failed: task not found. taskId=$taskId'); return _unchangedResult( input, SchedulingNotice( @@ -270,6 +302,8 @@ class SchedulingEngine { } if (!task.isFlexible || task.status != TaskStatus.planned) { + logger.warn(() => 'Tomorrow push failed: invalid task state. ' + 'taskId=${task.id} taskType=${task.type.name} taskStatus=${task.status.name}'); return _unchangedResult( input, SchedulingNotice( @@ -287,6 +321,8 @@ class SchedulingEngine { final taskDuration = _scheduledIntervalFor(task)?.duration ?? _durationFromMinutes(task.durationMinutes); if (taskDuration == null || taskDuration.inMicroseconds <= 0) { + logger.warn(() => 'Tomorrow push failed: missing positive duration. ' + 'taskId=${task.id} durationMinutes=${task.durationMinutes}'); return _unchangedResult( input, SchedulingNotice( @@ -308,6 +344,8 @@ class SchedulingEngine { ); if (placement == null) { + logger.warn( + () => 'Tomorrow push failed: no available slot. taskId=${task.id}'); return _unchangedResult( input, SchedulingNotice( @@ -352,6 +390,10 @@ class SchedulingEngine { SchedulingWindow? sourceWindow, DateTime? updatedAt, }) { + logger.debug(() => 'Rolling over unfinished flexible tasks. ' + 'taskCount=${input.tasks.length} targetWindowStart=${input.window.start.toIso8601String()} ' + 'targetWindowEnd=${input.window.end.toIso8601String()} ' + 'hasSourceWindow=${sourceWindow != null}'); // Build the explicit queue of tasks to roll before asking the planner to // place anything. This keeps selection separate from placement. final rolledItems = <_PlacementItem>[]; @@ -388,6 +430,8 @@ class SchedulingEngine { } if (rolledItems.isEmpty) { + logger + .debug(() => 'Rollover finished with no unfinished flexible tasks.'); return SchedulingResult( tasks: input.tasks, operationCode: SchedulingOperationCode.rollOverUnfinishedFlexibleTasks, @@ -408,6 +452,9 @@ class SchedulingEngine { ); if (placement == null) { + logger.warn( + () => 'Rollover failed: unfinished flexible tasks could not fit. ' + 'rolledCount=${rolledItems.length}'); return _unchangedResult( input, SchedulingNotice( @@ -434,6 +481,8 @@ class SchedulingEngine { /// reports any overlap with blocked intervals. It deliberately returns the /// original task list unchanged. SchedulingResult analyzeSchedule(SchedulingInput input) { + logger.debug(() => 'Analyzing schedule. taskCount=${input.tasks.length} ' + 'conflictOccupancyCount=${input.conflictReportingOccupancies.length}'); final overlaps = []; final notices = []; final conflictOccupancies = input.conflictReportingOccupancies; @@ -477,6 +526,9 @@ class SchedulingEngine { } } + logger.debug( + () => 'Schedule analysis finished. overlapCount=${overlaps.length} ' + 'noticeCount=${notices.length}'); return SchedulingResult( tasks: input.tasks, operationCode: SchedulingOperationCode.analyzeSchedule, @@ -495,6 +547,8 @@ class SchedulingEngine { /// reports can distinguish this from a task that was never scheduled. Task moveToBacklog(Task task, {DateTime? updatedAt}) { final now = updatedAt ?? clock.now(); + logger.debug(() => 'Legacy move-to-backlog requested. taskId=${task.id} ' + 'taskStatus=${task.status.name} occurredAt=${now.toIso8601String()}'); final result = _transitionService.apply( task: task, transitionCode: TaskTransitionCode.moveToBacklog, @@ -503,6 +557,8 @@ class SchedulingEngine { 'legacy-move-to-backlog:${task.id}:${now.toIso8601String()}:activity', occurredAt: now, ); + logger.debug(() => 'Legacy move-to-backlog finished. taskId=${task.id} ' + 'outcome=${result.outcomeCode.name} nextStatus=${result.task.status.name}'); return result.applied ? result.task : task; } @@ -512,6 +568,9 @@ class SchedulingEngine { /// actual scheduled slot should change. Task markManuallyPushed(Task task, {DateTime? updatedAt}) { final now = updatedAt ?? clock.now(); + logger.debug( + () => 'Legacy manual push statistic requested. taskId=${task.id} ' + 'occurredAt=${now.toIso8601String()}'); final result = _transitionService.apply( task: task, transitionCode: TaskTransitionCode.manualPush, @@ -520,6 +579,9 @@ class SchedulingEngine { 'legacy-manual-push:${task.id}:${now.toIso8601String()}:activity', occurredAt: now, ); + logger + .debug(() => 'Legacy manual push statistic finished. taskId=${task.id} ' + 'outcome=${result.outcomeCode.name}'); return result.applied ? result.task : task; } @@ -530,6 +592,9 @@ class SchedulingEngine { /// or time block that cannot simply be rescheduled automatically. Task markMissed(Task task, {DateTime? updatedAt}) { final now = updatedAt ?? clock.now(); + logger.debug(() => 'Legacy mark-missed requested. taskId=${task.id} ' + 'taskType=${task.type.name} taskStatus=${task.status.name} ' + 'occurredAt=${now.toIso8601String()}'); final result = _transitionService.apply( task: task, transitionCode: TaskTransitionCode.miss, @@ -537,6 +602,8 @@ class SchedulingEngine { activityId: 'legacy-miss:${task.id}:${now.toIso8601String()}:activity', occurredAt: now, ); + logger.debug(() => 'Legacy mark-missed finished. taskId=${task.id} ' + 'outcome=${result.outcomeCode.name} nextStatus=${result.task.status.name}'); return result.applied ? result.task : task; } @@ -553,6 +620,10 @@ class SchedulingEngine { required Duration duration, required List blocked, }) { + logger.debug(() => 'Finding first open interval. ' + 'windowStart=${windowStart.toIso8601String()} ' + 'windowEnd=${windowEnd.toIso8601String()} ' + 'durationMinutes=${duration.inMinutes} blockedCount=${blocked.length}'); final sortedBlocked = [...blocked] ..sort((a, b) => a.start.compareTo(b.start)); var cursor = windowStart; @@ -745,7 +816,7 @@ _BacklogInsertionPlan? _planFlexiblePush({ }) { final pushPoint = _laterOf( currentInterval.end, - earliestStart == null ? input.window.start : earliestStart, + earliestStart ?? input.window.start, ); final fixedBlocks = [ ...input.blockedIntervals, @@ -999,6 +1070,9 @@ SchedulingResult _applyPlacement({ ); } + logger.debug(() => 'Backlog insertion placement applied. ' + 'insertedTaskId=${insertedTask.id} changeCount=${changes.length} ' + 'noticeCount=${notices.length}'); return SchedulingResult( tasks: List.unmodifiable(updatedTasks), operationCode: @@ -1092,6 +1166,9 @@ SchedulingResult _applyPushPlacement({ ); } + logger.debug(() => 'Flexible push placement applied. ' + 'operationCode=${operationCode.name} pushedTaskId=${pushedTask.id} ' + 'changeCount=${changes.length} noticeCount=${notices.length}'); return SchedulingResult( tasks: List.unmodifiable(updatedTasks), operationCode: operationCode, @@ -1193,6 +1270,8 @@ SchedulingResult _applyRolloverPlacement({ ), ); + logger.debug(() => 'Rollover placement applied. rolledCount=$rolledCount ' + 'changeCount=${changes.length} noticeCount=${notices.length}'); return SchedulingResult( tasks: List.unmodifiable(updatedTasks), operationCode: SchedulingOperationCode.rollOverUnfinishedFlexibleTasks, diff --git a/packages/scheduler_core/lib/src/scheduling/task_actions/services/required_task_action_service.dart b/packages/scheduler_core/lib/src/scheduling/task_actions/services/required_task_action_service.dart index 35874f2..94ef868 100644 --- a/packages/scheduler_core/lib/src/scheduling/task_actions/services/required_task_action_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/task_actions/services/required_task_action_service.dart @@ -37,7 +37,12 @@ class RequiredTaskActionService { List lockedIntervals = const [], Iterable existingActivities = const [], }) { + logger.debug(() => 'Applying required task action. taskId=${task.id} ' + 'action=${action.name} taskType=${task.type.name} status=${task.status.name} ' + 'operationId=$operationId'); if (!task.isRequiredVisible) { + logger.error(() => 'Required task action failed: invalid task type. ' + 'taskId=${task.id} taskType=${task.type.name} action=${action.name}'); throw ArgumentError.value( task.type, 'task.type', @@ -61,6 +66,10 @@ class RequiredTaskActionService { RequiredTaskAction.noLongerRelevant => TaskActivityCode.noLongerRelevant, }; final opId = operationId ?? _defaultOperationId(action.name, task.id, now); + logger.finer( + () => 'Required task action resolved transition. taskId=${task.id} ' + 'action=${action.name} transition=${transitionCode.name} ' + 'operationId=$opId'); final transition = transitionService.apply( task: task, transitionCode: transitionCode, @@ -73,6 +82,11 @@ class RequiredTaskActionService { existingActivities: existingActivities, ); + logger.debug(() => 'Required task action finished. taskId=${task.id} ' + 'action=${action.name} outcome=${transition.outcomeCode.name} ' + 'activityCount=${transition.activities.length} ' + 'removedFromActivePlan=${transition.task.status == TaskStatus.backlog || transition.task.status == TaskStatus.cancelled || transition.task.status == TaskStatus.noLongerRelevant}'); + return RequiredTaskActionResult( action: action, task: transition.task, diff --git a/packages/scheduler_core/lib/src/scheduling/task_actions/services/surprise_task_log_service.dart b/packages/scheduler_core/lib/src/scheduling/task_actions/services/surprise_task_log_service.dart index 7af04ec..7ea05d0 100644 --- a/packages/scheduler_core/lib/src/scheduling/task_actions/services/surprise_task_log_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/task_actions/services/surprise_task_log_service.dart @@ -39,9 +39,16 @@ class SurpriseTaskLogService { bool revealHiddenLockedDetails = false, }) { final now = updatedAt ?? clock.now(); + logger.debug(() => 'Logging surprise task. taskId=${request.id} ' + 'taskCount=${input.tasks.length} hasStartedAt=${request.startedAt != null} ' + 'hasDuration=${request.timeUsedMinutes != null} ' + 'revealHiddenLockedDetails=$revealHiddenLockedDetails'); final existingTask = _taskById(input.tasks, request.id); if (existingTask != null) { if (existingTask.type != TaskType.surprise) { + logger.error(() => + 'Surprise task log failed: id already used by another task type. ' + 'taskId=${request.id} taskType=${existingTask.type.name}'); throw ArgumentError.value( request.id, 'request.id', @@ -49,6 +56,8 @@ class SurpriseTaskLogService { ); } + logger.warn( + () => 'Duplicate surprise task log ignored. taskId=${request.id}'); return SurpriseTaskLogResult( surpriseTask: existingTask, schedulingResult: SchedulingResult( @@ -82,6 +91,8 @@ class SurpriseTaskLogService { var currentTasks = [surpriseTask, ...input.tasks]; if (surpriseInterval == null) { + logger.debug(() => 'Surprise task logged without occupying interval. ' + 'taskId=${surpriseTask.id} activityCount=1'); return SurpriseTaskLogResult( surpriseTask: surpriseTask, schedulingResult: SchedulingResult( @@ -113,6 +124,12 @@ class SurpriseTaskLogService { final movementNotices = []; var usedNormalPushRules = false; + logger.debug(() => + 'Surprise task repair scanning overlaps. taskId=${surpriseTask.id} ' + 'requiredOverlapCount=${requiredOverlaps.length} ' + 'lockedOverlapCount=${lockedOverlaps.length} ' + 'flexibleOverlapCount=${flexibleTaskIds.length}'); + for (final taskId in flexibleTaskIds) { final currentTask = _taskById(currentTasks, taskId); final currentInterval = @@ -120,9 +137,14 @@ class SurpriseTaskLogService { if (currentTask == null || currentInterval == null || !currentInterval.overlaps(surpriseInterval)) { + logger.finer(() => 'Surprise task repair skipped flexible candidate. ' + 'surpriseTaskId=${surpriseTask.id} taskId=$taskId ' + 'hasCurrentTask=${currentTask != null} hasInterval=${currentInterval != null}'); continue; } + logger.finer(() => 'Surprise task repair pushing flexible overlap. ' + 'surpriseTaskId=${surpriseTask.id} taskId=$taskId'); final pushResult = schedulingEngine.pushFlexibleTaskToNextAvailableSlot( input: SchedulingInput( tasks: currentTasks, @@ -157,6 +179,11 @@ class SurpriseTaskLogService { ) .toList(growable: false); + logger.debug(() => 'Surprise task log finished. taskId=${surpriseTask.id} ' + 'outcome=${requiredOverlaps.isEmpty ? SchedulingOutcomeCode.success.name : SchedulingOutcomeCode.conflict.name} ' + 'changeCount=${changes.length} noticeCount=${movementNotices.length + overlapNotices.length + 1} ' + 'requiredOverlapCount=${requiredOverlaps.length} lockedOverlapCount=${lockedOverlaps.length}'); + return SurpriseTaskLogResult( surpriseTask: _taskById(currentTasks, surpriseTask.id) ?? surpriseTask, schedulingResult: SchedulingResult( @@ -196,10 +223,15 @@ class SurpriseTaskLogService { }) { final generator = idGenerator; if (generator == null) { + logger.error(() => 'Surprise task logNew failed: missing id generator.'); throw StateError('Surprise task logging needs an id generator.'); } final now = createdAt ?? updatedAt ?? clock.now(); + logger.debug(() => + 'Logging new surprise task. hasTitle=${title.trim().isNotEmpty} ' + 'hasStartedAt=${startedAt != null} hasDuration=${timeUsedMinutes != null} ' + 'projectId=$projectId'); return log( request: SurpriseTaskLogRequest( @@ -227,6 +259,8 @@ class SurpriseTaskLogService { }) { final trimmedTitle = request.title.trim(); if (trimmedTitle.isEmpty) { + logger.warn(() => 'Surprise task creation failed: blank title. ' + 'taskId=${request.id}'); throw ArgumentError.value(request.title, 'title', 'Title is required.'); } diff --git a/packages/scheduler_core/lib/src/scheduling/task_lifecycle.dart b/packages/scheduler_core/lib/src/scheduling/task_lifecycle.dart index f4ba3bd..c876320 100644 --- a/packages/scheduler_core/lib/src/scheduling/task_lifecycle.dart +++ b/packages/scheduler_core/lib/src/scheduling/task_lifecycle.dart @@ -13,6 +13,7 @@ library; import '../domain/models.dart'; import '../domain/task_statistics.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'task_lifecycle/codes/task_transition_code.dart'; part 'task_lifecycle/codes/task_activity_code.dart'; part 'task_lifecycle/codes/task_transition_outcome_code.dart'; diff --git a/packages/scheduler_core/lib/src/scheduling/task_lifecycle/services/task_transition_service.dart b/packages/scheduler_core/lib/src/scheduling/task_lifecycle/services/task_transition_service.dart index 599ed3c..01939c6 100644 --- a/packages/scheduler_core/lib/src/scheduling/task_lifecycle/services/task_transition_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/task_lifecycle/services/task_transition_service.dart @@ -37,12 +37,19 @@ class TaskTransitionService { Map metadata = const {}, }) { final now = occurredAt ?? clock.now(); + logger.debug(() => 'Applying task transition. ' + 'taskId=${task.id} transition=${transitionCode.name} ' + 'operationId=$operationId taskStatus=${task.status.name} ' + 'occurredAt=${now.toIso8601String()}'); final duplicate = _duplicateActivity( existingActivities: existingActivities, taskId: task.id, operationId: operationId, ); if (duplicate != null) { + logger.warn(() => 'Duplicate task transition ignored. ' + 'taskId=${task.id} transition=${transitionCode.name} ' + 'operationId=$operationId duplicateActivityId=${duplicate.id}'); return TaskTransitionResult( transitionCode: transitionCode, outcomeCode: TaskTransitionOutcomeCode.duplicateOperation, @@ -52,6 +59,10 @@ class TaskTransitionService { } if (!_actualIntervalShapeIsValid(actualStart, actualEnd)) { + logger.warn(() => 'Task transition rejected: invalid actual interval. ' + 'taskId=${task.id} transition=${transitionCode.name} ' + 'actualStart=${actualStart?.toIso8601String()} ' + 'actualEnd=${actualEnd?.toIso8601String()}'); return TaskTransitionResult( transitionCode: transitionCode, outcomeCode: TaskTransitionOutcomeCode.invalidState, @@ -60,6 +71,9 @@ class TaskTransitionService { } if (_isNoOpTerminalRepeat(task, transitionCode)) { + logger.fine(() => 'Possible issue: terminal task transition repeated. ' + 'taskId=${task.id} transition=${transitionCode.name} ' + 'taskStatus=${task.status.name}'); return TaskTransitionResult( transitionCode: transitionCode, outcomeCode: TaskTransitionOutcomeCode.noOp, @@ -68,6 +82,10 @@ class TaskTransitionService { } if (_isBlockedByTerminalState(task, transitionCode)) { + logger.warn( + () => 'Task transition rejected: terminal state blocks transition. ' + 'taskId=${task.id} transition=${transitionCode.name} ' + 'taskStatus=${task.status.name}'); return TaskTransitionResult( transitionCode: transitionCode, outcomeCode: TaskTransitionOutcomeCode.invalidState, @@ -75,7 +93,7 @@ class TaskTransitionService { ); } - return switch (transitionCode) { + final result = switch (transitionCode) { TaskTransitionCode.complete => _complete( task: task, operationId: operationId, @@ -156,6 +174,16 @@ class TaskTransitionService { metadata: metadata, ), }; + logger.debug(() => 'Task transition finished. taskId=${task.id} ' + 'transition=${transitionCode.name} outcome=${result.outcomeCode.name} ' + 'nextStatus=${result.task.status.name} activityCount=${result.activities.length}'); + if (result.outcomeCode == TaskTransitionOutcomeCode.invalidState) { + logger.warn(() => 'Task transition returned invalid state. ' + 'taskId=${task.id} transition=${transitionCode.name} ' + 'taskType=${task.type.name} previousStatus=${task.status.name} ' + 'nextStatus=${result.task.status.name}'); + } + return result; } /// Runs the `_complete` helper used inside this library. @@ -751,6 +779,8 @@ TaskTransitionResult _invalid(Task task, TaskTransitionCode transitionCode) { /// Top-level helper that performs the `_noOp` operation for this file. /// Keeping the helper private makes the surrounding flow easier to read while preventing unrelated libraries from depending on implementation detail. TaskTransitionResult _noOp(Task task, TaskTransitionCode transitionCode) { + logger.fine(() => 'Possible issue: task transition no-op. taskId=${task.id} ' + 'transition=${transitionCode.name} taskStatus=${task.status.name}'); return TaskTransitionResult( transitionCode: transitionCode, outcomeCode: TaskTransitionOutcomeCode.noOp, diff --git a/packages/scheduler_core/lib/src/scheduling/today_state.dart b/packages/scheduler_core/lib/src/scheduling/today_state.dart index 8b42495..e87e733 100644 --- a/packages/scheduler_core/lib/src/scheduling/today_state.dart +++ b/packages/scheduler_core/lib/src/scheduling/today_state.dart @@ -17,6 +17,7 @@ import '../persistence/repositories.dart'; import 'scheduling_engine.dart'; import 'timeline_state.dart'; import '../domain/time_contracts.dart'; +import '../logging/focus_flow_logger.dart'; part 'today_state/models/today_timeline_item_source.dart'; part 'today_state/requests/get_today_state_request.dart'; part 'today_state/models/today_timeline_item.dart'; diff --git a/packages/scheduler_core/lib/src/scheduling/today_state/queries/get_today_state_query.dart b/packages/scheduler_core/lib/src/scheduling/today_state/queries/get_today_state_query.dart index 256b296..7788883 100644 --- a/packages/scheduler_core/lib/src/scheduling/today_state/queries/get_today_state_query.dart +++ b/packages/scheduler_core/lib/src/scheduling/today_state/queries/get_today_state_query.dart @@ -30,6 +30,10 @@ class GetTodayStateQuery { action: (repositories) async { final context = request.context; final ownerId = context.ownerTimeZone.ownerId; + logger.debug(() => 'Today state query started. ' + 'ownerId=$ownerId date=${request.date.toIsoString()} ' + 'revealHiddenLockedBlocks=${request.revealHiddenLockedBlocks} ' + 'includeNextFlexibleItem=${request.includeNextFlexibleItem}'); final storedSettings = await repositories.ownerSettings.findByOwnerId(ownerId); final settings = storedSettings ?? @@ -37,6 +41,11 @@ class GetTodayStateQuery { ownerId: ownerId, timeZoneId: context.ownerTimeZone.timeZoneId, ); + if (storedSettings == null) { + logger.finer(() => + 'Today state query owner settings missing; using defaults. ' + 'ownerId=$ownerId timeZoneId=${context.ownerTimeZone.timeZoneId}'); + } final timeZoneId = settings.timeZoneId; final dayStart = _resolve( date: request.date, @@ -76,6 +85,12 @@ class GetTodayStateQuery { (await repositories.noticeAcknowledgements.findByOwnerId(ownerId)) .map((record) => record.noticeId) .toSet(); + logger.debug(() => 'Today state query loaded persisted inputs. ' + 'ownerId=$ownerId date=${request.date.toIsoString()} ' + 'projectCount=${projects.length} taskCount=${tasks.length} ' + 'lockedBlockCount=${blocks.length} overrideCount=${overrides.length} ' + 'snapshotCount=${snapshots.length} ' + 'acknowledgedNoticeCount=${acknowledgedNoticeIds.length}'); final lockedExpansion = expandLockedBlocksForDay( blocks: blocks, @@ -138,6 +153,13 @@ class GetTodayStateQuery { snapshots, acknowledgedNoticeIds: acknowledgedNoticeIds, ); + logger.debug(() => 'Today state query finished. ' + 'ownerId=$ownerId date=${request.date.toIsoString()} ' + 'timelineItemCount=${selectedItems.length} ' + 'pendingNoticeCount=${pendingNotices.length} ' + 'hasCurrent=${selectedCurrent != null} ' + 'hasNextRequired=${selectedNextRequired != null} ' + 'hasNextFlexible=${selectedNextFlexible != null}'); return ApplicationResult.success( TodayState( diff --git a/packages/scheduler_export/lib/src/export_controller/controller/export_controller.dart b/packages/scheduler_export/lib/src/export_controller/controller/export_controller.dart index de85645..63ef66f 100644 --- a/packages/scheduler_export/lib/src/export_controller/controller/export_controller.dart +++ b/packages/scheduler_export/lib/src/export_controller/controller/export_controller.dart @@ -27,6 +27,8 @@ final class ExportController { required StringSink sink, int pageSize = 100, }) { + core.logger.info(() => 'Task export to sink requested. ' + 'ownerId=${context.ownerId.value} format=$format pageSize=$pageSize'); final writer = _writerRegistry.create(format, sink); return exportTasks( context: context, @@ -41,11 +43,18 @@ final class ExportController { required ExportWriter writer, int pageSize = 100, }) async { + core.logger.info(() => 'Task export started. ' + 'ownerId=${context.ownerId.value} timezone=${context.timezone} ' + 'version=${context.version} pageSize=$pageSize'); if (pageSize <= 0) { + core.logger.warn(() => 'Task export rejected invalid page size. ' + 'ownerId=${context.ownerId.value} pageSize=$pageSize'); throw ArgumentError.value(pageSize, 'pageSize', 'Must be positive.'); } await writer.begin(context); + var pageCount = 0; + var taskCount = 0; String? cursor; do { final result = await _taskRepository.findByOwner( @@ -53,14 +62,24 @@ final class ExportController { page: core.PageRequest(cursor: cursor, limit: pageSize), ); if (result.isLeft) { + core.logger.warn(() => 'Task export repository read failed. ' + 'ownerId=${context.ownerId.value} pageCount=$pageCount ' + 'taskCount=$taskCount failureType=${result.left.runtimeType}'); throw ExportRepositoryException(result.left); } final page = result.right; + pageCount += 1; + core.logger.finer(() => 'Task export page loaded. ' + 'ownerId=${context.ownerId.value} pageNumber=$pageCount ' + 'itemCount=${page.items.length} hasNext=${page.nextCursor != null}'); for (final task in page.items) { await writer.writeTask(task); + taskCount += 1; } cursor = page.nextCursor; } while (cursor != null); await writer.end(); + core.logger.info(() => 'Task export completed. ' + 'ownerId=${context.ownerId.value} pageCount=$pageCount taskCount=$taskCount'); } } diff --git a/packages/scheduler_export/lib/src/export_controller/writers/registry/export_writer_registry.dart b/packages/scheduler_export/lib/src/export_controller/writers/registry/export_writer_registry.dart index b70406b..fc23a9d 100644 --- a/packages/scheduler_export/lib/src/export_controller/writers/registry/export_writer_registry.dart +++ b/packages/scheduler_export/lib/src/export_controller/writers/registry/export_writer_registry.dart @@ -34,7 +34,9 @@ final class ExportWriterRegistry { /// Register [factory] for [format]. void register(String format, ExportWriterFactory factory) { - _factories[_normalizeFormat(format)] = factory; + final normalized = _normalizeFormat(format); + core.logger.finer(() => 'Export writer registered. format=$normalized'); + _factories[normalized] = factory; } /// Create a writer for [format] using [sink]. @@ -42,8 +44,11 @@ final class ExportWriterRegistry { final normalized = _normalizeFormat(format); final factory = _factories[normalized]; if (factory == null) { + core.logger.warn(() => 'Export writer lookup failed: unknown format. ' + 'format=$normalized availableFormatCount=${_factories.length}'); throw ExportException('Unknown export format: $format'); } + core.logger.finer(() => 'Export writer created. format=$normalized'); return factory(sink); } } diff --git a/packages/scheduler_export_json/lib/src/json_csv_writers.dart b/packages/scheduler_export_json/lib/src/json_csv_writers.dart index 7fa4548..fab4499 100644 --- a/packages/scheduler_export_json/lib/src/json_csv_writers.dart +++ b/packages/scheduler_export_json/lib/src/json_csv_writers.dart @@ -15,6 +15,8 @@ part 'json_csv_writers/csv_export_writer.dart'; /// Create the readable export writer registry used by export commands. ExportWriterRegistry readableExportWriterRegistry() { + core.logger + .finer(() => 'Readable export writer registry created. formatCount=2'); return ExportWriterRegistry( factories: { 'json': JsonExportWriter.new, diff --git a/packages/scheduler_notifications/lib/src/notification_adapter.dart b/packages/scheduler_notifications/lib/src/notification_adapter.dart index 8105622..44d5dcf 100644 --- a/packages/scheduler_notifications/lib/src/notification_adapter.dart +++ b/packages/scheduler_notifications/lib/src/notification_adapter.dart @@ -5,6 +5,7 @@ library; import 'dart:async'; +import 'package:scheduler_core/scheduler_core.dart' show logger; part 'notification_adapter/requests/notification_request.dart'; part 'notification_adapter/requests/notification_request_impl.dart'; part 'notification_adapter/feedback/notification_feedback_type.dart'; diff --git a/packages/scheduler_notifications/lib/src/notification_adapter/adapter/fake_notification_adapter.dart b/packages/scheduler_notifications/lib/src/notification_adapter/adapter/fake_notification_adapter.dart index 6eca676..0991879 100644 --- a/packages/scheduler_notifications/lib/src/notification_adapter/adapter/fake_notification_adapter.dart +++ b/packages/scheduler_notifications/lib/src/notification_adapter/adapter/fake_notification_adapter.dart @@ -35,6 +35,9 @@ final class FakeNotificationAdapter implements NotificationAdapter { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future schedule(NotificationRequest request) async { + logger.debug(() => 'Fake notification scheduled. ' + 'notificationId=${request.id} ' + 'scheduledDateTimeUtc=${request.scheduledDateTimeUtc.toIso8601String()}'); _scheduled[request.id] = request; } @@ -43,17 +46,24 @@ final class FakeNotificationAdapter implements NotificationAdapter { @override Future cancel(String id) async { final trimmed = _requiredTrimmed(id, 'id'); - _scheduled.remove(trimmed); + final removed = _scheduled.remove(trimmed) != null; _cancelledIds.add(trimmed); + logger.debug(() => 'Fake notification cancelled. ' + 'notificationId=$trimmed removed=$removed'); } /// Emit [event] to feedback listeners. void emitFeedback(NotificationFeedback event) { + logger.debug(() => 'Fake notification feedback emitted. ' + 'notificationId=${event.id} type=${event.type.name} ' + 'hasAction=${event.actionId != null}'); _feedbackController.add(event); } /// Release stream resources held by this fake. Future close() { + logger.debug(() => 'Fake notification adapter closing. ' + 'scheduledCount=${_scheduled.length} cancelledCount=${_cancelledIds.length}'); return _feedbackController.close(); } } diff --git a/packages/scheduler_notifications/pubspec.yaml b/packages/scheduler_notifications/pubspec.yaml index 7cbf28c..fdd1825 100644 --- a/packages/scheduler_notifications/pubspec.yaml +++ b/packages/scheduler_notifications/pubspec.yaml @@ -10,6 +10,9 @@ resolution: workspace environment: sdk: '>=3.6.0 <4.0.0' +dependencies: + scheduler_core: any + dev_dependencies: lints: ^5.0.0 test: ^1.25.0 diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io.dart index 7720b84..ff57dab 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io.dart @@ -9,6 +9,7 @@ import 'dart:convert'; import 'dart:io'; import 'package:scheduler_notifications/notifications.dart'; +import 'package:scheduler_core/scheduler_core.dart' show logger; part 'desktop_notification_adapter_io/platform/desktop_notification_platform.dart'; part 'desktop_notification_adapter_io/callbacks/desktop_notification_log_sink.dart'; part 'desktop_notification_adapter_io/callbacks/desktop_process_runner.dart'; diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/adapter/desktop_notification_adapter.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/adapter/desktop_notification_adapter.dart index 50b2c4f..099c191 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/adapter/desktop_notification_adapter.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/adapter/desktop_notification_adapter.dart @@ -19,6 +19,9 @@ final class DesktopNotificationAdapter implements NotificationAdapter { DesktopProcessRunner? processRunner, DesktopNotificationLogSink? logSink, }) { + logger.info(() => 'Creating desktop notification adapter. ' + 'requestedPlatform=${platform?.name} hasCustomRunner=${processRunner != null} ' + 'hasCustomLogSink=${logSink != null}'); return DesktopNotificationAdapter( backend: createDefaultDesktopNotificationBackend( platform: platform, @@ -37,6 +40,10 @@ final class DesktopNotificationAdapter implements NotificationAdapter { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future schedule(NotificationRequest request) { + logger.debug(() => 'Desktop notification schedule requested. ' + 'notificationId=${request.id} ' + 'scheduledDateTimeUtc=${request.scheduledDateTimeUtc.toIso8601String()} ' + 'backendSupported=${_backend.isSupported}'); return _backend.deliver(request); } @@ -44,6 +51,9 @@ final class DesktopNotificationAdapter implements NotificationAdapter { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future cancel(String id) { - return _backend.cancel(id.trim()); + final trimmed = id.trim(); + logger.debug(() => 'Desktop notification cancel requested. ' + 'notificationId=$trimmed backendSupported=${_backend.isSupported}'); + return _backend.cancel(trimmed); } } diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/core/desktop_notification_backend_factory.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/core/desktop_notification_backend_factory.dart index a07ff17..4db784c 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/core/desktop_notification_backend_factory.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/core/desktop_notification_backend_factory.dart @@ -15,6 +15,9 @@ DesktopNotificationBackend createDefaultDesktopNotificationBackend({ logSink: logSink ?? stdout.writeln, platform: resolvedPlatform, ); + logger.info(() => 'Resolved desktop notification backend. ' + 'platform=${resolvedPlatform.name} hasCustomRunner=${processRunner != null} ' + 'hasCustomLogSink=${logSink != null}'); return switch (resolvedPlatform) { DesktopNotificationPlatform.linux => LinuxNotifySendBackend( diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/fallback/stdout_notification_backend.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/fallback/stdout_notification_backend.dart index b8e3d14..8c2aac6 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/fallback/stdout_notification_backend.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/fallback/stdout_notification_backend.dart @@ -27,6 +27,8 @@ final class StdoutNotificationBackend implements DesktopNotificationBackend { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future deliver(NotificationRequest request) async { + logger.warn(() => 'Desktop notification fallback delivery used. ' + 'platform=${platform.name} notificationId=${request.id}'); _logSink( 'notification[$platform] ${request.id}: ${request.title} - ' '${request.body}', @@ -37,6 +39,9 @@ final class StdoutNotificationBackend implements DesktopNotificationBackend { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future cancel(String id) async { - _logSink('notification[$platform] cancel: ${id.trim()}'); + final trimmed = id.trim(); + logger.finer(() => 'Desktop notification fallback cancel used. ' + 'platform=${platform.name} notificationId=$trimmed'); + _logSink('notification[$platform] cancel: $trimmed'); } } diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/platform/linux_notify_send_backend.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/platform/linux_notify_send_backend.dart index e336a69..99ce38f 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/platform/linux_notify_send_backend.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/platform/linux_notify_send_backend.dart @@ -29,6 +29,8 @@ final class LinuxNotifySendBackend implements DesktopNotificationBackend { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future deliver(NotificationRequest request) async { + logger.debug(() => 'Linux notification delivery requested. ' + 'notificationId=${request.id} backend=notify-send'); await _runOrFallback( request, () => _processRunner('notify-send', [ @@ -43,6 +45,8 @@ final class LinuxNotifySendBackend implements DesktopNotificationBackend { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future cancel(String id) async { + logger.finer(() => 'Linux notification cancel delegated to fallback. ' + 'notificationId=${id.trim()}'); await _fallback.cancel(id); } @@ -55,9 +59,20 @@ final class LinuxNotifySendBackend implements DesktopNotificationBackend { try { final result = await run(); if (result.exitCode != 0) { + logger.warn(() => 'Linux notification command failed; using fallback. ' + 'notificationId=${request.id} exitCode=${result.exitCode}'); await _fallback.deliver(request); + } else { + logger.debug(() => 'Linux notification command completed. ' + 'notificationId=${request.id} exitCode=${result.exitCode}'); } - } on ProcessException { + } on ProcessException catch (error, stackTrace) { + logger.warn( + () => 'Linux notification command unavailable; using fallback. ' + 'notificationId=${request.id}', + error: error, + stackTrace: stackTrace, + ); await _fallback.deliver(request); } } diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/platform/mac_os_notification_backend.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/platform/mac_os_notification_backend.dart index 70bbcf3..655c9ac 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/platform/mac_os_notification_backend.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_io/backends/platform/mac_os_notification_backend.dart @@ -29,14 +29,27 @@ final class MacOsNotificationBackend implements DesktopNotificationBackend { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future deliver(NotificationRequest request) async { + logger.debug(() => 'macOS notification delivery requested. ' + 'notificationId=${request.id} backend=osascript'); final script = 'display notification ${_appleScriptString(request.body)} ' 'with title ${_appleScriptString(request.title)}'; try { final result = await _processRunner('osascript', ['-e', script]); if (result.exitCode != 0) { + logger.warn(() => 'macOS notification command failed; using fallback. ' + 'notificationId=${request.id} exitCode=${result.exitCode}'); await _fallback.deliver(request); + } else { + logger.debug(() => 'macOS notification command completed. ' + 'notificationId=${request.id} exitCode=${result.exitCode}'); } - } on ProcessException { + } on ProcessException catch (error, stackTrace) { + logger.warn( + () => 'macOS notification command unavailable; using fallback. ' + 'notificationId=${request.id}', + error: error, + stackTrace: stackTrace, + ); await _fallback.deliver(request); } } @@ -45,6 +58,8 @@ final class MacOsNotificationBackend implements DesktopNotificationBackend { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future cancel(String id) async { + logger.finer(() => 'macOS notification cancel delegated to fallback. ' + 'notificationId=${id.trim()}'); await _fallback.cancel(id); } } diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub.dart index eabbd58..14414a5 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub.dart @@ -7,6 +7,7 @@ library; import 'dart:async'; import 'package:scheduler_notifications/notifications.dart'; +import 'package:scheduler_core/scheduler_core.dart' show logger; part 'desktop_notification_adapter_stub/platform/desktop_notification_platform.dart'; part 'desktop_notification_adapter_stub/callbacks/desktop_notification_log_sink.dart'; part 'desktop_notification_adapter_stub/backends/desktop_notification_backend.dart'; diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/adapter/desktop_notification_adapter.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/adapter/desktop_notification_adapter.dart index 3b876dd..acc20d0 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/adapter/desktop_notification_adapter.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/adapter/desktop_notification_adapter.dart @@ -19,6 +19,9 @@ final class DesktopNotificationAdapter implements NotificationAdapter { Object? processRunner, DesktopNotificationLogSink? logSink, }) { + logger.info(() => 'Creating stub desktop notification adapter. ' + 'requestedPlatform=${platform?.name} hasCustomRunner=${processRunner != null} ' + 'hasCustomLogSink=${logSink != null}'); return DesktopNotificationAdapter( backend: createDefaultDesktopNotificationBackend( platform: platform, @@ -37,6 +40,10 @@ final class DesktopNotificationAdapter implements NotificationAdapter { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future schedule(NotificationRequest request) { + logger.debug(() => 'Stub desktop notification schedule requested. ' + 'notificationId=${request.id} ' + 'scheduledDateTimeUtc=${request.scheduledDateTimeUtc.toIso8601String()} ' + 'backendSupported=${_backend.isSupported}'); return _backend.deliver(request); } @@ -44,6 +51,9 @@ final class DesktopNotificationAdapter implements NotificationAdapter { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future cancel(String id) { - return _backend.cancel(id.trim()); + final trimmed = id.trim(); + logger.debug(() => 'Stub desktop notification cancel requested. ' + 'notificationId=$trimmed backendSupported=${_backend.isSupported}'); + return _backend.cancel(trimmed); } } diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/backends/desktop_notification_backend_factory.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/backends/desktop_notification_backend_factory.dart index 39626a7..f098ee0 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/backends/desktop_notification_backend_factory.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/backends/desktop_notification_backend_factory.dart @@ -9,8 +9,12 @@ DesktopNotificationBackend createDefaultDesktopNotificationBackend({ Object? processRunner, DesktopNotificationLogSink? logSink, }) { + final resolvedPlatform = platform ?? DesktopNotificationPlatform.unsupported; + logger.info(() => 'Resolved stub desktop notification backend. ' + 'platform=${resolvedPlatform.name} hasCustomRunner=${processRunner != null} ' + 'hasCustomLogSink=${logSink != null}'); return StdoutNotificationBackend( logSink: logSink ?? _defaultLogSink, - platform: platform ?? DesktopNotificationPlatform.unsupported, + platform: resolvedPlatform, ); } diff --git a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/backends/stdout_notification_backend.dart b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/backends/stdout_notification_backend.dart index 797cc2d..f99dd0f 100644 --- a/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/backends/stdout_notification_backend.dart +++ b/packages/scheduler_notifications_desktop/lib/src/desktop_notification_adapter_stub/backends/stdout_notification_backend.dart @@ -27,6 +27,8 @@ final class StdoutNotificationBackend implements DesktopNotificationBackend { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future deliver(NotificationRequest request) async { + logger.warn(() => 'Stub desktop notification fallback delivery used. ' + 'platform=${platform.name} notificationId=${request.id}'); _logSink( 'notification[$platform] ${request.id}: ${request.title} - ' '${request.body}', @@ -37,6 +39,9 @@ final class StdoutNotificationBackend implements DesktopNotificationBackend { /// Callers should await the returned future so repository writes, UI refreshes, and failure handling happen in a predictable order. @override Future cancel(String id) async { - _logSink('notification[$platform] cancel: ${id.trim()}'); + final trimmed = id.trim(); + logger.finer(() => 'Stub desktop notification fallback cancel used. ' + 'platform=${platform.name} notificationId=$trimmed'); + _logSink('notification[$platform] cancel: $trimmed'); } } diff --git a/packages/scheduler_notifications_desktop/pubspec.yaml b/packages/scheduler_notifications_desktop/pubspec.yaml index aebf6bc..2fa470e 100644 --- a/packages/scheduler_notifications_desktop/pubspec.yaml +++ b/packages/scheduler_notifications_desktop/pubspec.yaml @@ -11,6 +11,7 @@ environment: sdk: '>=3.6.0 <4.0.0' dependencies: + scheduler_core: any scheduler_notifications: any dev_dependencies: diff --git a/packages/scheduler_persistence_memory/lib/persistence_memory/repositories/in_memory_schedule_snapshot_repository.dart b/packages/scheduler_persistence_memory/lib/persistence_memory/repositories/in_memory_schedule_snapshot_repository.dart index ca2c902..8d2c5c9 100644 --- a/packages/scheduler_persistence_memory/lib/persistence_memory/repositories/in_memory_schedule_snapshot_repository.dart +++ b/packages/scheduler_persistence_memory/lib/persistence_memory/repositories/in_memory_schedule_snapshot_repository.dart @@ -94,6 +94,9 @@ Either> _checkWrite({ required core.Revision expectedRevision, }) { if (expectedRevision.value <= 0) { + core.logger.warn(() => + 'In-memory repository write rejected invalid revision. ' + 'entityId=$id ownerId=${ownerId.value} expectedRevision=${expectedRevision.value}'); return Left( RepositoryInvalidRevision( entityId: id, @@ -103,12 +106,21 @@ Either> _checkWrite({ } final record = records[id]; if (record == null) { + core.logger.warn(() => 'In-memory repository write target missing. ' + 'entityId=$id ownerId=${ownerId.value} expectedRevision=${expectedRevision.value}'); return Left(RepositoryNotFound(entityId: id)); } if (record.ownerId != ownerId) { + core.logger.warn(() => + 'In-memory repository write rejected owner mismatch. ' + 'entityId=$id ownerId=${ownerId.value} recordOwnerId=${record.ownerId.value}'); return Left(RepositoryOwnerMismatch(entityId: id)); } if (record.revision != expectedRevision) { + core.logger.warn(() => + 'In-memory repository write rejected stale revision. ' + 'entityId=$id ownerId=${ownerId.value} expectedRevision=${expectedRevision.value} ' + 'actualRevision=${record.revision.value}'); return Left( RepositoryStaleRevision( entityId: id, diff --git a/packages/scheduler_persistence_sqlite/lib/src/sqlite_application/sqlite_application_runtime.dart b/packages/scheduler_persistence_sqlite/lib/src/sqlite_application/sqlite_application_runtime.dart index b4a3707..2987882 100644 --- a/packages/scheduler_persistence_sqlite/lib/src/sqlite_application/sqlite_application_runtime.dart +++ b/packages/scheduler_persistence_sqlite/lib/src/sqlite_application/sqlite_application_runtime.dart @@ -28,12 +28,17 @@ final class SqliteApplicationRuntime { required String path, String defaultOwnerId = defaultV1OwnerId, }) async { + core.logger.info(() => 'Opening SQLite application runtime. ' + 'path=$path defaultOwnerId=$defaultOwnerId'); final file = File(path); await file.parent.create(recursive: true); - return SqliteApplicationRuntime( + final runtime = SqliteApplicationRuntime( db: SchedulerDb(NativeDatabase(file)), defaultOwnerId: defaultOwnerId, ); + core.logger.info(() => 'SQLite application runtime opened. ' + 'path=$path defaultOwnerId=$defaultOwnerId'); + return runtime; } /// Shared SQLite database handle. @@ -48,6 +53,8 @@ final class SqliteApplicationRuntime { String timeZoneId = defaultV1TimeZoneId, String defaultProjectId = defaultV1ProjectId, }) { + core.logger.info(() => 'SQLite application bootstrap started. ' + 'ownerId=$ownerId timeZoneId=$timeZoneId defaultProjectId=$defaultProjectId'); return _guardApplicationErrors(() { return db.transaction(() async { final repositories = _SqliteApplicationRepositories( @@ -58,6 +65,8 @@ final class SqliteApplicationRuntime { ownerId, ); if (settings == null) { + core.logger.finer(() => 'SQLite bootstrap creating owner settings. ' + 'ownerId=$ownerId timeZoneId=$timeZoneId'); await repositories.ownerSettings.save( core.OwnerSettings( ownerId: ownerId, @@ -69,6 +78,8 @@ final class SqliteApplicationRuntime { final project = await repositories.projects.findById(defaultProjectId); if (project == null) { + core.logger.finer(() => 'SQLite bootstrap creating default project. ' + 'ownerId=$ownerId projectId=$defaultProjectId'); await repositories.projects.save( core.ProjectProfile( id: defaultProjectId, @@ -78,13 +89,18 @@ final class SqliteApplicationRuntime { ); } + core.logger.info(() => 'SQLite application bootstrap completed. ' + 'ownerId=$ownerId createdSettings=${settings == null} ' + 'createdProject=${project == null}'); return core.ApplicationResult.success(null); }); }); } /// Closes the underlying SQLite database. - Future close() { - return db.close(); + Future close() async { + core.logger.info(() => 'Closing SQLite application runtime.'); + await db.close(); + core.logger.info(() => 'SQLite application runtime closed.'); } } diff --git a/packages/scheduler_persistence_sqlite/lib/src/sqlite_application/sqlite_application_unit_of_work.dart b/packages/scheduler_persistence_sqlite/lib/src/sqlite_application/sqlite_application_unit_of_work.dart index 36bcb2e..cea9c5f 100644 --- a/packages/scheduler_persistence_sqlite/lib/src/sqlite_application/sqlite_application_unit_of_work.dart +++ b/packages/scheduler_persistence_sqlite/lib/src/sqlite_application/sqlite_application_unit_of_work.dart @@ -26,6 +26,9 @@ final class SqliteApplicationUnitOfWork implements core.ApplicationUnitOfWork { core.ApplicationUnitOfWorkRepositories repositories, ) action, }) { + core.logger.debug(() => 'SQLite unit of work run started. ' + 'operationId=${context.operationId} operationName=$operationName ' + 'ownerId=${context.ownerTimeZone.ownerId}'); return _guardApplicationErrors(() { return db.transaction(() async { final repositories = _SqliteApplicationRepositories( @@ -36,6 +39,9 @@ final class SqliteApplicationUnitOfWork implements core.ApplicationUnitOfWork { context.operationId, ); if (existing != null) { + core.logger.warn(() => + 'Duplicate operation ignored by SQLite unit of work. ' + 'operationId=${context.operationId} operationName=$operationName'); return core.ApplicationResult.failure( core.ApplicationFailure( code: core.ApplicationFailureCode.duplicateOperation, @@ -46,6 +52,10 @@ final class SqliteApplicationUnitOfWork implements core.ApplicationUnitOfWork { final result = await action(repositories); if (result.isFailure) { + core.logger.warn(() => 'SQLite unit of work action returned failure. ' + 'operationId=${context.operationId} operationName=$operationName ' + 'code=${result.failure!.code.name} ' + 'detailCode=${result.failure!.detailCode}'); return result; } @@ -58,6 +68,9 @@ final class SqliteApplicationUnitOfWork implements core.ApplicationUnitOfWork { ), ); if (!operationResult.isSuccess) { + core.logger.warn(() => + 'SQLite unit of work operation record insert conflicted. ' + 'operationId=${context.operationId} operationName=$operationName'); return core.ApplicationResult.failure( core.ApplicationFailure( code: core.ApplicationFailureCode.duplicateOperation, @@ -66,6 +79,8 @@ final class SqliteApplicationUnitOfWork implements core.ApplicationUnitOfWork { ); } + core.logger.debug(() => 'SQLite unit of work run committed. ' + 'operationId=${context.operationId} operationName=$operationName'); return result; }); }); @@ -78,13 +93,23 @@ final class SqliteApplicationUnitOfWork implements core.ApplicationUnitOfWork { core.ApplicationUnitOfWorkRepositories repositories, ) action, }) { - return _guardApplicationErrors(() { - return action( + core.logger.debug(() => 'SQLite unit of work read started. ' + 'defaultOwnerId=$defaultOwnerId'); + return _guardApplicationErrors(() async { + final result = await action( _SqliteApplicationRepositories( db, defaultOwnerId: defaultOwnerId, ), ); + if (result.isFailure) { + core.logger.warn(() => 'SQLite unit of work read returned failure. ' + 'code=${result.failure!.code.name} detailCode=${result.failure!.detailCode}'); + } else { + core.logger.debug(() => 'SQLite unit of work read finished. ' + 'defaultOwnerId=$defaultOwnerId'); + } + return result; }); } } @@ -96,8 +121,13 @@ Future> _guardApplicationErrors( try { return await action(); } on core.ApplicationFailureException catch (error) { + core.logger.warn(() => 'SQLite application caught application failure. ' + 'code=${error.failure.code.name} detailCode=${error.failure.detailCode}'); return core.ApplicationResult.failure(error.failure); } on core.DomainValidationException catch (error) { + core.logger + .warn(() => 'SQLite application caught domain validation failure. ' + 'code=${error.code.name}'); return core.ApplicationResult.failure( core.ApplicationFailure( code: core.ApplicationFailureCode.validation, @@ -105,25 +135,43 @@ Future> _guardApplicationErrors( ), ); } on ArgumentError catch (error) { + core.logger + .warn(() => 'SQLite application caught argument validation failure. ' + 'argumentName=${error.name}'); return core.ApplicationResult.failure( core.ApplicationFailure( code: core.ApplicationFailureCode.validation, detailCode: error.name, ), ); - } on core.ApplicationPersistenceException { + } on core.ApplicationPersistenceException catch (error, stackTrace) { + core.logger.error( + () => 'SQLite application persistence failure.', + error: error, + stackTrace: stackTrace, + ); return core.ApplicationResult.failure( const core.ApplicationFailure( code: core.ApplicationFailureCode.persistenceFailure, ), ); - } on sqlite.SqliteException catch (_) { + } on sqlite.SqliteException catch (error, stackTrace) { + core.logger.error( + () => 'SQLite database operation failed. errorType=${error.runtimeType}', + error: error, + stackTrace: stackTrace, + ); return core.ApplicationResult.failure( const core.ApplicationFailure( code: core.ApplicationFailureCode.persistenceFailure, ), ); - } catch (_) { + } catch (error, stackTrace) { + core.logger.error( + () => 'SQLite application unexpected failure.', + error: error, + stackTrace: stackTrace, + ); return core.ApplicationResult.failure( const core.ApplicationFailure( code: core.ApplicationFailureCode.unexpected),